diff --git a/README.md b/README.md index 30bd4e1..9f6e600 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: @@ -24,7 +24,6 @@ In your api file (somewhere on the top) logger.formatter = GrapeLogging::Formatters::Default.new use GrapeLogging::Middleware::RequestLogger, { logger: logger } - ## Features ### Log Format @@ -35,6 +34,25 @@ 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::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 @@ -42,6 +60,37 @@ 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::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_key') 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 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. + + - If you use a logger that already format logs (as the Logging gem), the logs will be formatted by your logger. ### Logging exceptions diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 282ad3e..d23956a 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -1,4 +1,9 @@ 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/formatters/json' +require 'grape_logging/loggers/base' +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/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/formatters/json.rb b/lib/grape_logging/formatters/json.rb new file mode 100644 index 0000000..342a782 --- /dev/null +++ b/lib/grape_logging/formatters/json.rb @@ -0,0 +1,33 @@ +module GrapeLogging + module Formatters + class Json + def call(severity, datetime, _, data) + { + date: datetime, + severity: severity, + data: format(data) + }.to_json + 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 diff --git a/lib/grape_logging/loggers/base.rb b/lib/grape_logging/loggers/base.rb new file mode 100644 index 0000000..c098eae --- /dev/null +++ b/lib/grape_logging/loggers/base.rb @@ -0,0 +1,12 @@ +module GrapeLogging + module Loggers + class Base + def before + end + + def parameters(request, response) + {} + 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..2559310 --- /dev/null +++ b/lib/grape_logging/loggers/filter_parameters.rb @@ -0,0 +1,23 @@ +module GrapeLogging + 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 + 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..bc671c3 --- /dev/null +++ b/lib/grape_logging/loggers/response.rb @@ -0,0 +1,27 @@ +module GrapeLogging + module Loggers + class Response < GrapeLogging::Loggers::Base + def parameters(request, response) + if response + { + response: serialized_response_body(response) + } + else + {} + end + 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 + response.body + end + end + end + end +end diff --git a/lib/grape_logging/middleware/request_logger.rb b/lib/grape_logging/middleware/request_logger.rb index e5491ef..e1b4a06 100644 --- a/lib/grape_logging/middleware/request_logger.rb +++ b/lib/grape_logging/middleware/request_logger.rb @@ -3,45 +3,76 @@ require 'grape/middleware/base' module GrapeLogging module Middleware class RequestLogger < Grape::Middleware::Base - 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) + 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] + @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 + reset_db_runtime + start_time + @included_loggers.each(&:before) end def after stop_time - logger.info parameters + + 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 + end + end + if @instrumentation_key + ActiveSupport::Notifications.instrument @instrumentation_key, params + else + @logger.info params + end + @included_loggers.each { |included_logger| included_logger.after if included_logger.respond_to?(:after) } nil end def call!(env) super - ensure - ActiveSupport::Notifications.unsubscribe(@subscription) if @subscription end protected + + def response + begin + super + rescue + nil + end + end + def parameters { - path: request.path, - params: request.params.to_hash, - method: request.request_method, + status: response.nil? ? 'fail' : response.status, + time: { total: total_runtime, - db: @db_duration.round(2), - status: response.status + db: db_runtime, + view: view_runtime + }, + method: request.request_method, + path: request.path, + params: request.params } end private - def logger - @logger ||= @options[:logger] || Logger.new(STDOUT) - end - def request @request ||= ::Rack::Request.new(env) end @@ -50,6 +81,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 @@ -57,6 +100,7 @@ module GrapeLogging def stop_time @stop_time ||= Time.now end + end end -end \ No newline at end of file +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 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