diff --git a/CHANGELOG.md b/CHANGELOG.md index dc9db2c2..e1854bcd 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -1,5 +1,9 @@ # Change Log +### Unreleased + +* Support logging of unpermitted parameters in Rails 4+ #154 + ### 0.3.4 * Added LTSV formatter () #138 diff --git a/lib/lograge/log_subscriber.rb b/lib/lograge/log_subscriber.rb index 65fbda5f..87487bfb 100644 --- a/lib/lograge/log_subscriber.rb +++ b/lib/lograge/log_subscriber.rb @@ -9,13 +9,7 @@ def process_action(event) return if Lograge.ignore?(event) payload = event.payload - - data = extract_request(payload) - extract_status(data, payload) - runtimes(data, event) - location(data) - custom_options(data, event) - + data = extract_request(event, payload) data = before_format(data, payload) formatted_message = Lograge.formatter.call(data) logger.send(Lograge.log_level, formatted_message) @@ -25,13 +19,28 @@ def redirect_to(event) Thread.current[:lograge_location] = event.payload[:location] end + def unpermitted_parameters(event) + Thread.current[:lograge_unpermitted_params] ||= [] + Thread.current[:lograge_unpermitted_params].concat(event.payload[:keys]) + end + def logger Lograge.logger.presence || super end private - def extract_request(payload) + def extract_request(event, payload) + payload = event.payload + data = initial_data(payload) + data.merge!(extract_status(payload)) + data.merge!(extract_runtimes(event, payload)) + data.merge!(extract_location) + data.merge!(extract_unpermitted_params) + data.merge!(custom_options(event)) + end + + def initial_data(payload) { method: payload[:method], path: extract_path(payload), @@ -57,15 +66,14 @@ def extract_format(payload) end end - def extract_status(data, payload) + def extract_status(payload) if (status = payload[:status]) - data[:status] = status.to_i + { status: status.to_i } elsif (error = payload[:exception]) exception, message = error - data[:status] = get_error_status_code(exception) - data[:error] = "#{exception}: #{message}" + { status: get_error_status_code(exception), error: "#{exception}: #{message}" } else - data[:status] = 0 + { status: 0 } end end @@ -74,28 +82,35 @@ def get_error_status_code(exception) Rack::Utils.status_code(status) end - def custom_options(data, event) - options = Lograge.custom_options(event) - data.merge! options if options + def custom_options(event) + Lograge.custom_options(event) || {} end def before_format(data, payload) Lograge.before_format(data, payload) end - def runtimes(data, event) - payload = event.payload - data[:duration] = event.duration.to_f.round(2) - data[:view] = payload[:view_runtime].to_f.round(2) if payload.key?(:view_runtime) - data[:db] = payload[:db_runtime].to_f.round(2) if payload.key?(:db_runtime) + def extract_runtimes(event, payload) + data = { duration: event.duration.to_f.round(2) } + data[:view] = payload[:view_runtime].to_f.round(2) if payload.key?(:view_runtime) + data[:db] = payload[:db_runtime].to_f.round(2) if payload.key?(:db_runtime) + data end - def location(data) + def extract_location location = Thread.current[:lograge_location] - return unless location + return {} unless location Thread.current[:lograge_location] = nil - data[:location] = location + { location: location } + end + + def extract_unpermitted_params + unpermitted_params = Thread.current[:lograge_unpermitted_params] + return {} unless unpermitted_params + + Thread.current[:lograge_unpermitted_params] = nil + { unpermitted_params: unpermitted_params } end end end diff --git a/spec/lograge_logsubscriber_spec.rb b/spec/lograge_logsubscriber_spec.rb index 809bee54..f1d2e9ed 100644 --- a/spec/lograge_logsubscriber_spec.rb +++ b/spec/lograge_logsubscriber_spec.rb @@ -29,16 +29,6 @@ view_runtime: 0.01 ) end - let(:redirect) do - ActiveSupport::Notifications::Event.new( - 'redirect_to.action_controller', - Time.now, - Time.now, - 1, - location: 'http://example.com', - status: 302 - ) - end before { Lograge.logger = logger } @@ -69,12 +59,40 @@ end context 'when processing a redirect' do + let(:redirect_event) do + ActiveSupport::Notifications::Event.new( + 'redirect_to.action_controller', + Time.now, + Time.now, + 1, + location: 'http://example.com', + status: 302 + ) + end + it 'stores the location in a thread local variable' do - subscriber.redirect_to(redirect) + subscriber.redirect_to(redirect_event) expect(Thread.current[:lograge_location]).to eq('http://example.com') end end + context 'when processing unpermitted parameters' do + let(:unpermitted_parameters_event) do + ActiveSupport::Notifications::Event.new( + 'unpermitted_parameters.action_controller', + Time.now, + Time.now, + 1, + keys: %w(foo bar) + ) + end + + it 'stores the parameters in a thread local variable' do + subscriber.unpermitted_parameters(unpermitted_parameters_event) + expect(Thread.current[:lograge_unpermitted_params]).to eq(%w(foo bar)) + end + end + context 'when processing an action with lograge output' do before do Lograge.formatter = Lograge::Formatters::KeyValue.new @@ -157,7 +175,7 @@ it 'removes the thread local variable' do subscriber.process_action(event) - expect(Thread.current[:lograge_location]).to be_falsey + expect(Thread.current[:lograge_location]).to be_nil end end @@ -165,6 +183,27 @@ subscriber.process_action(event) expect(log_output.string).to_not include('location=') end + + context 'with unpermitted_parameters' do + before do + Thread.current[:lograge_unpermitted_params] = %w(florb blarf) + end + + it 'adds the unpermitted_params to the log line' do + subscriber.process_action(event) + expect(log_output.string).to include('unpermitted_params=["florb", "blarf"]') + end + + it 'removes the thread local variable' do + subscriber.process_action(event) + expect(Thread.current[:lograge_unpermitted_params]).to be_nil + end + end + + it 'does not include unpermitted_params by default' do + subscriber.process_action(event) + expect(log_output.string).to_not include('unpermitted_params=') + end end context 'with custom_options configured for lograge output' do