Add GrapeLogging::Formatters::RailsFormatter.new. Updates to README (#47)

README.md

@@ -33,11 +33,83 @@ use GrapeLogging::Middleware::RequestLogger, { logger: logger }
 
 ### Log Format
 
-With the default configuration you will get nice log message
+There are formatters provided for you, or you can provide your own.
 
-    [2015-04-16 12:52:12 +0200] INFO -- 200 -- total=2.06 db=0.36 -- PATCH /your_app/endpoint params={"some_param"=>{"value_1"=>"123", "value_2"=>"456"}}
+#### `GrapeLogging::Formatters::Default`
 
-If you prefer some other format I strongly encourage you to do pull request with new formatter class ;)
+    [2015-04-16 12:52:12 +0200] INFO -- 200 -- total=2.06 db=0.36 -- PATCH /api/endpoint params={"some_param"=>{"value_1"=>"123", "value_2"=>"456"}}
+
+#### `GrapeLogging::Formatters::Json`
+
+```json
+{
+  "date": "2015-04-16 12:52:12+0200",
+  "severity": "INFO",
+  "data": {
+    "status": 200,
+    "time": {
+      "total": 2.06,
+      "db": 0.36,
+      "view": 1.70
+    },
+    "method": "PATCH",
+    "path": "/api/endpoint",
+    "params": {
+      "value_1": "123",
+      "value_2": "456"
+    },
+    "host": "localhost"
+  }
+}
+```
+
+#### `GrapeLogging::Formatters::Lograge`
+
+    severity="INFO", duration=2.06, db=0.36, view=1.70, datetime="2015-04-16 12:52:12+0200", status=200, method="PATCH", path="/api/endpoint", params={}, host="localhost"
+
+#### `GrapeLogging::Formatters::Logstash`
+
+```json
+{
+  "@timestamp": "2015-04-16 12:52:12+0200",
+  "severity": "INFO",
+  "status": 200,
+  "time": {
+    "total": 2.06,
+    "db": 0.36,
+    "view": 1.70
+  },
+  "method": "PATCH",
+  "path": "/api/endpoint",
+  "params": {
+    "value_1": "123",
+    "value_2": "456"
+  },
+  "host": "localhost"
+}
+```
+
+#### `GrapeLogging::Formatters::Rails`
+
+Rails will print the "Started..." line:
+
+    Started GET "/api/endpoint" for ::1 at 2015-04-16 12:52:12 +0200
+      User Load (0.7ms)  SELECT "users".* FROM "users" WHERE  "users"."id" = $1
+      ...
+
+The `Rails` formatter adds the last line of the request, like a standard Rails request:
+
+    Completed 200 OK in 349ms (Views: 250.1ms | DB: 98.63ms)
+
+#### Custom
+
+You can provide your own class that implements the `call` method returning a `String`:
+
+```ruby
+def call(severity, datetime, _, data)
+   ...
+end
+```
 
 You can change the formatter like so
 ```ruby
@@ -46,6 +118,8 @@ class MyAPI < Grape::API
 end
 ```
 
+If you prefer some other format I strongly encourage you to do pull request with new formatter class ;)
+
 ### Customising What Is Logged
 
 You can include logging of other parts of the request / response cycle by including subclasses of `GrapeLogging::Loggers::Base`

grape_logging.gemspec

@@ -20,6 +20,7 @@ Gem::Specification.new do |spec|
   spec.require_paths = ['lib']
 
   spec.add_dependency 'grape'
+  spec.add_dependency 'rack'
 
   spec.add_development_dependency 'bundler', '~> 1.8'
   spec.add_development_dependency 'rake', '~> 10.0'

lib/grape_logging.rb

@@ -4,6 +4,7 @@ require 'grape_logging/formatters/default'
 require 'grape_logging/formatters/json'
 require 'grape_logging/formatters/lograge'
 require 'grape_logging/formatters/logstash'
+require 'grape_logging/formatters/rails'
 require 'grape_logging/loggers/base'
 require 'grape_logging/loggers/response'
 require 'grape_logging/loggers/filter_parameters'

lib/grape_logging/formatters/rails.rb

@@ -0,0 +1,59 @@
+require 'rack/utils'
+
+module GrapeLogging
+  module Formatters
+    class Rails
+
+      def call(severity, datetime, _, data)
+        if data.is_a?(String)
+          "#{severity[0..0]} [#{datetime}] #{severity} -- : #{data}\n"
+        elsif data.is_a?(Exception)
+          "#{severity[0..0]} [#{datetime}] #{severity} -- : #{format_exception(data)}\n"
+        elsif data.is_a?(Hash)
+          format_hash(data)
+        else
+          "#{data.inspect}\n"
+        end
+      end
+
+      private
+
+      def format_exception(exception)
+        backtrace_array = (exception.backtrace || []).map { |line| "\t#{line}" }
+
+        [
+          "#{exception.message} (#{exception.class})",
+          backtrace_array.join("\n")
+        ].reject{|line| line == ""}.join("\n")
+      end
+
+      def format_hash(hash)
+        # Create Rails' single summary line at the end of every request, formatted like:
+        # Completed 200 OK in 958ms (Views: 951.1ms | ActiveRecord: 3.8ms)
+        # See: actionpack/lib/action_controller/log_subscriber.rb
+
+        message = ""
+        additions = []
+        status = hash.delete(:status)
+        params = hash.delete(:params)
+
+        total_time = hash[:time] && hash[:time][:total] && hash[:time][:total].round(2)
+        view_time  = hash[:time] && hash[:time][:view]  && hash[:time][:view].round(2)
+        db_time    = hash[:time] && hash[:time][:db]    && hash[:time][:db].round(2)
+
+        additions << "Views: #{view_time}ms" if view_time
+        additions << "DB: #{db_time}ms"      if db_time
+
+        message << "  Parameters: #{params.inspect}\n" if params
+
+        message << "Completed #{status} #{::Rack::Utils::HTTP_STATUS_CODES[status]} in #{total_time}ms"
+        message << " (#{additions.join(" | ".freeze)})" if additions.size > 0
+        message << "\n"
+        message << "\n" if defined?(::Rails.env) && ::Rails.env.development?
+
+        message
+      end
+
+    end
+  end
+end

lib/grape_logging/loggers/filter_parameters.rb

@@ -4,7 +4,7 @@ module GrapeLogging
       AD_PARAMS = 'action_dispatch.request.parameters'.freeze
 
       def initialize(filter_parameters = nil, replacement = nil, exceptions = %w(controller action format))
-        @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : [])
+        @filter_parameters = filter_parameters || (defined?(::Rails.application) ? ::Rails.application.config.filter_parameters : [])
         @replacement = replacement || '[FILTERED]'
         @exceptions = exceptions
       end

lib/grape_logging/util/parameter_filter.rb

@@ -1,4 +1,4 @@
-if defined?(Rails.application)
+if defined?(::Rails.application)
   class ParameterFilter < ActionDispatch::Http::ParameterFilter
     def initialize(_replacement, filter_parameters)
       super(filter_parameters)

spec/lib/grape_logging/formatters/rails_spec.rb

@@ -0,0 +1,79 @@
+require 'spec_helper'
+
+describe GrapeLogging::Formatters::Rails do
+  let(:formatter) { described_class.new }
+  let(:severity) { "INFO" }
+  let(:datetime) { Time.new('2018', '03', '02', '10', '35', '04', '+13:00') }
+
+  let(:exception_data) { ArgumentError.new('Message') }
+  let(:hash_data) {
+    {
+      status: 200,
+      time: {
+        total: 272.4,
+        db: 40.63,
+        view: 231.76999999999998
+      },
+      method: "GET",
+      path: "/api/endpoint",
+      host: "localhost"
+    }
+  }
+
+  describe '#call' do
+    context 'string data' do
+      it 'returns a formatted string' do
+        message = formatter.call(severity, datetime, nil, 'value')
+
+        expect(message).to eq "I [2018-03-02 10:35:04 +1300] INFO -- : value\n"
+      end
+    end
+
+    context 'exception data' do
+      it 'returns a string with a backtrace' do
+        exception_data.set_backtrace(caller)
+
+        message = formatter.call(severity, datetime, nil, exception_data)
+        lines = message.split("\n")
+
+        expect(lines[0]).to eq "I [2018-03-02 10:35:04 +1300] INFO -- : Message (ArgumentError)"
+        expect(lines[1]).to include 'grape_logging'
+        expect(lines.size).to be > 1
+      end
+    end
+
+    context 'hash data' do
+      it 'returns a formatted string' do
+        message = formatter.call(severity, datetime, nil, hash_data)
+
+        expect(message).to eq "Completed 200 OK in 272.4ms (Views: 231.77ms | DB: 40.63ms)\n"
+      end
+
+      it 'includes params if included (from GrapeLogging::Loggers::FilterParameters)' do
+        hash_data.merge!(
+          params: {
+            "some_param" => {
+              value_1: "123",
+              value_2: "456"
+            }
+          }
+        )
+
+        message = formatter.call(severity, datetime, nil, hash_data)
+        lines = message.split("\n")
+
+        expect(lines.first).to eq '  Parameters: {"some_param"=>{:value_1=>"123", :value_2=>"456"}}'
+        expect(lines.last).to eq "Completed 200 OK in 272.4ms (Views: 231.77ms | DB: 40.63ms)"
+      end
+    end
+
+    context "unhandled data" do
+      it 'returns the #inspect string representation' do
+        message = formatter.call(severity, datetime, nil, [1, 2, 3])
+
+        expect(message).to eq "[1, 2, 3]\n"
+      end
+    end
+  end
+
+end