Merge pull request #16 from mmclead/one_line_log_option

adding an option to format log message to be one line

.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)

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

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,22 +20,27 @@ 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
 
   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)

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

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