From 9e089db5e9ad01470a3b15f153f3e1f24a88d291 Mon Sep 17 00:00:00 2001 From: Marc Grimme Date: Wed, 6 Jul 2016 18:26:52 +0200 Subject: [PATCH 1/2] Added a new middleware that adds json logs for exceptions. Plus silence the old logs if suppress_app_logs. Closes #79 --- lib/logstasher.rb | 22 +++++++-- .../active_support/log_subscriber.rb | 2 +- .../rails_ext/rack/debug_exceptions.rb | 45 ++++++++++++++++++ lib/logstasher/railtie.rb | 5 +- .../rails_ext/rack/debug_exceptions_spec.rb | 46 +++++++++++++++++++ spec/lib/logstasher_spec.rb | 34 ++++++++++---- 6 files changed, 138 insertions(+), 16 deletions(-) create mode 100644 lib/logstasher/rails_ext/rack/debug_exceptions.rb create mode 100644 spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb diff --git a/lib/logstasher.rb b/lib/logstasher.rb index 69d9e3d..2ce65f8 100644 --- a/lib/logstasher.rb +++ b/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. diff --git a/lib/logstasher/active_support/log_subscriber.rb b/lib/logstasher/active_support/log_subscriber.rb index 7eeece6..822e6f4 100644 --- a/lib/logstasher/active_support/log_subscriber.rb +++ b/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 diff --git a/lib/logstasher/rails_ext/rack/debug_exceptions.rb b/lib/logstasher/rails_ext/rack/debug_exceptions.rb new file mode 100644 index 0000000..4eaa7b4 --- /dev/null +++ b/lib/logstasher/rails_ext/rack/debug_exceptions.rb @@ -0,0 +1,45 @@ +require 'action_dispatch' +require 'active_support/all' + +module LogStasher + module ActionDispatch + + class DebugExceptions < ::ActionDispatch::DebugExceptions + include ::LogStasher::ActionDispatch + + 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 + + def 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 + + private + + def log_error(env, wrapper) + LogStasher.logger << LogStasher.build_logstash_event(build_exception_hash(wrapper), ["exception"]).to_json + "\n" + end + end + end +end diff --git a/lib/logstasher/railtie.rb b/lib/logstasher/railtie.rb index 5a28733..afcae1e 100644 --- a/lib/logstasher/railtie.rb +++ b/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 diff --git a/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb b/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb new file mode 100644 index 0000000..12441f3 --- /dev/null +++ b/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 = subject.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 diff --git a/spec/lib/logstasher_spec.rb b/spec/lib/logstasher_spec.rb index 0563012..f4a176e 100644 --- a/spec/lib/logstasher_spec.rb +++ b/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,19 +190,33 @@ 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 @@ -210,7 +224,7 @@ 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 From 1cbe7f267341317b08639a68d4a838215e1e2282 Mon Sep 17 00:00:00 2001 From: Marc Grimme Date: Mon, 11 Jul 2016 10:10:52 +0200 Subject: [PATCH 2/2] Make build_exception_hash static method in LogStasher::ActionDispatch::DebugExceptions so that it can be used outside as well. --- .../rails_ext/rack/debug_exceptions.rb | 24 +++++++++---------- .../rails_ext/rack/debug_exceptions_spec.rb | 2 +- 2 files changed, 12 insertions(+), 14 deletions(-) diff --git a/lib/logstasher/rails_ext/rack/debug_exceptions.rb b/lib/logstasher/rails_ext/rack/debug_exceptions.rb index 4eaa7b4..004c228 100644 --- a/lib/logstasher/rails_ext/rack/debug_exceptions.rb +++ b/lib/logstasher/rails_ext/rack/debug_exceptions.rb @@ -5,7 +5,16 @@ module LogStasher module ActionDispatch class DebugExceptions < ::ActionDispatch::DebugExceptions - include ::LogStasher::ActionDispatch + 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 @@ -24,21 +33,10 @@ def call(env) [status, header, body] end - def 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 - private def log_error(env, wrapper) - LogStasher.logger << LogStasher.build_logstash_event(build_exception_hash(wrapper), ["exception"]).to_json + "\n" + LogStasher.logger << LogStasher.build_logstash_event(DebugExceptions.build_exception_hash(wrapper), ["exception"]).to_json + "\n" end end end diff --git a/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb b/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb index 12441f3..4dce2db 100644 --- a/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb +++ b/spec/lib/logstasher/rails_ext/rack/debug_exceptions_spec.rb @@ -28,7 +28,7 @@ def call(*args) describe '#build_exception_hash' do let (:wrapper) { double(exception: Exception.new("My Exception"), application_trace: [ "line5" ]) } it do - hash = subject.build_exception_hash(wrapper) + hash = described_class.build_exception_hash(wrapper) expect(hash).to match({:error=>{:exception=>"Exception", :message=>"My Exception", :trace=>["line5"]}}) end