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 aff776d..ef51c32 100644 --- a/README.md +++ b/README.md @@ -55,6 +55,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 `: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. @@ -65,17 +66,18 @@ For example: ```ruby insert_after Grape::Middleware::Formatter, Grape::Middleware::Logger, { logger: Logger.new(STDERR), + condensed: true, filter: Class.new { def filter(opts) opts.reject { |k, _| k.to_s == 'password' } end }.new, headers: %w(version cache-control) } ``` ## 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..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, :headers + attr_accessor :logger, :filter, :headers, :condensed 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[:condensed] ||= 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] + + 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 + ], + %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 @@ -64,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 '' + log_info( + [ + "Completed #{status} in #{((Time.now - start_time) * 1000).round(2)}ms", + '' + ] + ) end # @@ -120,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 fb001e2..a15d741 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[: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 '' + 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[: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]"}) + 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..f25d5b2 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[: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 '' + 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[: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/ + subject.call!(env) + end end describe 'the "processing by" section' do