From 4276cd642a0890a83d61ab046b4456fd354a7511 Mon Sep 17 00:00:00 2001 From: Mason McLead Date: Thu, 13 Apr 2017 00:41:59 -0700 Subject: [PATCH 1/2] adding an option to format log message to be one line --- README.md | 7 +++-- lib/grape/middleware/logger.rb | 27 ++++++++++------- .../lib/grape/middleware/logger_spec.rb | 30 ++++++++++++++----- .../lib/grape/middleware/logger_spec.rb | 29 +++++++++++++----- 4 files changed, 64 insertions(+), 29 deletions(-) diff --git a/README.md b/README.md index d0dfae2..a667163 100644 --- a/README.md +++ b/README.md @@ -52,6 +52,7 @@ Completed 422 in 6.29ms The middleware logger can be customized with the following options: * The `:logger` option can be any object that responds to `.info(String)` +* The `:one_line` option configures the log output to be on one line instead of multiple. It accepts `true` or `false`. The default configuration is `false` * The `:filter` option can be any object that responds to `.filter(Hash)` and returns a hash. * The `:headers` option can be either `:all` or array of strings. + If `:all`, all request headers will be output. @@ -62,17 +63,19 @@ For example: ```ruby insert_after Grape::Middleware::Formatter, Grape::Middleware::Logger, { logger: Logger.new(STDERR), + one_line: true, filter: Class.new { def filter(opts) opts.reject { |k, _| k.to_s == 'password' } end }.new, headers: %w(version cache-control) + filter: Class.new { def filter(opts) opts.reject { |k, _| k.to_s == 'password' } end }.new } ``` ## Using Rails? -`Rails.logger` and `Rails.application.config.filter_parameters` will be used automatically as the default logger and +`Rails.logger` and `Rails.application.config.filter_parameters` will be used automatically as the default logger and param filterer, respectively. This behavior can be overridden by passing the `:logger` or `:filter` option when mounting. -You may want to disable Rails logging for API endpoints, so that the logging doesn't double-up. You can achieve this +You may want to disable Rails logging for API endpoints, so that the logging doesn't double-up. You can achieve this by switching around some middleware. For example: ```ruby diff --git a/lib/grape/middleware/logger.rb b/lib/grape/middleware/logger.rb index 38e9d29..082471b 100644 --- a/lib/grape/middleware/logger.rb +++ b/lib/grape/middleware/logger.rb @@ -7,7 +7,7 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals attr_reader :logger class << self - attr_accessor :logger, :filter, :headers + attr_accessor :logger, :filter, :one_line, :headers def default_logger default = Logger.new(STDOUT) @@ -20,6 +20,7 @@ def initialize(_, options = {}) super @options[:filter] ||= self.class.filter @options[:headers] ||= self.class.headers + @options[:one_line] ||= false @logger = options[:logger] || self.class.logger || self.class.default_logger end @@ -27,15 +28,19 @@ def before start_time # sets env['grape.*'] super - logger.info '' - logger.info %Q(Started %s "%s" at %s) % [ - env[Grape::Env::GRAPE_REQUEST].request_method, - env[Grape::Env::GRAPE_REQUEST].path, - start_time.to_s - ] - logger.info %Q(Processing by #{processed_by}) - logger.info %Q( Parameters: #{parameters}) - logger.info %Q( Headers: #{headers}) if @options[:headers] + if @options[:one_line] + logger.info %Q(Started #{env[Grape::Env::GRAPE_REQUEST].request_method} "#{env[Grape::Env::GRAPE_REQUEST].path}" at #{start_time.to_s} - Processing by #{processed_by} - Parameters: #{parameters}) + else + logger.info '' + logger.info %Q(Started %s "%s" at %s) % [ + env[Grape::Env::GRAPE_REQUEST].request_method, + env[Grape::Env::GRAPE_REQUEST].path, + start_time.to_s + ] + logger.info %Q(Processing by #{processed_by}) + logger.info %Q( Parameters: #{parameters}) + logger.info %Q( Headers: #{headers}) if @options[:headers] + end end # @note Error and exception handling are required for the +after+ hooks @@ -65,7 +70,7 @@ def call!(env) def after(status) logger.info "Completed #{status} in #{((Time.now - start_time) * 1000).round(2)}ms" - logger.info '' + logger.info '' unless @options[:one_line] end # diff --git a/spec/integration/lib/grape/middleware/logger_spec.rb b/spec/integration/lib/grape/middleware/logger_spec.rb index fb001e2..458f62a 100644 --- a/spec/integration/lib/grape/middleware/logger_spec.rb +++ b/spec/integration/lib/grape/middleware/logger_spec.rb @@ -11,14 +11,28 @@ let(:grape_endpoint) { build(:grape_endpoint) } let(:env) { build(:expected_env, grape_endpoint: grape_endpoint) } - it 'logs all parts of the request' do - expect(subject.logger).to receive(:info).with '' - expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time}) - expect(subject.logger).to receive(:info).with %Q(Processing by TestAPI/users) - expect(subject.logger).to receive(:info).with %Q( Parameters: {"id"=>"101001", "secret"=>"[FILTERED]", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) - expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ - expect(subject.logger).to receive(:info).with '' - subject.call!(env) + context 'when the option[:one_line] is false' do + let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), one_line: false } } + + it 'logs all parts of the request on multiple lines' do + expect(subject.logger).to receive(:info).with '' + expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time}) + expect(subject.logger).to receive(:info).with %Q(Processing by TestAPI/users) + expect(subject.logger).to receive(:info).with %Q( Parameters: {"id"=>"101001", "secret"=>"[FILTERED]", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) + expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ + expect(subject.logger).to receive(:info).with '' + subject.call!(env) + end + end + + context 'when the options[:one_line is true' do + let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), one_line: true } } + + it 'logs all parts of the request on one line' do + expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time} - Processing by TestAPI/users - Parameters: {"id"=>"101001", "secret"=>"[FILTERED]", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) + expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ + subject.call!(env) + end end context 'when an exception occurs' do diff --git a/spec/integration_rails/lib/grape/middleware/logger_spec.rb b/spec/integration_rails/lib/grape/middleware/logger_spec.rb index 3d9b6fa..73e0c50 100644 --- a/spec/integration_rails/lib/grape/middleware/logger_spec.rb +++ b/spec/integration_rails/lib/grape/middleware/logger_spec.rb @@ -42,14 +42,27 @@ end end - it 'logs all parts of the request' do - expect(subject.logger).to receive(:info).with '' - expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time}) - expect(subject.logger).to receive(:info).with %Q(Processing by TestAPI/users) - expect(subject.logger).to receive(:info).with %Q( Parameters: {"id"=>"101001", "secret"=>"key", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) - expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ - expect(subject.logger).to receive(:info).with '' - subject.call!(env) + context 'when the option[:one_line] is false' do + let(:options) { { one_line: false } } + + it 'logs all parts of the request on multiple lines' do + expect(subject.logger).to receive(:info).with '' + expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time}) + expect(subject.logger).to receive(:info).with %Q(Processing by TestAPI/users) + expect(subject.logger).to receive(:info).with %Q( Parameters: {"id"=>"101001", "secret"=>"key", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) + expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ + expect(subject.logger).to receive(:info).with '' + subject.call!(env) + end + end + + context 'when the option[:one_line] is true' do + let(:options) { { one_line: true } } + it 'logs all parts of the request on one line' do + expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time} - Processing by TestAPI/users - Parameters: {"id"=>"101001", "secret"=>"key", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) + expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/ + subject.call!(env) + end end describe 'the "processing by" section' do From 6546c9351255daa668c8c954fbdf9eae6e31eb2a Mon Sep 17 00:00:00 2001 From: Mason McLead Date: Fri, 2 Jun 2017 09:50:46 -0700 Subject: [PATCH 2/2] renaming to :condensed --- .byebug_history | 5 +++ README.md | 5 +-- lib/grape/middleware/logger.rb | 40 ++++++++++++------- .../lib/grape/middleware/logger_spec.rb | 8 ++-- .../lib/grape/middleware/logger_spec.rb | 8 ++-- 5 files changed, 41 insertions(+), 25 deletions(-) create mode 100644 .byebug_history diff --git a/.byebug_history b/.byebug_history new file mode 100644 index 0000000..577a447 --- /dev/null +++ b/.byebug_history @@ -0,0 +1,5 @@ +exit +c +log_statements.compact.delete_if(&:empty?).each(&:strip!) +log_statements.compact.delete_if(&:empty?).each(&:lstrip) +log_statements.compact.delete_if(&:empty?).each(&:strip) diff --git a/README.md b/README.md index a667163..dd7dbe7 100644 --- a/README.md +++ b/README.md @@ -52,7 +52,7 @@ Completed 422 in 6.29ms The middleware logger can be customized with the following options: * The `:logger` option can be any object that responds to `.info(String)` -* The `:one_line` option configures the log output to be on one line instead of multiple. It accepts `true` or `false`. The default configuration is `false` +* The `:condensed` option configures the log output to be on one line instead of multiple. It accepts `true` or `false`. The default configuration is `false` * The `:filter` option can be any object that responds to `.filter(Hash)` and returns a hash. * The `:headers` option can be either `:all` or array of strings. + If `:all`, all request headers will be output. @@ -63,10 +63,9 @@ For example: ```ruby insert_after Grape::Middleware::Formatter, Grape::Middleware::Logger, { logger: Logger.new(STDERR), - one_line: true, + condensed: true, filter: Class.new { def filter(opts) opts.reject { |k, _| k.to_s == 'password' } end }.new, headers: %w(version cache-control) - filter: Class.new { def filter(opts) opts.reject { |k, _| k.to_s == 'password' } end }.new } ``` diff --git a/lib/grape/middleware/logger.rb b/lib/grape/middleware/logger.rb index 082471b..3c63f40 100644 --- a/lib/grape/middleware/logger.rb +++ b/lib/grape/middleware/logger.rb @@ -7,7 +7,7 @@ class Grape::Middleware::Logger < Grape::Middleware::Globals attr_reader :logger class << self - attr_accessor :logger, :filter, :one_line, :headers + attr_accessor :logger, :filter, :headers, :condensed def default_logger default = Logger.new(STDOUT) @@ -20,7 +20,7 @@ def initialize(_, options = {}) super @options[:filter] ||= self.class.filter @options[:headers] ||= self.class.headers - @options[:one_line] ||= false + @options[:condensed] ||= false @logger = options[:logger] || self.class.logger || self.class.default_logger end @@ -28,19 +28,19 @@ def before start_time # sets env['grape.*'] super - if @options[:one_line] - logger.info %Q(Started #{env[Grape::Env::GRAPE_REQUEST].request_method} "#{env[Grape::Env::GRAPE_REQUEST].path}" at #{start_time.to_s} - Processing by #{processed_by} - Parameters: #{parameters}) - else - logger.info '' - logger.info %Q(Started %s "%s" at %s) % [ + + log_statements = [ + '', + %Q(Started %s "%s" at %s) % [ env[Grape::Env::GRAPE_REQUEST].request_method, env[Grape::Env::GRAPE_REQUEST].path, start_time.to_s - ] - logger.info %Q(Processing by #{processed_by}) - logger.info %Q( Parameters: #{parameters}) - logger.info %Q( Headers: #{headers}) if @options[:headers] - end + ], + %Q(Processing by #{processed_by}), + %Q( Parameters: #{parameters})] + + log_statements.append(%Q( Headers: #{headers})) if @options[:headers] + log_info(log_statements) end # @note Error and exception handling are required for the +after+ hooks @@ -69,8 +69,12 @@ def call!(env) end def after(status) - logger.info "Completed #{status} in #{((Time.now - start_time) * 1000).round(2)}ms" - logger.info '' unless @options[:one_line] + log_info( + [ + "Completed #{status} in #{((Time.now - start_time) * 1000).round(2)}ms", + '' + ] + ) end # @@ -125,6 +129,14 @@ def processed_by result.concat endpoint.options[:path].map { |path| path.to_s.sub(BACKSLASH, '') } endpoint.options[:for].to_s << result.join(BACKSLASH) end + + def log_info(log_statements=[]) + if @options[:condensed] + logger.info log_statements.compact.delete_if(&:empty?).each(&:strip!).join(" - ") + else + log_statements.each { |log_statement| logger.info log_statement } + end + end end require_relative 'logger/railtie' if defined?(Rails) diff --git a/spec/integration/lib/grape/middleware/logger_spec.rb b/spec/integration/lib/grape/middleware/logger_spec.rb index 458f62a..a15d741 100644 --- a/spec/integration/lib/grape/middleware/logger_spec.rb +++ b/spec/integration/lib/grape/middleware/logger_spec.rb @@ -11,8 +11,8 @@ let(:grape_endpoint) { build(:grape_endpoint) } let(:env) { build(:expected_env, grape_endpoint: grape_endpoint) } - context 'when the option[:one_line] is false' do - let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), one_line: false } } + context 'when the option[:condensed] is false' do + let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), condensed: false } } it 'logs all parts of the request on multiple lines' do expect(subject.logger).to receive(:info).with '' @@ -25,8 +25,8 @@ end end - context 'when the options[:one_line is true' do - let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), one_line: true } } + context 'when the options[:condensed is true' do + let(:options) { { filter: build(:param_filter), logger: Logger.new(Tempfile.new('logger')), condensed: true } } it 'logs all parts of the request on one line' do expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time} - Processing by TestAPI/users - Parameters: {"id"=>"101001", "secret"=>"[FILTERED]", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) diff --git a/spec/integration_rails/lib/grape/middleware/logger_spec.rb b/spec/integration_rails/lib/grape/middleware/logger_spec.rb index 73e0c50..f25d5b2 100644 --- a/spec/integration_rails/lib/grape/middleware/logger_spec.rb +++ b/spec/integration_rails/lib/grape/middleware/logger_spec.rb @@ -42,8 +42,8 @@ end end - context 'when the option[:one_line] is false' do - let(:options) { { one_line: false } } + context 'when the option[:condensed] is false' do + let(:options) { { condensed: false } } it 'logs all parts of the request on multiple lines' do expect(subject.logger).to receive(:info).with '' @@ -56,8 +56,8 @@ end end - context 'when the option[:one_line] is true' do - let(:options) { { one_line: true } } + context 'when the option[:condensed] is true' do + let(:options) { { condensed: true } } it 'logs all parts of the request on one line' do expect(subject.logger).to receive(:info).with %Q(Started POST "/api/1.0/users" at #{subject.start_time} - Processing by TestAPI/users - Parameters: {"id"=>"101001", "secret"=>"key", "customer"=>[], "name"=>"foo", "password"=>"[FILTERED]"}) expect(subject.logger).to receive(:info).with /Completed 200 in \d+.\d+ms/