Log unpermitted parameters

CHANGELOG.md

@@ -1,5 +1,9 @@
 # Change Log
 
+### Unreleased
+
+* Support logging of unpermitted parameters in Rails 4+ #154
+
 ### 0.3.4
 
 * Added LTSV formatter (<https://github.com/takashi>) #138

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

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,14 +175,35 @@
 
       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
 
     it 'does not include a location by default' do
       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