diff --git a/README.md b/README.md index 4eadf38..a8ee893 100644 --- a/README.md +++ b/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` diff --git a/grape_logging.gemspec b/grape_logging.gemspec index 377465f..ebe4cf4 100644 --- a/grape_logging.gemspec +++ b/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' diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 0886d21..aa0c457 100644 --- a/lib/grape_logging.rb +++ b/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' diff --git a/lib/grape_logging/formatters/rails.rb b/lib/grape_logging/formatters/rails.rb new file mode 100644 index 0000000..1451862 --- /dev/null +++ b/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 diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb index 1e45482..84a17b7 100644 --- a/lib/grape_logging/loggers/filter_parameters.rb +++ b/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 diff --git a/lib/grape_logging/util/parameter_filter.rb b/lib/grape_logging/util/parameter_filter.rb index 23b99a5..9e94bc9 100644 --- a/lib/grape_logging/util/parameter_filter.rb +++ b/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) diff --git a/spec/lib/grape_logging/formatters/rails_spec.rb b/spec/lib/grape_logging/formatters/rails_spec.rb new file mode 100644 index 0000000..15863e2 --- /dev/null +++ b/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