Add rails logging and logsubscriber configuration

lib/sapience/configuration/grape.rb

@@ -0,0 +1,9 @@
+module Sapience
+  class Configuration
+    class Grape
+      def self.configure
+        Grape::API.send(:include, Sapience::Loggable)
+      end
+    end
+  end
+end

lib/sapience/configuration/rails.rb

@@ -0,0 +1,29 @@
+module Sapience
+  class Configuration
+    class Rails
+      # rubocop:disable LineLength, AbcSize, CyclomaticComplexity, PerceivedComplexity
+      def self.configure
+        ::Rails.logger = Sapience[::Rails]
+        [:active_record, :action_controller, :action_mailer, :action_view].each do |name|
+          ActiveSupport.on_load(name) { include Sapience::Loggable }
+        end
+        ActiveSupport.on_load(:action_cable) { self.logger = Sapience["ActionCable"] }
+        require("sapience/extensions/action_cable/tagged_logger_proxy") if defined?(ActionCable)
+        require("sapience/extensions/action_controller/live") if defined?(ActionController::Live)
+        require("sapience/extensions/action_dispatch/debug_exceptions") if defined?(ActionDispatch::DebugExceptions)
+        require("sapience/extensions/action_view/streaming_template_renderer") if defined?(ActionView::StreamingTemplateRenderer::Body)
+        require("sapience/extensions/active_job/logging") if defined?(ActiveJob)
+        require("sapience/extensions/active_model_serializers/logging") if defined?(ActiveModelSerializers)
+
+        require("sapience/extensions/rack/logger") if defined?(Rails::Rack::Logger)
+        require("sapience/extensions/action_controller/log_subscriber") if defined?(ActionController)
+        require("sapience/extensions/active_record/log_subscriber") if defined?(ActiveRecord::LogSubscriber)
+
+        require("sapience/extensions/rack/logger_info_as_debug") if defined?(Rails::Rack::Logger)
+        require("sapience/extensions/action_view/log_subscriber") if defined?(ActionView::LogSubscriber)
+        require("sapience/extensions/action_controller/log_subscriber_processing") if defined?(ActionView::LogSubscriber)
+      end
+      # rubocop:enable LineLength, AbcSize, CyclomaticComplexity, PerceivedComplexity
+    end
+  end
+end

lib/sapience/extensions/action_controller/live.rb

@@ -0,0 +1,6 @@
+# Log actual exceptions, not a string representation
+module ActionController::Live # rubocop:disable ClassAndModuleChildren
+  def log_error(exception)
+    logger.fatal(exception)
+  end
+end

lib/sapience/extensions/action_controller/log_subscriber.rb

@@ -0,0 +1,95 @@
+require "action_controller/log_subscriber"
+
+class ActionController::LogSubscriber # rubocop:disable ClassAndModuleChildren
+  # Log as debug to hide Processing messages in production
+  def start_processing(event)
+    controller_logger(event).debug { "Processing ##{event.payload[:action]}" }
+  end
+
+  def process_action(event) # rubocop:disable AbcSize, CyclomaticComplexity, PerceivedComplexity
+    controller_logger(event).info do
+      payload = event.payload.dup
+      payload[:params].except!(*INTERNAL_PARAMS)
+      payload.delete(:params) if payload[:params].empty?
+
+      format           = payload[:format]
+      payload[:format] = format.to_s.upcase if format.is_a?(Symbol)
+
+      payload[:path]   = extract_path(payload[:path]) if payload.key?(:path)
+
+      exception = payload.delete(:exception)
+      if payload[:status].nil? && exception.present?
+        exception_class_name = exception.first
+        payload[:status]     = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception_class_name)
+      end
+
+      # Rounds off the runtimes. For example, :view_runtime, :mongo_runtime, etc.
+      payload.keys.each do |key|
+        payload[key] = payload[key].to_f.round(2) if key.to_s.match(/(.*)_runtime/)
+      end
+
+      payload[:message]        = "Completed ##{payload[:action]}"
+      payload[:status_message] = Rack::Utils::HTTP_STATUS_CODES[payload[:status]] if payload[:status].present?
+      payload[:duration]       = event.duration
+      # Causes excessive log output with Rails 5 RC1
+      payload.delete(:headers)
+      payload
+    end
+  end
+
+  def halted_callback(event)
+    controller_logger(event).info { "Filter chain halted as #{event.payload[:filter].inspect} rendered or redirected" }
+  end
+
+  def send_file(event)
+    controller_logger(event).info("Sent file") { { path: event.payload[:path], duration: event.duration } }
+  end
+
+  def redirect_to(event)
+    controller_logger(event).info("Redirected to") { { location: event.payload[:location] } }
+  end
+
+  def send_data(event)
+    controller_logger(event).info("Sent data") { { file_name: event.payload[:filename], duration: event.duration } }
+  end
+
+  def unpermitted_parameters(event)
+    controller_logger(event).debug do
+      unpermitted_keys = event.payload[:keys]
+      "Unpermitted parameter#{"s" if unpermitted_keys.size > 1}: #{unpermitted_keys.join(", ")}"
+    end
+  end
+
+  %w(write_fragment read_fragment exist_fragment?
+     expire_fragment expire_page write_page).each do |method|
+    class_eval <<-METHOD, __FILE__, __LINE__ + 1
+      def #{method}(event)
+        controller_logger(event).info do
+          key_or_path = event.payload[:key] || event.payload[:path]
+          {message: "#{method.to_s.humanize} \#{key_or_path}", duration: event.duration}
+        end
+      end
+    METHOD
+  end
+
+  private
+
+  # Returns the logger for the supplied event.
+  # Returns ActionController::Base.logger if no controller is present
+  def controller_logger(event)
+    if (controller = event.payload[:controller])
+      begin
+        controller.constantize.logger
+      rescue NameError
+        ActionController::Base.logger
+      end
+    else
+      ActionController::Base.logger
+    end
+  end
+
+  def extract_path(path)
+    index = path.index("?")
+    index ? path[0, index] : path
+  end
+end

lib/sapience/extensions/action_controller/log_subscriber_processing.rb

@@ -0,0 +1,24 @@
+require "action_controller/log_subscriber"
+
+class ActionController::LogSubscriber # rubocop:disable ClassAndModuleChildren
+  # Log as info to show Processing messages in production
+  def start_processing(event)
+    controller_logger(event).info { "Processing ##{event.payload[:action]}" }
+  end
+
+  private
+
+  # Returns the logger for the supplied event.
+  # Returns ActionController::Base.logger if no controller is present
+  def controller_logger(event)
+    if (controller = event.payload[:controller])
+      begin
+        controller.constantize.logger
+      rescue NameError
+        ActionController::Base.logger
+      end
+    else
+      ActionController::Base.logger
+    end
+  end
+end

lib/sapience/extensions/action_dispatch/debug_exceptions.rb

@@ -0,0 +1,11 @@
+# Log actual exceptions, not a string representation
+
+class ActionDispatch::DebugExceptions # rubocop:disable ClassAndModuleChildren
+  private
+
+  def log_error(_request, wrapper)
+    ActiveSupport::Deprecation.silence do
+      ActionController::Base.logger.fatal(wrapper.exception)
+    end
+  end
+end

lib/sapience/extensions/action_view/log_subscriber.rb

@@ -0,0 +1,9 @@
+class ActionView::LogSubscriber # rubocop:disable ClassAndModuleChildren
+  def info(message = nil, &block)
+    debug(message, &block)
+  end
+
+  def info?
+    debug?
+  end
+end

lib/sapience/extensions/action_view/streaming_template_renderer.rb

@@ -0,0 +1,11 @@
+# Log actual exceptions, not a string representation
+
+class ActionView::StreamingTemplateRenderer # rubocop:disable ClassAndModuleChildren
+  class Body
+    private
+
+    def log_error(exception) #:nodoc:
+      ActionView::Base.logger.fatal(exception)
+    end
+  end
+end

lib/sapience/extensions/active_job/logging.rb

@@ -0,0 +1,12 @@
+# Patch ActiveJob logger
+require "active_job/logging"
+
+module ActiveJob::Logging # rubocop:disable ClassAndModuleChildren
+  include Sapience::Loggable
+
+  private
+
+  def tag_logger(*tags, &block)
+    logger.tagged(*tags, &block)
+  end
+end

lib/sapience/extensions/active_model_serializers/logging.rb

@@ -0,0 +1,12 @@
+# Patch ActiveModelSerializers logger
+require "active_model_serializers/logging"
+
+module ActiveModelSerializers::Logging # rubocop:disable ClassAndModuleChildren
+  include Sapience::Loggable
+
+  private
+
+  def tag_logger(*tags, &block)
+    logger.tagged(*tags, &block)
+  end
+end

lib/sapience/extensions/active_record/log_subscriber.rb

@@ -0,0 +1,33 @@
+class ActiveRecord::LogSubscriber # rubocop:disable ClassAndModuleChildren
+  def sql(event) # rubocop:disable AbcSize
+    self.class.runtime += event.duration
+
+    return unless logger.debug?
+
+    payload = event.payload
+    name    = payload[:name]
+    return if IGNORE_PAYLOAD_NAMES.include?(name)
+
+    log = {
+      message:  name,
+      sql:      payload[:sql],
+      duration: event.duration,
+    }
+    unless (payload[:binds] || []).empty?
+      log[:binds] = binds = {}
+      # Changed with Rails 5
+      if Rails.version.to_i >= 5
+        payload[:binds].each do |attr|
+          attr_name, value = render_bind(attr)
+          binds[attr_name] = value
+        end
+      else
+        payload[:binds].each do |col, v|
+          attr_name, value = render_bind(col, v)
+          binds[attr_name] = value
+        end
+      end
+    end
+    debug(log)
+  end
+end

lib/sapience/extensions/rack/logger.rb

@@ -0,0 +1,11 @@
+# Replace rack started message with a semantic equivalent
+class Rails::Rack::Logger # rubocop:disable ClassAndModuleChildren
+  def started_request_message(request)
+    {
+      message: "Started",
+      method:  request.request_method,
+      path:    request.filtered_path,
+      ip:      request.ip,
+    }
+  end
+end

lib/sapience/extensions/rack/logger_info_as_debug.rb

@@ -0,0 +1,22 @@
+# Drop rack Started message to debug level message
+class Rails::Rack::Logger # rubocop:disable ClassAndModuleChildren
+  private
+
+  module LogInfoAsDebug
+    def info(*args, &block)
+      debug(*args, &block)
+    end
+
+    def info?
+      debug?
+    end
+  end
+
+  def logger
+    @logger ||= begin
+      logger = Sapience["Rails"]
+      logger.extend(LogInfoAsDebug)
+      logger
+    end
+  end
+end

spec/lib/sapience/configuration/grape_spec.rb

@@ -0,0 +1,6 @@
+require "spec_helper"
+
+describe Sapience::Configuration::Grape do
+  describe ".configure" do
+  end
+end

spec/lib/sapience/configuration/rails_spec.rb

@@ -0,0 +1,6 @@
+require "spec_helper"
+
+describe Sapience::Configuration::Rails do
+  describe ".configure" do
+  end
+end