port deep parameter logging from Badiapp/grape_logging (#37)

* port deep parameter logging from Badiapp/grape_logging; add some specs

* fix initializer for ParameterFilter

* PR feedback

.gitignore

@@ -7,3 +7,4 @@
 /pkg/
 /spec/reports/
 /tmp/
+.rspec

grape_logging.gemspec

@@ -23,4 +23,6 @@ Gem::Specification.new do |spec|
 
   spec.add_development_dependency 'bundler', '~> 1.8'
   spec.add_development_dependency 'rake', '~> 10.0'
+  spec.add_development_dependency 'rspec', '~> 3.5'
+  spec.add_development_dependency 'pry-byebug', '~> 3.4.2'
 end

lib/grape_logging.rb

@@ -12,3 +12,4 @@ require 'grape_logging/reporters/active_support_reporter'
 require 'grape_logging/reporters/logger_reporter'
 require 'grape_logging/timings'
 require 'grape_logging/middleware/request_logger'
+require 'grape_logging/util/parameter_filter'

lib/grape_logging/loggers/filter_parameters.rb

@@ -1,23 +1,35 @@
 module GrapeLogging
   module Loggers
     class FilterParameters < GrapeLogging::Loggers::Base
-      def initialize(filter_parameters = nil, replacement = '[FILTERED]')
+      AD_PARAMS = 'action_dispatch.request.parameters'.freeze
+
+      def initialize(filter_parameters = nil, replacement = nil, exceptions = %w(controller action format))
         @filter_parameters = filter_parameters || (defined?(Rails.application) ? Rails.application.config.filter_parameters : [])
-        @replacement = replacement
+        @replacement = replacement || '[FILTERED]'
+        @exceptions = exceptions
       end
 
       def parameters(request, _)
-        { params: replace_parameters(request.params.clone) }
+        { params: safe_parameters(request) }
       end
 
       private
-      def replace_parameters(parameters)
-        @filter_parameters.each do |parameter_name|
-          if parameters.key?(parameter_name.to_s)
-            parameters[parameter_name.to_s] = @replacement
-          end
+
+      def parameter_filter
+        @parameter_filter ||= ParameterFilter.new(@replacement, @filter_parameters)
+      end
+
+      def safe_parameters(request)
+        # Now this logger can work also over Rails requests
+        if request.params.empty?
+          clean_parameters(request.env[AD_PARAMS] || {})
+        else
+          clean_parameters(request.params)
         end
-        parameters
+      end
+
+      def clean_parameters(parameters)
+        parameter_filter.filter(parameters).reject{ |key, _value| @exceptions.include?(key) }
       end
     end
   end

lib/grape_logging/util/parameter_filter.rb

@@ -0,0 +1,90 @@
+if defined?(Rails.application)
+  class ParameterFilter < ActionDispatch::Http::ParameterFilter
+    def initialize(_replacement, filter_parameters)
+      super(filter_parameters)
+    end
+  end
+else
+  #
+  # lifted from https://github.com/rails/rails/blob/master/actionpack/lib/action_dispatch/http/parameter_filter.rb
+  # we could depend on Rails specifically, but that would us way to hefty!
+  #
+  class ParameterFilter
+    def initialize(replacement, filters = [])
+      @replacement = replacement
+      @filters = filters
+    end
+
+    def filter(params)
+      compiled_filter.call(params)
+    end
+
+    private
+
+    def compiled_filter
+      @compiled_filter ||= CompiledFilter.compile(@replacement, @filters)
+    end
+
+    class CompiledFilter # :nodoc:
+      def self.compile(replacement, filters)
+        return lambda { |params| params.dup } if filters.empty?
+
+        strings, regexps, blocks = [], [], []
+
+        filters.each do |item|
+          case item
+          when Proc
+            blocks << item
+          when Regexp
+            regexps << item
+          else
+            strings << Regexp.escape(item.to_s)
+          end
+        end
+
+        deep_regexps, regexps = regexps.partition { |r| r.to_s.include?("\\.".freeze) }
+        deep_strings, strings = strings.partition { |s| s.include?("\\.".freeze) }
+
+        regexps << Regexp.new(strings.join('|'.freeze), true) unless strings.empty?
+        deep_regexps << Regexp.new(deep_strings.join('|'.freeze), true) unless deep_strings.empty?
+
+        new replacement, regexps, deep_regexps, blocks
+      end
+
+      attr_reader :regexps, :deep_regexps, :blocks
+
+      def initialize(replacement, regexps, deep_regexps, blocks)
+        @replacement = replacement
+        @regexps = regexps
+        @deep_regexps = deep_regexps.any? ? deep_regexps : nil
+        @blocks  = blocks
+      end
+
+      def call(original_params, parents = [])
+        filtered_params = {}
+
+        original_params.each do |key, value|
+          parents.push(key) if deep_regexps
+          if regexps.any? { |r| key =~ r }
+            value = @replacement
+          elsif deep_regexps && (joined = parents.join('.')) && deep_regexps.any? { |r| joined =~ r }
+            value = @replacement
+          elsif value.is_a?(Hash)
+            value = call(value, parents)
+          elsif value.is_a?(Array)
+            value = value.map { |v| v.is_a?(Hash) ? call(v, parents) : v }
+          elsif blocks.any?
+            key = key.dup if key.duplicable?
+            value = value.dup if value.duplicable?
+            blocks.each { |b| b.call(key, value) }
+          end
+          parents.pop if deep_regexps
+
+          filtered_params[key] = value
+        end
+
+        filtered_params
+      end
+    end
+  end
+end

spec/lib/grape_logging/loggers/client_env_spec.rb

@@ -0,0 +1,49 @@
+require 'ostruct'
+
+describe GrapeLogging::Loggers::ClientEnv do
+  let(:ip) { '10.0.0.1' }
+  let(:user_agent) { 'user agent' }
+  let(:forwarded_for) { "forwarded for" }
+  let(:remote_addr) { "remote address" }
+
+  context 'forwarded for' do
+    let(:mock_request) do
+      OpenStruct.new(env: {
+        "HTTP_X_FORWARDED_FOR" => forwarded_for
+      })
+    end
+
+    it 'sets the ip key' do
+      expect(subject.parameters(mock_request, nil)).to eq(ip: forwarded_for, ua: nil)
+    end
+
+    it 'prefers the forwarded_for over the remote_addr' do
+      mock_request.env['REMOTE_ADDR'] = remote_addr
+      expect(subject.parameters(mock_request, nil)).to eq(ip: forwarded_for, ua: nil)
+    end
+  end
+
+  context 'remote address' do
+    let(:mock_request) do
+      OpenStruct.new(env: {
+        "REMOTE_ADDR" => remote_addr
+      })
+    end
+
+    it 'sets the ip key' do
+      expect(subject.parameters(mock_request, nil)).to eq(ip: remote_addr, ua: nil)
+    end
+  end
+
+  context 'user agent' do
+    let(:mock_request) do
+      OpenStruct.new(env: {
+        "HTTP_USER_AGENT" => user_agent
+      })
+    end
+
+    it 'sets the ua key' do
+      expect(subject.parameters(mock_request, nil)).to eq(ip: nil, ua: user_agent)
+    end
+  end
+end

spec/lib/grape_logging/loggers/filter_parameters_spec.rb

@@ -0,0 +1,75 @@
+require 'ostruct'
+
+describe GrapeLogging::Loggers::FilterParameters do
+  let(:filtered_parameters) { %w[one four] }
+
+  let(:mock_request) do
+    OpenStruct.new(params: {
+      this_one: 'this one',
+      that_one: 'one',
+      two: 'two',
+      three: 'three',
+      four: 'four'
+    })
+  end
+
+  let(:mock_request_with_deep_nesting) do
+    deep_clone = lambda { Marshal.load Marshal.dump mock_request.params }
+    OpenStruct.new(
+      params: deep_clone.call.merge(
+        five: deep_clone.call.merge(
+          deep_clone.call.merge({six: {seven: 'seven', eight: 'eight', one: 'another one'}})
+        )
+      )
+    )
+  end
+
+  let(:subject) do
+    GrapeLogging::Loggers::FilterParameters.new filtered_parameters, replacement
+  end
+
+  let(:replacement) { nil }
+
+  shared_examples 'filtering' do
+    it 'filters out sensitive parameters' do
+      expect(subject.parameters(mock_request, nil)).to eq(params: {
+        this_one: subject.instance_variable_get('@replacement'),
+        that_one: subject.instance_variable_get('@replacement'),
+        two: 'two',
+        three: 'three',
+        four: subject.instance_variable_get('@replacement'),
+      })
+    end
+
+    it 'deeply filters out sensitive parameters' do
+      expect(subject.parameters(mock_request_with_deep_nesting, nil)).to eq(params: {
+        this_one: subject.instance_variable_get('@replacement'),
+        that_one: subject.instance_variable_get('@replacement'),
+        two: 'two',
+        three: 'three',
+        four: subject.instance_variable_get('@replacement'),
+        five: {
+          this_one: subject.instance_variable_get('@replacement'),
+          that_one: subject.instance_variable_get('@replacement'),
+          two: 'two',
+          three: 'three',
+          four: subject.instance_variable_get('@replacement'),
+          six: {
+            seven: 'seven',
+            eight: 'eight',
+            one: subject.instance_variable_get('@replacement'),
+          },
+        },
+      })
+    end
+  end
+
+  context 'with default replacement' do
+    it_behaves_like 'filtering'
+  end
+
+  context 'with custom replacement' do
+    let(:replacement) { 'CUSTOM_REPLACEMENT' }
+    it_behaves_like 'filtering'
+  end
+end

spec/lib/grape_logging/loggers/request_headers_spec.rb

@@ -0,0 +1,13 @@
+require 'ostruct'
+
+describe GrapeLogging::Loggers::RequestHeaders do
+  let(:mock_request) do
+    OpenStruct.new(env: {HTTP_REFERER: 'http://example.com', HTTP_ACCEPT: 'text/plain'})
+  end
+
+  it 'strips HTTP_ from the parameter' do
+    expect(subject.parameters(mock_request, nil)).to eq({
+      headers: {'Referer' => 'http://example.com', 'Accept' => 'text/plain'}
+    })
+  end
+end

spec/lib/grape_logging/loggers/response_spec.rb

@@ -0,0 +1,27 @@
+require 'ostruct'
+
+describe GrapeLogging::Loggers::Response do
+  context 'with a parseable JSON body' do
+    let(:response) do
+      OpenStruct.new(body: [%q{{"one": "two", "three": {"four": 5}}}])
+    end
+
+    it 'returns an array of parseable JSON objects' do
+      expect(subject.parameters(nil, response)).to eq({
+        response: [response.body.first.dup]
+      })
+    end
+  end
+
+  context 'with a body that is not parseable JSON' do
+    let(:response) do
+      OpenStruct.new(body: "this is a body")
+    end
+
+    it 'just returns the body' do
+      expect(subject.parameters(nil, response)).to eq({
+        response: response.body.dup
+      })
+    end
+  end
+end

spec/lib/grape_logging/middleware/request_logger_spec.rb

@@ -0,0 +1,89 @@
+require 'rack'
+
+describe GrapeLogging::Middleware::RequestLogger do
+  let(:subject) { request.send(request_method, path) }
+  let(:app) { proc{ [status, {} , ['response body']] } }
+  let(:stack) { described_class.new app, options }
+  let(:request) { Rack::MockRequest.new(stack) }
+  let(:options) { {include: [], logger: logger} }
+  let(:logger) { double('logger') }
+  let(:path) { '/' }
+  let(:request_method) { 'get' }
+  let(:status) { 200 }
+
+  it 'logs to the logger' do
+    expect(logger).to receive('info') do |arguments|
+      expect(arguments[:status]).to eq 200
+      expect(arguments[:method]).to eq 'GET'
+      expect(arguments[:params]).to be_empty
+      expect(arguments[:host]).to eq 'example.org'
+      expect(arguments).to have_key :time
+      expect(arguments[:time]).to have_key :total
+      expect(arguments[:time]).to have_key :db
+      expect(arguments[:time]).to have_key :view
+    end
+    subject
+  end
+
+  [301, 404, 500].each do |the_status|
+    context "when the respnse status is #{the_status}" do
+      let(:status) { the_status }
+      it 'should log the correct status code' do
+        expect(logger).to receive('info') do |arguments|
+          expect(arguments[:status]).to eq the_status
+        end
+        subject
+      end
+    end
+  end
+
+  context 'with a nil response' do
+    let(:app) { proc{ [500, {} , nil] } }
+    it 'should log "fail" instead of a status' do
+      expect(Rack::MockResponse).to receive(:new) { nil }
+      expect(logger).to receive('info') do |arguments|
+        expect(arguments[:status]).to eq 'fail'
+      end
+      subject
+    end
+  end
+
+  context 'additional_loggers' do
+    before do
+      options[:include] << GrapeLogging::Loggers::RequestHeaders.new
+      options[:include] << GrapeLogging::Loggers::ClientEnv.new
+      options[:include] << GrapeLogging::Loggers::Response.new
+      options[:include] << GrapeLogging::Loggers::FilterParameters.new(["replace_me"])
+    end
+
+    %w[get put post delete options head patch].each do |the_method|
+      let(:request_method) { the_method }
+      context "with HTTP method[#{the_method}]" do
+        it 'should include additional information in the log' do
+          expect(logger).to receive('info') do |arguments|
+            expect(arguments).to have_key :headers
+            expect(arguments).to have_key :ip
+            expect(arguments).to have_key :response
+          end
+          subject
+        end
+      end
+    end
+
+    it 'should filter parameters in the log' do
+      expect(logger).to receive('info') do |arguments|
+        expect(arguments[:params]).to eq(
+          "replace_me" => '[FILTERED]',
+          "replace_me_too" => '[FILTERED]',
+          "cant_touch_this" => 'should see'
+        )
+      end
+      parameters = {
+        'replace_me' => 'should not see',
+        'replace_me_too' => 'should not see',
+        'cant_touch_this' => 'should see'
+      }
+      request.post path, params: parameters
+    end
+  end
+end

spec/spec_helper.rb

@@ -0,0 +1,88 @@
+$:.unshift '.'
+require 'lib/grape_logging'
+
+RSpec.configure do |config|
+  # rspec-expectations config goes here. You can use an alternate
+  # assertion/expectation library such as wrong or the stdlib/minitest
+  # assertions if you prefer.
+  config.expect_with :rspec do |expectations|
+    # This option will default to `true` in RSpec 4. It makes the `description`
+    # and `failure_message` of custom matchers include text for helper methods
+    # defined using `chain`, e.g.:
+    #     be_bigger_than(2).and_smaller_than(4).description
+    #     # => "be bigger than 2 and smaller than 4"
+    # ...rather than:
+    #     # => "be bigger than 2"
+    expectations.include_chain_clauses_in_custom_matcher_descriptions = true
+  end
+
+  # rspec-mocks config goes here. You can use an alternate test double
+  # library (such as bogus or mocha) by changing the `mock_with` option here.
+  config.mock_with :rspec do |mocks|
+    # Prevents you from mocking or stubbing a method that does not exist on
+    # a real object. This is generally recommended, and will default to
+    # `true` in RSpec 4.
+    mocks.verify_partial_doubles = true
+  end
+
+  # This option will default to `:apply_to_host_groups` in RSpec 4 (and will
+  # have no way to turn it off -- the option exists only for backwards
+  # compatibility in RSpec 3). It causes shared context metadata to be
+  # inherited by the metadata hash of host groups and examples, rather than
+  # triggering implicit auto-inclusion in groups with matching metadata.
+  config.shared_context_metadata_behavior = :apply_to_host_groups
+
+# The settings below are suggested to provide a good initial experience
+# with RSpec, but feel free to customize to your heart's content.
+=begin
+  # This allows you to limit a spec run to individual examples or groups
+  # you care about by tagging them with `:focus` metadata. When nothing
+  # is tagged with `:focus`, all examples get run. RSpec also provides
+  # aliases for `it`, `describe`, and `context` that include `:focus`
+  # metadata: `fit`, `fdescribe` and `fcontext`, respectively.
+  config.filter_run_when_matching :focus
+
+  # Allows RSpec to persist some state between runs in order to support
+  # the `--only-failures` and `--next-failure` CLI options. We recommend
+  # you configure your source control system to ignore this file.
+  config.example_status_persistence_file_path = "spec/examples.txt"
+
+  # Limits the available syntax to the non-monkey patched syntax that is
+  # recommended. For more details, see:
+  #   - http://rspec.info/blog/2012/06/rspecs-new-expectation-syntax/
+  #   - http://www.teaisaweso.me/blog/2013/05/27/rspecs-new-message-expectation-syntax/
+  #   - http://rspec.info/blog/2014/05/notable-changes-in-rspec-3/#zero-monkey-patching-mode
+  config.disable_monkey_patching!
+
+  # This setting enables warnings. It's recommended, but in some cases may
+  # be too noisy due to issues in dependencies.
+  config.warnings = true
+
+  # Many RSpec users commonly either run the entire suite or an individual
+  # file, and it's useful to allow more verbose output when running an
+  # individual spec file.
+  if config.files_to_run.one?
+    # Use the documentation formatter for detailed output,
+    # unless a formatter has already been configured
+    # (e.g. via a command-line flag).
+    config.default_formatter = 'doc'
+  end
+
+  # Print the 10 slowest examples and example groups at the
+  # end of the spec run, to help surface which specs are running
+  # particularly slow.
+  config.profile_examples = 10
+
+  # Run specs in random order to surface order dependencies. If you find an
+  # order dependency and want to debug it, you can fix the order by providing
+  # the seed, which is printed after each run.
+  #     --seed 1234
+  config.order = :random
+
+  # Seed global randomization in this process using the `--seed` CLI option.
+  # Setting this allows you to use `--seed` to deterministically reproduce
+  # test failures related to randomization by passing the same `--seed` value
+  # as the one that triggered the failure.
+  Kernel.srand config.seed
+=end
+end