Merge branch 'guizmaii-master'

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
 

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'
+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'

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
+end

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

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

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

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

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
+      ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
-        @subscription = ActiveSupport::Notifications.subscribe('sql.active_record') do |*args|
+        event = ActiveSupport::Notifications::Event.new(*args)
-          event = ActiveSupport::Notifications::Event.new(*args)
+        GrapeLogging::Timings.append_db_runtime(event)
-          @db_duration += event.duration
+      end if defined?(ActiveRecord)
-        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,
+          status: response.nil? ? 'fail' : response.status,
-            params: request.params.to_hash,
+          time: {
-            method: request.request_method,
             total: total_runtime,
-            db: @db_duration.round(2),
+            db: db_runtime,
-            status: response.status
+            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
+end

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

lib/grape_logging/version.rb

@@ -1,3 +1,3 @@
 module GrapeLogging
-  VERSION = '1.1.2'
+  VERSION = '1.1.3'
 end