From eb63aa03e14e8b0d5a0697684c418a3a2d087f50 Mon Sep 17 00:00:00 2001 From: Rodrigo Souto Date: Fri, 29 May 2015 18:35:13 -0300 Subject: [PATCH 01/39] add support for obfuscated parameters Now you may override the method 'sensitive_parameters' with a list of parameters that should be obfuscated on the log. If the lib is loaded on a Rails application, uses the 'filter_parameters' attribute as default value for 'sensitive_parameters'. --- lib/grape_logging/middleware/request_logger.rb | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 121fe9c..424b640 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -23,7 +23,7 @@ module GrapeLogging def parameters(request, response) { path: request.path, - params: request.params.to_hash, + params: obfuscate_parameters(request.params), method: request.request_method, total: total_runtime, db: @db_duration.round(2), @@ -51,6 +51,18 @@ module GrapeLogging def stop_time @stop_time ||= Time.now end + + def obfuscate_parameters(request_parameters) + filtered_parameters = request_parameters.clone.to_hash + sensitive_parameters.each do |param| + filtered_parameters[param.to_s] = '***' + end + filtered_parameters + end + + def sensitive_parameters + defined?(Rails.application) ? Rails.application.config.filter_parameters : [] + end end end end \ No newline at end of file From 7ba9b5b83a4c719290c409c07c7a036166923546 Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 14:31:50 +0100 Subject: [PATCH 02/39] using pluggable loggers separating out the base logger behaviour and logging of specific parts of request / response into pluggable components also setting the defualt formatter for the logger --- lib/grape_logging.rb | 6 +- lib/grape_logging/formatters/default.rb | 4 +- lib/grape_logging/loggers/base.rb | 12 ++++ lib/grape_logging/loggers/database_time.rb | 21 +++++++ .../loggers/filter_parameters.rb | 23 ++++++++ lib/grape_logging/loggers/response.rb | 11 ++++ .../middleware/request_logger.rb | 55 +++++++++---------- 7 files changed, 100 insertions(+), 32 deletions(-) create mode 100644 lib/grape_logging/loggers/base.rb create mode 100644 lib/grape_logging/loggers/database_time.rb create mode 100644 lib/grape_logging/loggers/filter_parameters.rb create mode 100644 lib/grape_logging/loggers/response.rb diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 282ad3e..10dee2b 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -1,4 +1,8 @@ require 'grape_logging/multi_io' require 'grape_logging/version' require 'grape_logging/formatters/default' -require 'grape_logging/middleware/request_logger' \ No newline at end of file +require 'grape_logging/middleware/request_logger' +require 'grape_logging/loggers/base' +require 'grape_logging/loggers/database_time' +require 'grape_logging/loggers/response' +require 'grape_logging/loggers/filter_parameters' diff --git a/lib/grape_logging/formatters/default.rb b/lib/grape_logging/formatters/default.rb index dda10bb..54c1344 100644 --- a/lib/grape_logging/formatters/default.rb +++ b/lib/grape_logging/formatters/default.rb @@ -11,7 +11,7 @@ module GrapeLogging elsif data.is_a?(Exception) format_exception(data) elsif data.is_a?(Hash) - "#{data.delete(:status)} -- total=#{data.delete(:total)} db=#{data.delete(:db)} -- #{data.delete(:method)} #{data.delete(:path)} #{format_hash(data)}" + "#{data.delete(:status)} -- #{format_hash(data.delete(:time))} -- #{data.delete(:method)} #{data.delete(:path)} #{format_hash(data)}" else data.inspect end @@ -28,4 +28,4 @@ module GrapeLogging end end end -end \ No newline at end of file +end diff --git a/lib/grape_logging/loggers/base.rb b/lib/grape_logging/loggers/base.rb new file mode 100644 index 0000000..e0e65e1 --- /dev/null +++ b/lib/grape_logging/loggers/base.rb @@ -0,0 +1,12 @@ +module GrapeLogging + module Logger + class Base + def before + end + + def parameters(request, response) + {} + end + end + end +end diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb new file mode 100644 index 0000000..ab84a45 --- /dev/null +++ b/lib/grape_logging/loggers/database_time.rb @@ -0,0 +1,21 @@ +module GrapeLogging + module Logger + class DatabaseTime < GrapeLogging::Logger::Base + def before + @duration = 0 + ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + @duration += event.duration + end + end + + def parameters(request, response) + { + time: { + db: @duration.round(2) + } + } + end + end + end +end diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb new file mode 100644 index 0000000..a3cfe05 --- /dev/null +++ b/lib/grape_logging/loggers/filter_parameters.rb @@ -0,0 +1,23 @@ +module GrapeLogging + module Logger + class FilterParameters < GrapeLogging::Logger::Base + def initialize(filter_parameters = nil, replacement = '[FILTERED]') + @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : []) + @replacement = replacement + end + + def parameters(request, response) + filtered_parameters = request.params.clone + @filter_parameters.each do |param| + if filtered_parameters[param.to_s] + filtered_parameters[param.to_s] = @replacement + end + end + + { + params: filtered_parameters + } + end + end + end +end diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb new file mode 100644 index 0000000..04f8980 --- /dev/null +++ b/lib/grape_logging/loggers/response.rb @@ -0,0 +1,11 @@ +module GrapeLogging + module Logger + class Response < GrapeLogging::Logger::Base + def parameters(request, response) + { + response: response.body + } + end + end + end +end diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 424b640..3621a12 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -3,39 +3,47 @@ require 'grape/middleware/base' module GrapeLogging module Middleware class RequestLogger < Grape::Middleware::Base + def initialize(app, options = {}) + super + @logger = @options[:logger] || Logger.new(STDOUT) + @logger.formatter = @options[:formatter] || GrapeLogging::Formatters::Default.new + @included_loggers = @options[:include] || [] + end + def before start_time - - @db_duration = 0 - ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| - event = ActiveSupport::Notifications::Event.new(*args) - @db_duration += event.duration - end if defined?(ActiveRecord) + included_loggers.each do |included_logger| + included_logger.before + end end def after stop_time - logger.info parameters(request, response) + + parameters = parameters(request, response) + included_loggers.each do |included_logger| + parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| + oldval.respond_to?(:merge) ? oldval.merge(newval) : newval + end + end + @logger.info parameters nil end protected def parameters(request, response) { - path: request.path, - params: obfuscate_parameters(request.params), - method: request.request_method, - total: total_runtime, - db: @db_duration.round(2), - status: response.status + status: response.status, + time: { + total: total_runtime + }, + method: request.request_method, + path: request.path, + params: obfuscate_parameters(request.params) } end private - def logger - @logger ||= @options[:logger] || Logger.new(STDOUT) - end - def request @request ||= ::Rack::Request.new(env) end @@ -52,17 +60,6 @@ module GrapeLogging @stop_time ||= Time.now end - def obfuscate_parameters(request_parameters) - filtered_parameters = request_parameters.clone.to_hash - sensitive_parameters.each do |param| - filtered_parameters[param.to_s] = '***' - end - filtered_parameters - end - - def sensitive_parameters - defined?(Rails.application) ? Rails.application.config.filter_parameters : [] - end end end -end \ No newline at end of file +end From 2c208bd5c5f21c3b4f3b413e15e8d0a47de0424b Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 16:38:35 +0100 Subject: [PATCH 03/39] updating README with usage examples --- README.md | 30 +++++++++++++++++++++++++----- 1 file changed, 25 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 93b07c2..14c8095 100644 --- a/README.md +++ b/README.md @@ -10,7 +10,7 @@ Add this line to your application's Gemfile: And then execute: - $ bundle + $ bundle install Or install it yourself as: @@ -18,11 +18,11 @@ Or install it yourself as: ## Basic Usage -In your api file (somewhere on the top) - - logger.formatter = GrapeLogging::Formatters::Default.new - use GrapeLogging::Middleware::RequestLogger, { logger: logger } +Include the middleware in your api + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, logger: logger + end ## Features @@ -34,6 +34,26 @@ With the default configuration you will get nice log message If you prefer some other format I strongly encourage you to do pull request with new formatter class ;) +You can change the formatter like so + + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, logger: logger, format: MyFormatter.new + end + +### Customising What Is Logged + +You can include logging of other parts of the request / response cycle by including subclasses of `GrapeLogging::Loggers::Base` + + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, + logger: logger, + include: [ GrapeLogging::Loggers::Response.new, + GrapeLogging::Loggers::DatabaseTime.new, + GrapeLogging::Loggers::FilterParameters.new ] + end + +The `FilterParameters` logger will filter out sensitive parameters from your logs. If mounted inside rails, will use the `Rails.application.config.filter_parameters` by default. Otherwise, you must specify a list of keys to filter out. + ### Logging to file and STDOUT You can to file and STDOUT at the same time, you just need to assign new logger From 82eab4cc917b13034d4b1b82b636577c44ca8d5c Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 17:24:29 +0100 Subject: [PATCH 04/39] fixing some small bugs --- lib/grape_logging/middleware/request_logger.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 3621a12..32c7349 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -12,7 +12,7 @@ module GrapeLogging def before start_time - included_loggers.each do |included_logger| + @included_loggers.each do |included_logger| included_logger.before end end @@ -21,7 +21,7 @@ module GrapeLogging stop_time parameters = parameters(request, response) - included_loggers.each do |included_logger| + @included_loggers.each do |included_logger| parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| oldval.respond_to?(:merge) ? oldval.merge(newval) : newval end @@ -39,7 +39,7 @@ module GrapeLogging }, method: request.request_method, path: request.path, - params: obfuscate_parameters(request.params) + params: request.params } end From a05e0181019b22220f37485c64f58983c49171f6 Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 10 Aug 2015 11:09:49 +0100 Subject: [PATCH 05/39] using module name of Loggers rather than Logger also explicit to_s on response body --- lib/grape_logging/loggers/base.rb | 2 +- lib/grape_logging/loggers/database_time.rb | 4 ++-- lib/grape_logging/loggers/filter_parameters.rb | 4 ++-- lib/grape_logging/loggers/response.rb | 6 +++--- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/lib/grape_logging/loggers/base.rb b/lib/grape_logging/loggers/base.rb index e0e65e1..c098eae 100644 --- a/lib/grape_logging/loggers/base.rb +++ b/lib/grape_logging/loggers/base.rb @@ -1,5 +1,5 @@ module GrapeLogging - module Logger + module Loggers class Base def before end diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb index ab84a45..ec754fc 100644 --- a/lib/grape_logging/loggers/database_time.rb +++ b/lib/grape_logging/loggers/database_time.rb @@ -1,6 +1,6 @@ module GrapeLogging - module Logger - class DatabaseTime < GrapeLogging::Logger::Base + module Loggers + class DatabaseTime < GrapeLogging::Loggers::Base def before @duration = 0 ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb index a3cfe05..2559310 100644 --- a/lib/grape_logging/loggers/filter_parameters.rb +++ b/lib/grape_logging/loggers/filter_parameters.rb @@ -1,6 +1,6 @@ module GrapeLogging - module Logger - class FilterParameters < GrapeLogging::Logger::Base + module Loggers + class FilterParameters < GrapeLogging::Loggers::Base def initialize(filter_parameters = nil, replacement = '[FILTERED]') @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : []) @replacement = replacement diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 04f8980..31f7ca7 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -1,9 +1,9 @@ module GrapeLogging - module Logger - class Response < GrapeLogging::Logger::Base + module Loggers + class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body + response: response.body.to_s } end end From 1b834e1dc12e2168b2baa3630179d42f162368dd Mon Sep 17 00:00:00 2001 From: Rodrigo Souto Date: Fri, 29 May 2015 18:35:13 -0300 Subject: [PATCH 06/39] add support for obfuscated parameters Now you may override the method 'sensitive_parameters' with a list of parameters that should be obfuscated on the log. If the lib is loaded on a Rails application, uses the 'filter_parameters' attribute as default value for 'sensitive_parameters'. --- lib/grape_logging/middleware/request_logger.rb | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index e5491ef..8150ebe 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -29,7 +29,7 @@ module GrapeLogging def parameters { path: request.path, - params: request.params.to_hash, + params: obfuscate_parameters(request.params), method: request.request_method, total: total_runtime, db: @db_duration.round(2), @@ -57,6 +57,18 @@ module GrapeLogging def stop_time @stop_time ||= Time.now end + + def obfuscate_parameters(request_parameters) + filtered_parameters = request_parameters.clone.to_hash + sensitive_parameters.each do |param| + filtered_parameters[param.to_s] = '***' + end + filtered_parameters + end + + def sensitive_parameters + defined?(Rails.application) ? Rails.application.config.filter_parameters : [] + end end end end \ No newline at end of file From e5cff1267384fecb416c8e20982020288e9c7f9b Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 14:31:50 +0100 Subject: [PATCH 07/39] using pluggable loggers separating out the base logger behaviour and logging of specific parts of request / response into pluggable components also setting the defualt formatter for the logger --- lib/grape_logging.rb | 6 +- lib/grape_logging/formatters/default.rb | 4 +- lib/grape_logging/loggers/base.rb | 12 ++++ lib/grape_logging/loggers/database_time.rb | 21 +++++++ .../loggers/filter_parameters.rb | 23 ++++++++ lib/grape_logging/loggers/response.rb | 11 ++++ .../middleware/request_logger.rb | 57 +++++++++---------- 7 files changed, 101 insertions(+), 33 deletions(-) create mode 100644 lib/grape_logging/loggers/base.rb create mode 100644 lib/grape_logging/loggers/database_time.rb create mode 100644 lib/grape_logging/loggers/filter_parameters.rb create mode 100644 lib/grape_logging/loggers/response.rb diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 282ad3e..10dee2b 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -1,4 +1,8 @@ require 'grape_logging/multi_io' require 'grape_logging/version' require 'grape_logging/formatters/default' -require 'grape_logging/middleware/request_logger' \ No newline at end of file +require 'grape_logging/middleware/request_logger' +require 'grape_logging/loggers/base' +require 'grape_logging/loggers/database_time' +require 'grape_logging/loggers/response' +require 'grape_logging/loggers/filter_parameters' diff --git a/lib/grape_logging/formatters/default.rb b/lib/grape_logging/formatters/default.rb index dda10bb..54c1344 100644 --- a/lib/grape_logging/formatters/default.rb +++ b/lib/grape_logging/formatters/default.rb @@ -11,7 +11,7 @@ module GrapeLogging elsif data.is_a?(Exception) format_exception(data) elsif data.is_a?(Hash) - "#{data.delete(:status)} -- total=#{data.delete(:total)} db=#{data.delete(:db)} -- #{data.delete(:method)} #{data.delete(:path)} #{format_hash(data)}" + "#{data.delete(:status)} -- #{format_hash(data.delete(:time))} -- #{data.delete(:method)} #{data.delete(:path)} #{format_hash(data)}" else data.inspect end @@ -28,4 +28,4 @@ module GrapeLogging end end end -end \ No newline at end of file +end diff --git a/lib/grape_logging/loggers/base.rb b/lib/grape_logging/loggers/base.rb new file mode 100644 index 0000000..e0e65e1 --- /dev/null +++ b/lib/grape_logging/loggers/base.rb @@ -0,0 +1,12 @@ +module GrapeLogging + module Logger + class Base + def before + end + + def parameters(request, response) + {} + end + end + end +end diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb new file mode 100644 index 0000000..ab84a45 --- /dev/null +++ b/lib/grape_logging/loggers/database_time.rb @@ -0,0 +1,21 @@ +module GrapeLogging + module Logger + class DatabaseTime < GrapeLogging::Logger::Base + def before + @duration = 0 + ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + @duration += event.duration + end + end + + def parameters(request, response) + { + time: { + db: @duration.round(2) + } + } + end + end + end +end diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb new file mode 100644 index 0000000..a3cfe05 --- /dev/null +++ b/lib/grape_logging/loggers/filter_parameters.rb @@ -0,0 +1,23 @@ +module GrapeLogging + module Logger + class FilterParameters < GrapeLogging::Logger::Base + def initialize(filter_parameters = nil, replacement = '[FILTERED]') + @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : []) + @replacement = replacement + end + + def parameters(request, response) + filtered_parameters = request.params.clone + @filter_parameters.each do |param| + if filtered_parameters[param.to_s] + filtered_parameters[param.to_s] = @replacement + end + end + + { + params: filtered_parameters + } + end + end + end +end diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb new file mode 100644 index 0000000..04f8980 --- /dev/null +++ b/lib/grape_logging/loggers/response.rb @@ -0,0 +1,11 @@ +module GrapeLogging + module Logger + class Response < GrapeLogging::Logger::Base + def parameters(request, response) + { + response: response.body + } + end + end + end +end diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 8150ebe..b731415 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -3,19 +3,30 @@ require 'grape/middleware/base' module GrapeLogging module Middleware class RequestLogger < Grape::Middleware::Base + def initialize(app, options = {}) + super + @logger = @options[:logger] || Logger.new(STDOUT) + @logger.formatter = @options[:formatter] || GrapeLogging::Formatters::Default.new + @included_loggers = @options[:include] || [] + end + def before start_time - - @db_duration = 0 - @subscription = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| - event = ActiveSupport::Notifications::Event.new(*args) - @db_duration += event.duration - end if defined?(ActiveRecord) + included_loggers.each do |included_logger| + included_logger.before + end end def after stop_time - logger.info parameters + + parameters = parameters(request, response) + included_loggers.each do |included_logger| + parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| + oldval.respond_to?(:merge) ? oldval.merge(newval) : newval + end + end + @logger.info parameters nil end @@ -26,22 +37,19 @@ module GrapeLogging end protected - def parameters + def parameters(request, response) { - path: request.path, - params: obfuscate_parameters(request.params), - method: request.request_method, - total: total_runtime, - db: @db_duration.round(2), - status: response.status + status: response.status, + time: { + total: total_runtime + }, + method: request.request_method, + path: request.path, + params: obfuscate_parameters(request.params) } end private - def logger - @logger ||= @options[:logger] || Logger.new(STDOUT) - end - def request @request ||= ::Rack::Request.new(env) end @@ -58,17 +66,6 @@ module GrapeLogging @stop_time ||= Time.now end - def obfuscate_parameters(request_parameters) - filtered_parameters = request_parameters.clone.to_hash - sensitive_parameters.each do |param| - filtered_parameters[param.to_s] = '***' - end - filtered_parameters - end - - def sensitive_parameters - defined?(Rails.application) ? Rails.application.config.filter_parameters : [] - end end end -end \ No newline at end of file +end From def34f7b8d6b722dc43a9e4b559facb5782d81e8 Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 16:38:35 +0100 Subject: [PATCH 08/39] updating README with usage examples --- README.md | 30 +++++++++++++++++++++++++----- 1 file changed, 25 insertions(+), 5 deletions(-) diff --git a/README.md b/README.md index 6925a8f..4cac959 100644 --- a/README.md +++ b/README.md @@ -10,7 +10,7 @@ Add this line to your application's Gemfile: And then execute: - $ bundle + $ bundle install Or install it yourself as: @@ -18,11 +18,11 @@ Or install it yourself as: ## Basic Usage -In your api file (somewhere on the top) - - logger.formatter = GrapeLogging::Formatters::Default.new - use GrapeLogging::Middleware::RequestLogger, { logger: logger } +Include the middleware in your api + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, logger: logger + end ## Features @@ -34,6 +34,26 @@ With the default configuration you will get nice log message If you prefer some other format I strongly encourage you to do pull request with new formatter class ;) +You can change the formatter like so + + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, logger: logger, format: MyFormatter.new + end + +### Customising What Is Logged + +You can include logging of other parts of the request / response cycle by including subclasses of `GrapeLogging::Loggers::Base` + + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, + logger: logger, + include: [ GrapeLogging::Loggers::Response.new, + GrapeLogging::Loggers::DatabaseTime.new, + GrapeLogging::Loggers::FilterParameters.new ] + end + +The `FilterParameters` logger will filter out sensitive parameters from your logs. If mounted inside rails, will use the `Rails.application.config.filter_parameters` by default. Otherwise, you must specify a list of keys to filter out. + ### Logging to file and STDOUT You can to file and STDOUT at the same time, you just need to assign new logger From 89fdbb0e499946509e9d598741e3713edc8ca1ef Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 13 Jul 2015 17:24:29 +0100 Subject: [PATCH 09/39] fixing some small bugs --- lib/grape_logging/middleware/request_logger.rb | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index b731415..07d6af3 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -12,7 +12,7 @@ module GrapeLogging def before start_time - included_loggers.each do |included_logger| + @included_loggers.each do |included_logger| included_logger.before end end @@ -21,7 +21,7 @@ module GrapeLogging stop_time parameters = parameters(request, response) - included_loggers.each do |included_logger| + @included_loggers.each do |included_logger| parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| oldval.respond_to?(:merge) ? oldval.merge(newval) : newval end @@ -45,7 +45,7 @@ module GrapeLogging }, method: request.request_method, path: request.path, - params: obfuscate_parameters(request.params) + params: request.params } end From de4d5c2c0fab6bdb412d02a9bba1e28e0a2631e7 Mon Sep 17 00:00:00 2001 From: Duncan Williams Date: Mon, 10 Aug 2015 11:09:49 +0100 Subject: [PATCH 10/39] using module name of Loggers rather than Logger also explicit to_s on response body --- lib/grape_logging/loggers/base.rb | 2 +- lib/grape_logging/loggers/database_time.rb | 4 ++-- lib/grape_logging/loggers/filter_parameters.rb | 4 ++-- lib/grape_logging/loggers/response.rb | 6 +++--- 4 files changed, 8 insertions(+), 8 deletions(-) diff --git a/lib/grape_logging/loggers/base.rb b/lib/grape_logging/loggers/base.rb index e0e65e1..c098eae 100644 --- a/lib/grape_logging/loggers/base.rb +++ b/lib/grape_logging/loggers/base.rb @@ -1,5 +1,5 @@ module GrapeLogging - module Logger + module Loggers class Base def before end diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb index ab84a45..ec754fc 100644 --- a/lib/grape_logging/loggers/database_time.rb +++ b/lib/grape_logging/loggers/database_time.rb @@ -1,6 +1,6 @@ module GrapeLogging - module Logger - class DatabaseTime < GrapeLogging::Logger::Base + module Loggers + class DatabaseTime < GrapeLogging::Loggers::Base def before @duration = 0 ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb index a3cfe05..2559310 100644 --- a/lib/grape_logging/loggers/filter_parameters.rb +++ b/lib/grape_logging/loggers/filter_parameters.rb @@ -1,6 +1,6 @@ module GrapeLogging - module Logger - class FilterParameters < GrapeLogging::Logger::Base + module Loggers + class FilterParameters < GrapeLogging::Loggers::Base def initialize(filter_parameters = nil, replacement = '[FILTERED]') @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : []) @replacement = replacement diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 04f8980..31f7ca7 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -1,9 +1,9 @@ module GrapeLogging - module Logger - class Response < GrapeLogging::Logger::Base + module Loggers + class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body + response: response.body.to_s } end end From 2e0f8c2aa5c47fa455b35f30ece0c9c7d2b167f7 Mon Sep 17 00:00:00 2001 From: jules Date: Wed, 21 Oct 2015 19:42:49 +0200 Subject: [PATCH 11/39] Add JSON formatter --- lib/grape_logging/formatters/json.rb | 33 ++++++++++++++++++++++++++++ 1 file changed, 33 insertions(+) create mode 100644 lib/grape_logging/formatters/json.rb diff --git a/lib/grape_logging/formatters/json.rb b/lib/grape_logging/formatters/json.rb new file mode 100644 index 0000000..1ea150e --- /dev/null +++ b/lib/grape_logging/formatters/json.rb @@ -0,0 +1,33 @@ +module GrapeLogging + module Formatters + class Json + def call(severity, datetime, _, data) + JSON.parse({ + date: datetime, + severity: severity, + data: format(data) + }) + end + + private + + def format(data) + if data.is_a?(String) || data.is_a?(Hash) + data + elsif data.is_a?(Exception) + format_exception(data) + else + data.inspect + end + end + + def format_exception(exception) + { + exception: { + message: exception.message + } + } + end + end + end +end From 9a593ee99647bef4012e64e3b49c845ba1cf3462 Mon Sep 17 00:00:00 2001 From: jules Date: Wed, 21 Oct 2015 19:49:25 +0200 Subject: [PATCH 12/39] Add JSON formatter --- lib/grape_logging/formatters/json.rb | 12 +++++++----- 1 file changed, 7 insertions(+), 5 deletions(-) diff --git a/lib/grape_logging/formatters/json.rb b/lib/grape_logging/formatters/json.rb index 1ea150e..e5c96ae 100644 --- a/lib/grape_logging/formatters/json.rb +++ b/lib/grape_logging/formatters/json.rb @@ -2,11 +2,13 @@ module GrapeLogging module Formatters class Json def call(severity, datetime, _, data) - JSON.parse({ - date: datetime, - severity: severity, - data: format(data) - }) + JSON.parse( + { + date: datetime, + severity: severity, + data: format(data) + } + ) end private From 6bc1b9405d94602f7af278ae8636af5c585f8efe Mon Sep 17 00:00:00 2001 From: jules Date: Wed, 21 Oct 2015 20:10:18 +0200 Subject: [PATCH 13/39] Don't forget to import the new formatter --- lib/grape_logging.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 10dee2b..a521a37 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -1,7 +1,7 @@ require 'grape_logging/multi_io' require 'grape_logging/version' require 'grape_logging/formatters/default' -require 'grape_logging/middleware/request_logger' +require 'grape_logging/formatters/json' require 'grape_logging/loggers/base' require 'grape_logging/loggers/database_time' require 'grape_logging/loggers/response' From 95dcaa097956c6111208e43bb899b07530433005 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 15:01:16 +0200 Subject: [PATCH 14/39] Typo --- lib/grape_logging.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index a521a37..7155dfb 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -6,3 +6,4 @@ require 'grape_logging/loggers/base' require 'grape_logging/loggers/database_time' require 'grape_logging/loggers/response' require 'grape_logging/loggers/filter_parameters' +require 'grape_logging/middleware/request_logger' \ No newline at end of file From ed8d25f89ffb0a926268fc05ff19c3c5615a3adc Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 15:13:30 +0200 Subject: [PATCH 15/39] JSON serialization was wrong --- lib/grape_logging/formatters/json.rb | 12 +++++------- 1 file changed, 5 insertions(+), 7 deletions(-) diff --git a/lib/grape_logging/formatters/json.rb b/lib/grape_logging/formatters/json.rb index e5c96ae..342a782 100644 --- a/lib/grape_logging/formatters/json.rb +++ b/lib/grape_logging/formatters/json.rb @@ -2,13 +2,11 @@ module GrapeLogging module Formatters class Json def call(severity, datetime, _, data) - JSON.parse( - { - date: datetime, - severity: severity, - data: format(data) - } - ) + { + date: datetime, + severity: severity, + data: format(data) + }.to_json end private From c716f78f2ac1080a6c54317feb8cdb5398976952 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 15:16:55 +0200 Subject: [PATCH 16/39] response.body should not be return as string --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 31f7ca7..e16d404 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,7 +3,7 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body.to_s + response: response.body } end end From 7412cd5cf306acca4071426aca3a30f7e0c0fa10 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 15:47:52 +0200 Subject: [PATCH 17/39] Add an option to use the Rails instrumentation --- lib/grape_logging/middleware/request_logger.rb | 18 ++++++++++++------ 1 file changed, 12 insertions(+), 6 deletions(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 07d6af3..63b6e60 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -5,16 +5,18 @@ module GrapeLogging class RequestLogger < Grape::Middleware::Base def initialize(app, options = {}) super - @logger = @options[:logger] || Logger.new(STDOUT) - @logger.formatter = @options[:formatter] || GrapeLogging::Formatters::Default.new + if options[:instrumentation_key] + @instrumentation_key = options[:instrumentation_key] + else + @logger = @options[:logger] || Logger.new(STDOUT) + @logger.formatter = @options[:formatter] || GrapeLogging::Formatters::Default.new + end @included_loggers = @options[:include] || [] end def before start_time - @included_loggers.each do |included_logger| - included_logger.before - end + @included_loggers.each { |included_logger| included_logger.before } end def after @@ -26,7 +28,11 @@ module GrapeLogging oldval.respond_to?(:merge) ? oldval.merge(newval) : newval end end - @logger.info parameters + if @instrumentation_key + ActiveSupport::Notifications.instrument @instrumentation_key, parameters + else + @logger.info parameters + end nil end From 7997b21b17ed88da8940179a6cd17ed04c8f4857 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 15:54:53 +0200 Subject: [PATCH 18/39] response.body is a string. It should be serialized --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index e16d404..c9696fb 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,7 +3,7 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body + response: JSON.parse(response.body) } end end From 3fd1ba13f3b92832778eb06d7f792074411b6bf0 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 16:01:31 +0200 Subject: [PATCH 19/39] response.body is an Array of Strings. We should get the first element and It should be serialized --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index c9696fb..27d7413 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,7 +3,7 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: JSON.parse(response.body) + response: JSON.parse(response.body.first) } end end From c90d565ebef013de99d3a9a8053907dcb5d943b0 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 16:03:53 +0200 Subject: [PATCH 20/39] response.body is an Array of Strings. We should serialized every body in this Array --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 27d7413..2163b11 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,7 +3,7 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: JSON.parse(response.body.first) + response: response.body.map{ |body| JSON.parse(body) } } end end From 4115e6383b58c8fdeca9e81f985eb30c5112430f Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 17:19:06 +0200 Subject: [PATCH 21/39] Code quality --- lib/grape_logging/loggers/database_time.rb | 7 ++++++- lib/grape_logging/middleware/request_logger.rb | 6 ++---- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb index ec754fc..c93ca14 100644 --- a/lib/grape_logging/loggers/database_time.rb +++ b/lib/grape_logging/loggers/database_time.rb @@ -3,12 +3,17 @@ module GrapeLogging class DatabaseTime < GrapeLogging::Loggers::Base def before @duration = 0 - ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| + @subscription = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| event = ActiveSupport::Notifications::Event.new(*args) @duration += event.duration end end + def after + ensure + ActiveSupport::Notifications.unsubscribe(@subscription) if @subscription + end + def parameters(request, response) { time: { diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 63b6e60..f61b1bc 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -22,7 +22,7 @@ module GrapeLogging def after stop_time - parameters = parameters(request, response) + parameters = get_parameters @included_loggers.each do |included_logger| parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| oldval.respond_to?(:merge) ? oldval.merge(newval) : newval @@ -38,12 +38,10 @@ module GrapeLogging def call!(env) super - ensure - ActiveSupport::Notifications.unsubscribe(@subscription) if @subscription end protected - def parameters(request, response) + def get_parameters { status: response.status, time: { From ccb9ec052e17f1850162585aea55b7639c92763f Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 17:21:06 +0200 Subject: [PATCH 22/39] Code quality --- lib/grape_logging/loggers/database_time.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb index c93ca14..0738422 100644 --- a/lib/grape_logging/loggers/database_time.rb +++ b/lib/grape_logging/loggers/database_time.rb @@ -6,7 +6,7 @@ module GrapeLogging @subscription = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| event = ActiveSupport::Notifications::Event.new(*args) @duration += event.duration - end + end if defined?(ActiveRecord) end def after From 7c310ec9463f44218bdb5ab570c1e9cb15221c15 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 17:28:37 +0200 Subject: [PATCH 23/39] Code quality --- lib/grape_logging/middleware/request_logger.rb | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index f61b1bc..cac4c91 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -22,16 +22,16 @@ module GrapeLogging def after stop_time - parameters = get_parameters + params = parameter @included_loggers.each do |included_logger| - parameters.merge! included_logger.parameters(request, response) do |key, oldval, newval| + params.merge! included_logger.parameters(request, response) do |key, oldval, newval| oldval.respond_to?(:merge) ? oldval.merge(newval) : newval end end if @instrumentation_key - ActiveSupport::Notifications.instrument @instrumentation_key, parameters + ActiveSupport::Notifications.instrument @instrumentation_key, params else - @logger.info parameters + @logger.info params end nil end @@ -41,7 +41,7 @@ module GrapeLogging end protected - def get_parameters + def parameter { status: response.status, time: { From 25f0883399709c75fa4d50731e820eff5d0dc9e1 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 17:33:22 +0200 Subject: [PATCH 24/39] After shoul be called --- lib/grape_logging/middleware/request_logger.rb | 1 + 1 file changed, 1 insertion(+) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index cac4c91..4d83ff7 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -33,6 +33,7 @@ module GrapeLogging else @logger.info params end + @included_loggers.each { |included_logger| included_logger.after if included_logger.respond_to?(:after) } nil end From da5d32ca684c32bcb99c0137b8de1faf191b533e Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 17:35:50 +0200 Subject: [PATCH 25/39] Typo --- lib/grape_logging/middleware/request_logger.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 4d83ff7..0272124 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -22,7 +22,7 @@ module GrapeLogging def after stop_time - params = parameter + params = parameters @included_loggers.each do |included_logger| params.merge! included_logger.parameters(request, response) do |key, oldval, newval| oldval.respond_to?(:merge) ? oldval.merge(newval) : newval @@ -42,7 +42,7 @@ module GrapeLogging end protected - def parameter + def parameters { status: response.status, time: { From 2a81b65de63403eff1e2aec9b41a0ceab6522706 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 18:07:15 +0200 Subject: [PATCH 26/39] Add documentation --- README.md | 32 ++++++++++++++++++++++++++++++++ 1 file changed, 32 insertions(+) diff --git a/README.md b/README.md index 4cac959..9e32cda 100644 --- a/README.md +++ b/README.md @@ -61,6 +61,38 @@ You can to file and STDOUT at the same time, you just need to assign new logger log_file = File.open('path/to/your/logfile.log', 'a') log_file.sync = true logger Logger.new GrapeLogging::MultiIO.new(STDOUT, log_file) + +### Logging via Rails instrumentation + +You can choose to not pass the logger to ```grape_logging``` but instead send logs to Rails instrumentation in order to let Rails and its configured Logger do the log job, for example. +First, config ```grape_logging```, like that: + + class MyAPI < Grape::API + use GrapeLogging::Middleware::RequestLogger, + instrumentation_key: 'grape_key', + include: [ GrapeLogging::Loggers::Response.new, + GrapeLogging::Loggers::DatabaseTime.new, + GrapeLogging::Loggers::FilterParameters.new ] + end + +and then add an initializer in your Rails project: + + # config/initializers/instrumentation.rb + + # Subscribe to grape request and log with Rails.logger + ActiveSupport::Notifications.subscribe('grape') do |name, starts, ends, notification_id, payload| + Rails.logger.info payload + end + +The idea come from here: https://gist.github.com/teamon/e8ae16ffb0cb447e5b49 + +There's some advantage to use this method: + + - You could use a logger that does not implement the ```formatter=```. + Defaults Rails 3 (ActiveSupport::BufferedLogger) does not implement it. + The Logging gem (https://github.com/TwP/logging) does not implement it neither + + - If you use a logger that already format logs (as the Logging gem), the logs will be formatted by your logger ### Logging exceptions From c582617209d5d6ad6b3d266981b67a2cdf178ec6 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 18:09:01 +0200 Subject: [PATCH 27/39] Typos --- README.md | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index 9e32cda..150880e 100644 --- a/README.md +++ b/README.md @@ -86,13 +86,13 @@ and then add an initializer in your Rails project: The idea come from here: https://gist.github.com/teamon/e8ae16ffb0cb447e5b49 -There's some advantage to use this method: +There's some advantages to use this method: - You could use a logger that does not implement the ```formatter=```. Defaults Rails 3 (ActiveSupport::BufferedLogger) does not implement it. - The Logging gem (https://github.com/TwP/logging) does not implement it neither + The Logging gem (https://github.com/TwP/logging) does not implement it neither. - - If you use a logger that already format logs (as the Logging gem), the logs will be formatted by your logger + - If you use a logger that already format logs (as the Logging gem), the logs will be formatted by your logger. ### Logging exceptions From 33db51245b3dc48abf521479c28af2b53b95da14 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 18:10:28 +0200 Subject: [PATCH 28/39] Update the version --- lib/grape_logging/version.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/version.rb b/lib/grape_logging/version.rb index 2c67eb9..7a37aea 100644 --- a/lib/grape_logging/version.rb +++ b/lib/grape_logging/version.rb @@ -1,3 +1,3 @@ module GrapeLogging - VERSION = '1.1.2' + VERSION = '1.1.3' end From 7fb15d204c21716c1962c152f80d8aa6dd219827 Mon Sep 17 00:00:00 2001 From: jules Date: Fri, 23 Oct 2015 18:12:20 +0200 Subject: [PATCH 29/39] Typo --- README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/README.md b/README.md index 150880e..83efde9 100644 --- a/README.md +++ b/README.md @@ -80,7 +80,7 @@ and then add an initializer in your Rails project: # config/initializers/instrumentation.rb # Subscribe to grape request and log with Rails.logger - ActiveSupport::Notifications.subscribe('grape') do |name, starts, ends, notification_id, payload| + ActiveSupport::Notifications.subscribe('grape_key') do |name, starts, ends, notification_id, payload| Rails.logger.info payload end From b8bd70e57b8b5249c6f3e0141ccbb40c39e9864b Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 26 Oct 2015 10:52:46 +0100 Subject: [PATCH 30/39] response.body is sometimes too strange to be parse by JSON --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 2163b11..e16d404 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,7 +3,7 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body.map{ |body| JSON.parse(body) } + response: response.body } end end From 918cba5c2d56c4a2befb43bf8355865fb3f81ba3 Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 26 Oct 2015 11:05:54 +0100 Subject: [PATCH 31/39] response.body is sometimes too strange to be parse by JSON --- lib/grape_logging/loggers/response.rb | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index e16d404..ae45e3d 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -3,9 +3,21 @@ module GrapeLogging class Response < GrapeLogging::Loggers::Base def parameters(request, response) { - response: response.body + response: serialized_response_body(response) } end + + private + # In some cases, response.body is not parseable by JSON. + # For example, if you POST on a PUT endpoint, response.body is egal to """". + # It's strange but it's the Grape behavior... + def serialized_response_body(response) + begin + response.body.map{ |body| JSON.parse(body) } + rescue => e + "" + end + end end end end From 522014fa6a3ecd92279d340f7f7025303bdae06a Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 26 Oct 2015 11:10:46 +0100 Subject: [PATCH 32/39] response.body is sometimes too strange to be parse by JSON, BIS --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index ae45e3d..6c9e566 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -15,7 +15,7 @@ module GrapeLogging begin response.body.map{ |body| JSON.parse(body) } rescue => e - "" + {} end end end From 55b75c624383f8fa3ba711433388e4c91410a059 Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 26 Oct 2015 16:32:14 +0100 Subject: [PATCH 33/39] response.body is sometimes too strange to be parse by JSON, just return it --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 6c9e566..55e42b4 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -15,7 +15,7 @@ module GrapeLogging begin response.body.map{ |body| JSON.parse(body) } rescue => e - {} + body end end end From 64f266d9892340f1e79a9bf3a0114bcbf73b9b13 Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 26 Oct 2015 16:32:27 +0100 Subject: [PATCH 34/39] response.body is sometimes too strange to be parse by JSON, just return it, BIS --- lib/grape_logging/loggers/response.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 55e42b4..650d98c 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -15,7 +15,7 @@ module GrapeLogging begin response.body.map{ |body| JSON.parse(body) } rescue => e - body + response.body end end end From 714f361b170013a64052cb22884d0b2f5e00e77b Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 29 Feb 2016 15:32:29 +0100 Subject: [PATCH 35/39] Use the https://github.com/aserafin/grape_logging/pull/18 code to add thread safety for the use of ActiveSupport::Notifications --- README.md | 2 -- lib/grape_logging.rb | 2 +- lib/grape_logging/loggers/database_time.rb | 26 ------------------- .../middleware/request_logger.rb | 23 +++++++++++++++- lib/grape_logging/timings.rb | 21 +++++++++++++++ 5 files changed, 44 insertions(+), 30 deletions(-) delete mode 100644 lib/grape_logging/loggers/database_time.rb create mode 100644 lib/grape_logging/timings.rb diff --git a/README.md b/README.md index 0e75ff6..9f6e600 100644 --- a/README.md +++ b/README.md @@ -48,7 +48,6 @@ You can include logging of other parts of the request / response cycle by includ use GrapeLogging::Middleware::RequestLogger, logger: logger, include: [ GrapeLogging::Loggers::Response.new, - GrapeLogging::Loggers::DatabaseTime.new, GrapeLogging::Loggers::FilterParameters.new ] end @@ -71,7 +70,6 @@ First, config ```grape_logging```, like that: use GrapeLogging::Middleware::RequestLogger, instrumentation_key: 'grape_key', include: [ GrapeLogging::Loggers::Response.new, - GrapeLogging::Loggers::DatabaseTime.new, GrapeLogging::Loggers::FilterParameters.new ] end diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 6789ec0..d23956a 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -3,7 +3,7 @@ require 'grape_logging/version' require 'grape_logging/formatters/default' require 'grape_logging/formatters/json' require 'grape_logging/loggers/base' -require 'grape_logging/loggers/database_time' require 'grape_logging/loggers/response' require 'grape_logging/loggers/filter_parameters' +require 'grape_logging/timings' require 'grape_logging/middleware/request_logger' diff --git a/lib/grape_logging/loggers/database_time.rb b/lib/grape_logging/loggers/database_time.rb deleted file mode 100644 index 0738422..0000000 --- a/lib/grape_logging/loggers/database_time.rb +++ /dev/null @@ -1,26 +0,0 @@ -module GrapeLogging - module Loggers - class DatabaseTime < GrapeLogging::Loggers::Base - def before - @duration = 0 - @subscription = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| - event = ActiveSupport::Notifications::Event.new(*args) - @duration += event.duration - end if defined?(ActiveRecord) - end - - def after - ensure - ActiveSupport::Notifications.unsubscribe(@subscription) if @subscription - end - - def parameters(request, response) - { - time: { - db: @duration.round(2) - } - } - end - end - end -end diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index 0272124..f46fcf6 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -3,6 +3,12 @@ require 'grape/middleware/base' module GrapeLogging module Middleware class RequestLogger < Grape::Middleware::Base + + ActiveSupport::Notifications.subscribe('sql.active_record') do |*args| + event = ActiveSupport::Notifications::Event.new(*args) + GrapeLogging::Timings.append_db_runtime(event) + end if defined?(ActiveRecord) + def initialize(app, options = {}) super if options[:instrumentation_key] @@ -15,6 +21,7 @@ module GrapeLogging end def before + reset_db_runtime start_time @included_loggers.each { |included_logger| included_logger.before } end @@ -46,7 +53,9 @@ module GrapeLogging { status: response.status, time: { - total: total_runtime + total: total_runtime, + db: db_runtime, + view: view_runtime }, method: request.request_method, path: request.path, @@ -63,6 +72,18 @@ module GrapeLogging ((stop_time - start_time) * 1000).round(2) end + def view_runtime + total_runtime - db_runtime + end + + def db_runtime + GrapeLogging::Timings.db_runtime.round(2) + end + + def reset_db_runtime + GrapeLogging::Timings.reset_db_runtime + end + def start_time @start_time ||= Time.now end diff --git a/lib/grape_logging/timings.rb b/lib/grape_logging/timings.rb new file mode 100644 index 0000000..145d99f --- /dev/null +++ b/lib/grape_logging/timings.rb @@ -0,0 +1,21 @@ +module GrapeLogging + module Timings + extend self + + def db_runtime=(value) + Thread.current[:grape_db_runtime] = value + end + + def db_runtime + Thread.current[:grape_db_runtime] ||= 0 + end + + def reset_db_runtime + self.db_runtime = 0 + end + + def append_db_runtime(event) + self.db_runtime = event.duration + end + end +end \ No newline at end of file From fe72aa1a155dd5b236a08c52e2ebde526266d95c Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 29 Feb 2016 15:38:01 +0100 Subject: [PATCH 36/39] Lisibility --- lib/grape_logging/middleware/request_logger.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index f46fcf6..d737731 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -23,7 +23,7 @@ module GrapeLogging def before reset_db_runtime start_time - @included_loggers.each { |included_logger| included_logger.before } + @included_loggers.each(&:before) end def after From ef946bf7fefb976a056181679b30c4b3d89f33df Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 29 Feb 2016 16:20:40 +0100 Subject: [PATCH 37/39] Since the Grape v0.14.1, the after callback is always called, so response could be nil if the called fail with an exception --- lib/grape_logging/loggers/response.rb | 10 +++++++--- lib/grape_logging/middleware/request_logger.rb | 2 +- 2 files changed, 8 insertions(+), 4 deletions(-) diff --git a/lib/grape_logging/loggers/response.rb b/lib/grape_logging/loggers/response.rb index 650d98c..bc671c3 100644 --- a/lib/grape_logging/loggers/response.rb +++ b/lib/grape_logging/loggers/response.rb @@ -2,9 +2,13 @@ module GrapeLogging module Loggers class Response < GrapeLogging::Loggers::Base def parameters(request, response) - { - response: serialized_response_body(response) - } + if response + { + response: serialized_response_body(response) + } + else + {} + end end private diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index d737731..cf89c48 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -51,7 +51,7 @@ module GrapeLogging protected def parameters { - status: response.status, + status: response.try(:status), time: { total: total_runtime, db: db_runtime, From e8fa681bb8421c83ae732ef455e52f06bf9940b3 Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 29 Feb 2016 16:32:43 +0100 Subject: [PATCH 38/39] We should protect the call to response --- lib/grape_logging/middleware/request_logger.rb | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index cf89c48..df23509 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -49,6 +49,15 @@ module GrapeLogging end protected + + def response + begin + super + rescue + nil + end + end + def parameters { status: response.try(:status), From d45d4956a904bff9d040d62df140be142488c995 Mon Sep 17 00:00:00 2001 From: jules Date: Mon, 29 Feb 2016 16:35:18 +0100 Subject: [PATCH 39/39] Show the failure of the call --- lib/grape_logging/middleware/request_logger.rb | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index df23509..e1b4a06 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -60,7 +60,7 @@ module GrapeLogging def parameters { - status: response.try(:status), + status: response.nil? ? 'fail' : response.status, time: { total: total_runtime, db: db_runtime,