Feature/rails error handling improved

lib/logstasher.rb

@@ -6,12 +6,21 @@
 require 'logstasher/active_job/log_subscriber'
 require 'logstasher/rails_ext/action_controller/base'
 require 'logstasher/custom_fields'
+require 'logstasher/rails_ext/rack/debug_exceptions'
 require 'request_store'
 require 'active_support/core_ext/module/attribute_accessors'
 require 'active_support/core_ext/string/inflections'
 require 'active_support/ordered_options'
 
 module LogStasher
+  class NullLogger < Logger
+    def initialize(*args)
+    end
+
+    def add(*args, &block)
+    end
+  end
+
   extend self
   STORE_KEY = :logstasher_data
   REQUEST_CONTEXT_KEY = :logstasher_request_context
@@ -98,12 +107,12 @@ def setup_before(config)
     LogStasher::ActiveJob::LogSubscriber.attach_to :active_job if has_active_job? && config.job_enabled
   end
 
-  def setup(config)
+  def setup(config, app)
     # Path instrumentation class to insert our hook
     if (! config.controller_monkey_patch && config.controller_monkey_patch != false) || config.controller_monkey_patch == true
       require 'logstasher/rails_ext/action_controller/metal/instrumentation'
     end
-    self.suppress_app_logs(config)
+    self.suppress_app_logs(config, app)
     self.logger_path = config.logger_path || "#{Rails.root}/log/logstash_#{Rails.env}.log"
     self.logger = config.logger || new_logger(self.logger_path)
     self.logger.level = config.log_level || Logger::WARN
@@ -134,9 +143,10 @@ def has_active_job?
     Rails::VERSION::MAJOR > 4 || (Rails::VERSION::MAJOR == 4 && Rails::VERSION::MINOR >= 2)
   end
 
-  def suppress_app_logs(config)
+  def suppress_app_logs(config, app)
     if configured_to_suppress_app_logs?(config)
       require 'logstasher/rails_ext/rack/logger'
+      app.env_config["action_dispatch.logger"] = NullLogger.new()
       LogStasher.remove_existing_log_subscriptions
     end
   end
@@ -146,6 +156,12 @@ def configured_to_suppress_app_logs?(config)
     !!(config.suppress_app_log.nil? ? config.supress_app_log : config.suppress_app_log)
   end
 
+  def modify_middleware(app)
+    if enabled
+      app.middleware.insert_after ::ActionDispatch::DebugExceptions, ::LogStasher::ActionDispatch::DebugExceptions, app
+    end
+  end
+
   # Log an arbitrary message.
   #
   # Usually invoked by the level-based wrapper methods defined below.

lib/logstasher/active_support/log_subscriber.rb

@@ -86,7 +86,7 @@ def location(event)
       def extract_exception(payload)
         if payload[:exception]
           exception, message = payload[:exception]
-          status = ActionDispatch::ExceptionWrapper.status_code_for_exception(exception)
+          status = ::ActionDispatch::ExceptionWrapper.status_code_for_exception(exception)
           if LogStasher.backtrace
             backtrace = $!.backtrace.join("\n")
           else

lib/logstasher/rails_ext/rack/debug_exceptions.rb

@@ -0,0 +1,43 @@
+require 'action_dispatch'
+require 'active_support/all'
+
+module LogStasher
+  module ActionDispatch
+
+    class DebugExceptions < ::ActionDispatch::DebugExceptions
+      def self.build_exception_hash(wrapper)
+        exception = wrapper.exception
+        trace = wrapper.application_trace
+        trace = wrapper.framework_trace if trace.empty?
+
+        { error:
+          ({ exception: exception.class.name, message: exception.message, trace: trace}.
+           merge!( exception.respond_to?(:annotated_source_code) && { annotated_source_code: exception.annoted_source_code } || {} ))
+        }
+      end
+
+      def initialize(app, routes_app = nil)
+        @app        = app
+        @routes_app = routes_app
+      end
+
+      def call(env)
+        begin
+          status, header, body = @app.call(env)
+          if header['X-Cascade'] == 'pass'
+            raise ::ActionController::RoutingError, "No route matches [#{env['REQUEST_METHOD']}] #{env['PATH_INFO'].inspect}"
+          end
+        rescue Exception => exception
+          log_error(env, ::ActionDispatch::ExceptionWrapper.new(env, exception))
+        end
+        [status, header, body]
+      end
+
+      private
+
+      def log_error(env, wrapper)
+        LogStasher.logger << LogStasher.build_logstash_event(DebugExceptions.build_exception_hash(wrapper), ["exception"]).to_json + "\n"
+      end
+    end
+  end
+end

lib/logstasher/railtie.rb

@@ -34,10 +34,11 @@ class Railtie < Rails::Railtie
       LogStasher.setup_before(app.config.logstasher) if app.config.logstasher.enabled
     end
 
-    initializer :logstasher do
+    initializer :logstasher do |app|
       config.after_initialize do
-        LogStasher.setup(config.logstasher) if config.logstasher.enabled
+        LogStasher.setup(config.logstasher, app) if config.logstasher.enabled
       end
+      LogStasher.modify_middleware(app)
     end
   end
 

spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb

@@ -0,0 +1,46 @@
+require 'spec_helper'
+
+shared_examples 'MyApp' do
+  before do
+    class MyApp 
+      def initialize()
+      end
+      def call(*args)
+        raise Exception.new("My Exception")
+      end
+    end
+  end
+
+  let(:app) { MyApp.new }
+  let(:environment) { { 'action_dispatch.show_exceptions' => true } } 
+  let(:logger) { double }
+  subject{ described_class.new(app) }
+
+  before(:each) do
+    allow(LogStasher).to receive(:logger).and_return(logger)
+    allow(LogStasher.logger).to receive(:'<<').and_return(true)
+  end
+end
+
+describe ::LogStasher::ActionDispatch::DebugExceptions do
+  include_examples 'MyApp'
+
+  describe '#build_exception_hash' do
+    let (:wrapper) { double(exception: Exception.new("My Exception"), application_trace: [ "line5" ]) }
+    it do
+      hash = described_class.build_exception_hash(wrapper)
+
+      expect(hash).to match({:error=>{:exception=>"Exception", :message=>"My Exception", :trace=>["line5"]}})
+    end
+  end
+
+  describe 'calls LogStasher.logger with json format exception' do
+    describe '#log_error' do
+      it do
+        expect(LogStasher).to receive(:build_logstash_event)
+        expect(LogStasher.logger).to receive(:'<<').and_return(true)
+        subject.call(environment)
+      end
+    end
+  end
+end

spec/lib/logstasher_spec.rb

@@ -147,9 +147,9 @@
     after { LogStasher.source = @previous_source } # Need to restore old source for specs
     it 'defines a method in ActionController::Base' do
       expect(LogStasher).to receive(:require).with('logstasher/rails_ext/action_controller/metal/instrumentation')
-      expect(LogStasher).to receive(:suppress_app_logs).with(config.logstasher)
+      expect(LogStasher).to receive(:suppress_app_logs).with(config.logstasher, app)
       expect(logger).to receive(:level=).with('warn')
-      LogStasher.setup(config.logstasher)
+      LogStasher.setup(config.logstasher, app)
       expect(LogStasher.source).to eq (logstasher_source || 'unknown')
       expect(LogStasher).to be_enabled
       expect(LogStasher::CustomFields.custom_fields).to be_empty
@@ -190,27 +190,41 @@
   end
 
   describe '.suppress_app_logs' do
-    let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => true))}
-    let(:app){ double(:config => logstasher_config)}
-    it 'removes existing subscription if enabled' do
-      expect(LogStasher).to receive(:require).with('logstasher/rails_ext/rack/logger')
-      expect(LogStasher).to receive(:remove_existing_log_subscriptions)
-      LogStasher.suppress_app_logs(app.config.logstasher)
+    let(:app){ double(config: logstasher_config, env_config: {})}
+
+    context 'when enabled' do
+      let(:logstasher_config){ double(logstasher: double(:suppress_app_log => true))}
+      it 'removes existing subscription if enabled' do
+        expect(LogStasher).to receive(:require).with('logstasher/rails_ext/rack/logger')
+        expect(LogStasher).to receive(:remove_existing_log_subscriptions)
+        LogStasher.suppress_app_logs(app.config.logstasher, app)
+      end
+
+      it 'changes "action_dispatch.logger" to NullLogger' do
+        LogStasher.suppress_app_logs(app.config.logstasher, app)
+        expect(app.env_config).to include('action_dispatch.logger' => an_instance_of(::LogStasher::NullLogger))
+      end
     end
 
     context 'when disabled' do
       let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => false)) }
+
       it 'does not remove existing subscription' do
         expect(LogStasher).to_not receive(:remove_existing_log_subscriptions)
-        LogStasher.suppress_app_logs(app.config.logstasher)
+        LogStasher.suppress_app_logs(app.config.logstasher, app)
+      end
+
+      it 'leaves "action_dispatch.logger" as before' do
+        LogStasher.suppress_app_logs(app.config.logstasher, app)
+        expect(app.env_config).to match({})
       end
 
       describe "backward compatibility" do
         context 'with spelling "supress_app_log"' do
           let(:logstasher_config){ double(:logstasher => double(:suppress_app_log => nil, :supress_app_log => false)) }
           it 'does not remove existing subscription' do
             expect(LogStasher).to_not receive(:remove_existing_log_subscriptions)
-            LogStasher.suppress_app_logs(app.config.logstasher)
+            LogStasher.suppress_app_logs(app.config.logstasher, app)
           end
         end
       end