Fix loggin middleware

Signed-off-by: Aleksandr Shilov <[email protected]>
Fohlio · Nov 20, 2022 · f5f1871 · f5f1871
1 parent d3f6ff3
commit f5f1871
Show file tree

Hide file tree

Showing 13 changed files with 214 additions and 137 deletions.
diff --git a/CHANGELOG.md b/CHANGELOG.md
@@ -1,5 1,5 @@
 # 2.1.0
-* `ClickHouse.connection.insert` now returns `ClickHouse::Response::Execution` objects
 * `ClickHouse.connection.insert` now returns `ClickHouse::Response::Summary` object
  with methods `headers`, `summary`, `written_rows`, `written_bytes`, etc... 
 * `ClickHouse.connection.insert(columns: ["id"], values: [1])` now uses `JSONCompactEachRow` by default
  (to increase JSON serialization speed)

diff --git a/lib/click_house/connection.rb b/lib/click_house/connection.rb
@@ -65,8 65,9 @@ def transport
 
  conn.response Middleware::RaiseError
  conn.response Middleware::Logging, logger: config.logger!
- conn.response config.json_parser, content_type: %r{application/json}, parser_options: { config: config }
- conn.response Middleware::ParseCsv, content_type: %r{text/csv}, parser_options: { config: config }
  conn.response Middleware::SummaryMiddleware, options: { config: config } # should be after logger
  conn.response config.json_parser, content_type: %r{application/json}, options: { config: config }
  conn.response Middleware::ParseCsv, content_type: %r{text/csv}, options: { config: config }
  conn.adapter config.adapter
  end
  end

diff --git a/lib/click_house/extend/connection_inserting.rb b/lib/click_house/extend/connection_inserting.rb
@@ -46,7 46,7 @@ def insert(table, body = [], **opts)
  return insert_compact(table, columns: columns, values: values, format: format)
  end
 
- Response::Factory.empty_exec
  Response::Factory.empty_exec(config)
  end
  # rubocop:enable Metrics/PerceivedComplexity, Metrics/CyclomaticComplexity
 

diff --git a/lib/click_house/middleware.rb b/lib/click_house/middleware.rb
@@ -3,6 3,7 @@
 module ClickHouse
  module Middleware
  autoload :ResponseBase, 'click_house/middleware/response_base'
  autoload :SummaryMiddleware, 'click_house/middleware/summary_middleware'
  autoload :Logging, 'click_house/middleware/logging'
  autoload :ParseCsv, 'click_house/middleware/parse_csv'
  autoload :ParseJsonOj, 'click_house/middleware/parse_json_oj'

diff --git a/lib/click_house/middleware/logging.rb b/lib/click_house/middleware/logging.rb
@@ -5,36 5,32 @@ module Middleware
  class Logging < Faraday::Middleware
  Faraday::Response.register_middleware self => self
 
- SUMMARY_HEADER = 'x-clickhouse-summary'
  EMPTY = ''
  GET = :get
 
- attr_reader :logger, :starting, :body
  attr_reader :logger, :starting
 
  def initialize(app = nil, logger:)
  @logger = logger
  super(app)
  end
 
- def call(environment)
  def call(env)
  @starting = timestamp
- @body = environment.body if log_body?
- @app.call(environment).on_complete(&method(:on_complete))
- end
-
- private
-
- def log_body?
- logger.level == Logger::DEBUG
  super
  end
 
  # rubocop:disable Layout/LineLength
  def on_complete(env)
- summary = extract_summary(env.response_headers)
- logger.info("\e[1m[35mSQL (#{duration_stats_log(env.body)})\e[0m #{query(env)};")
- logger.debug(body) if body
- logger.info("\e[1m[36mRead: #{summary.fetch(:read_rows)} rows, #{summary.fetch(:read_bytes)}. Written: #{summary.fetch(:written_rows)} rows, #{summary.fetch(:written_bytes)}\e[0m")
  summary = SummaryMiddleware.extract(env)
  logger.info("\e[1m[35mSQL (#{duration_stats_log(summary)})\e[0m #{query(env)};")
  logger.debug(env.request_body) if log_body?(env)
  logger.info("\e[1m[36mRead: #{summary.read_rows} rows, #{summary.read_bytes_pretty}. Written: #{summary.written_rows} rows, #{summary.written_bytes_pretty}\e[0m")
  end
  # rubocop:enable Layout/LineLength
 
  private
 
  def duration
  timestamp - starting
  end
@@ -43,37 39,25 @@ def timestamp
  Process.clock_gettime(Process::CLOCK_MONOTONIC)
  end
 
- def query_in_body?(env)
- env.method == :get
  # @return [Boolean]
  def log_body?(env)
  return unless logger.debug?
  return if env.method == GET # GET queries logs body as a statement
  return if env.request_body.nil? || env.request_body == EMPTY
 
  true
  end
 
  def query(env)
- if query_in_body?(env)
- body
  if env.method == GET
  env.request_body
  else
- CGI.parse(env.url.query.to_s).dig('query', 0) || '[NO QUERY]'
  String(CGI.parse(env.url.query.to_s).dig('query', 0) || '[NO QUERY]').chomp
  end
  end
 
- def duration_stats_log(body)
- elapsed = duration
- clickhouse_elapsed = body['statistics'].fetch('elapsed') if body.is_a?(Hash) && body.key?('statistics')
-
- [
- "Total: #{Util::Pretty.measure(elapsed * 1000)}",
- ("CH: #{Util::Pretty.measure(clickhouse_elapsed * 1000)}" if clickhouse_elapsed)
- ].compact.join(', ')
- end
-
- def extract_summary(headers)
- JSON.parse(headers.fetch('x-clickhouse-summary', '{}')).tap do |summary|
- summary[:read_rows] = summary['read_rows']
- summary[:read_bytes] = Util::Pretty.size(summary['read_bytes'].to_i)
- summary[:written_rows] = summary['written_rows']
- summary[:written_bytes] = Util::Pretty.size(summary['written_bytes'].to_i)
- end
- rescue JSON::ParserError
- {}
  def duration_stats_log(summary)
  "Total: #{Util::Pretty.measure(duration * 1000)}, CH: #{summary.elapsed_pretty}"
  end
  end
  end

diff --git a/lib/click_house/middleware/response_base.rb b/lib/click_house/middleware/response_base.rb
@@ -5,12 5,12 @@ module Middleware
  class ResponseBase < Faraday::Middleware
  CONTENT_TYPE_HEADER = 'content-type'
 
- attr_reader :parser_options
  attr_reader :options
  attr_reader :content_type
 
- def initialize(app = nil, parser_options: {}, content_type: nil, preserve_raw: false)
  def initialize(app = nil, options: {}, content_type: nil, preserve_raw: false)
  super(app)
- @parser_options = parser_options
  @options = options
  @content_type = content_type
  @preserve_raw = preserve_raw
  on_setup
@@ -32,7 32,7 @@ def content_type?(env, regexp)
 
  # @return [Config]
  def config
- parser_options.fetch(:config)
  options.fetch(:config)
  end
 
  private

diff --git a/lib/click_house/middleware/summary_middleware.rb b/lib/click_house/middleware/summary_middleware.rb
@@ -0,0 1,26 @@
 # frozen_string_literal: true
 
 module ClickHouse
  module Middleware
  class SummaryMiddleware < ResponseBase
  Faraday::Response.register_middleware self => self
 
  KEY = :summary
 
  # @param env [Faraday::Env]
  # @return [Response::Summary]
  def self.extract(env)
  env.custom_members.fetch(KEY)
  end
 
  # @param env [Faraday::Env]
  def on_complete(env)
  env.custom_members[KEY] = Response::Summary.new(
  config,
  headers: env.response_headers,
  body: env.body.is_a?(Hash) ? env.body : {}
  )
  end
  end
  end
 end
diff --git a/lib/click_house/response.rb b/lib/click_house/response.rb
@@ -4,6 4,6 @@ module ClickHouse
  module Response
  autoload :Factory, 'click_house/response/factory'
  autoload :ResultSet, 'click_house/response/result_set'
- autoload :Execution, 'click_house/response/execution'
  autoload :Summary, 'click_house/response/summary'
  end
 end
diff --git a/lib/click_house/response/execution.rb b/lib/click_house/response/execution.rb
diff --git a/lib/click_house/response/factory.rb b/lib/click_house/response/factory.rb
@@ -5,9 5,6 @@ module Response
  class Factory
  KEY_META = 'meta'
  KEY_DATA = 'data'
- KEY_TOTALS = 'totals'
- KEY_STATISTICS = 'statistics'
- KEY_ROWS_BEFORE_LIMIT_AT_LEAST = 'rows_before_limit_at_least'
 
  # @return [Nil], ResultSet]
  # @params faraday [Faraday::Response]
@@ -22,21 19,19 @@ def self.response(faraday, config)
  config: config,
  meta: body.fetch(config.key(KEY_META)),
  data: body.fetch(config.key(KEY_DATA)),
- totals: body[config.key(KEY_TOTALS)],
- statistics: body[config.key(KEY_STATISTICS)],
- rows_before_limit_at_least: body[config.key(KEY_ROWS_BEFORE_LIMIT_AT_LEAST)]
  summary: Middleware::SummaryMiddleware.extract(faraday.env)
  )
  end
 
  # @return [Response::Execution]
  # @params faraday [Faraday::Response]
  def self.exec(faraday)
- Execution.new(headers: faraday.headers)
  Middleware::SummaryMiddleware.extract(faraday.env)
  end
 
  # @return [Response::Execution]
- def self.empty_exec
- Execution.new
  def self.empty_exec(config)
  Summary.new(config)
  end
  end
  end

diff --git a/lib/click_house/response/result_set.rb b/lib/click_house/response/result_set.rb
@@ -13,24 13,22 @@ class ResultSet
  :inspect, :each, :fetch, :length, :count, :size,
  :first, :last, :[], :to_h
 
- attr_reader :config, :meta, :data, :totals, :statistics, :rows_before_limit_at_least
  def_delegators :summary,
  :statistics, :headers,
  :totals, :rows_before_limit_at_least
 
  attr_reader :config, :meta, :data, :summary
 
  # @param config [Config]
  # @param meta [Array]
  # @param data [Array]
- # @param totals [Array|Hash|NilClass] Support for 'GROUP BY WITH TOTALS' modifier
- # https://clickhouse.tech/docs/en/sql-reference/statements/select/group-by/#with-totals-modifier
- # Hash in JSON format and Array in JSONCompact
- # rubocop:disable Metrics/ParameterLists
- def initialize(config:, meta:, data:, totals: nil, statistics: nil, rows_before_limit_at_least: nil)
  # @param summary [Response::Summary]
  def initialize(config:, meta:, data:, summary:)
  @config = config
  @meta = meta
  @data = data
- @totals = totals
- @rows_before_limit_at_least = rows_before_limit_at_least
- @statistics = Hash(statistics)
  @summary = summary
  end
- # rubocop:enable Metrics/ParameterLists
 
  # @return [Array, Hash]
  # @param data [Array, Hash]