From cc35a9ad5012b83e686dc768b89d624cabc79b0a Mon Sep 17 00:00:00 2001 From: jason-uh Date: Mon, 6 Mar 2017 11:30:31 -0500 Subject: [PATCH] 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 | 1 + grape_logging.gemspec | 4 +- lib/grape_logging.rb | 1 + .../loggers/filter_parameters.rb | 30 +++++-- lib/grape_logging/util/parameter_filter.rb | 90 +++++++++++++++++++ .../grape_logging/loggers/client_env_spec.rb | 49 ++++++++++ .../loggers/filter_parameters_spec.rb | 75 ++++++++++++++++ .../loggers/request_headers_spec.rb | 13 +++ .../grape_logging/loggers/response_spec.rb | 27 ++++++ .../middleware/request_logger_spec.rb | 89 ++++++++++++++++++ spec/spec_helper.rb | 88 ++++++++++++++++++ 11 files changed, 457 insertions(+), 10 deletions(-) create mode 100644 lib/grape_logging/util/parameter_filter.rb create mode 100644 spec/lib/grape_logging/loggers/client_env_spec.rb create mode 100644 spec/lib/grape_logging/loggers/filter_parameters_spec.rb create mode 100644 spec/lib/grape_logging/loggers/request_headers_spec.rb create mode 100644 spec/lib/grape_logging/loggers/response_spec.rb create mode 100644 spec/lib/grape_logging/middleware/request_logger_spec.rb create mode 100644 spec/spec_helper.rb diff --git a/.gitignore b/.gitignore index 0cb6eeb..fe95d4d 100644 --- a/.gitignore +++ b/.gitignore @@ -7,3 +7,4 @@ /pkg/ /spec/reports/ /tmp/ +.rspec diff --git a/grape_logging.gemspec b/grape_logging.gemspec index 7b9ac27..377465f 100644 --- a/grape_logging.gemspec +++ b/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' -end \ No newline at end of file + spec.add_development_dependency 'rspec', '~> 3.5' + spec.add_development_dependency 'pry-byebug', '~> 3.4.2' +end diff --git a/lib/grape_logging.rb b/lib/grape_logging.rb index 2993166..830e7ed 100644 --- a/lib/grape_logging.rb +++ b/lib/grape_logging.rb @@ -12,3 +12,4 @@ require 'grape_logging/reporters/logger_reporter' require 'grape_logging/timings' require 'grape_logging/middleware/request_logger' +require 'grape_logging/util/parameter_filter' diff --git a/lib/grape_logging/loggers/filter_parameters.rb b/lib/grape_logging/loggers/filter_parameters.rb index 83d612d..1e45482 100644 --- a/lib/grape_logging/loggers/filter_parameters.rb +++ b/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 diff --git a/lib/grape_logging/util/parameter_filter.rb b/lib/grape_logging/util/parameter_filter.rb new file mode 100644 index 0000000..23b99a5 --- /dev/null +++ b/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 diff --git a/spec/lib/grape_logging/loggers/client_env_spec.rb b/spec/lib/grape_logging/loggers/client_env_spec.rb new file mode 100644 index 0000000..bc6bc1c --- /dev/null +++ b/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 diff --git a/spec/lib/grape_logging/loggers/filter_parameters_spec.rb b/spec/lib/grape_logging/loggers/filter_parameters_spec.rb new file mode 100644 index 0000000..8eac67c --- /dev/null +++ b/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 diff --git a/spec/lib/grape_logging/loggers/request_headers_spec.rb b/spec/lib/grape_logging/loggers/request_headers_spec.rb new file mode 100644 index 0000000..888a843 --- /dev/null +++ b/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 diff --git a/spec/lib/grape_logging/loggers/response_spec.rb b/spec/lib/grape_logging/loggers/response_spec.rb new file mode 100644 index 0000000..a736903 --- /dev/null +++ b/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 diff --git a/spec/lib/grape_logging/middleware/request_logger_spec.rb b/spec/lib/grape_logging/middleware/request_logger_spec.rb new file mode 100644 index 0000000..37e3f12 --- /dev/null +++ b/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 diff --git a/spec/spec_helper.rb b/spec/spec_helper.rb new file mode 100644 index 0000000..8a74f64 --- /dev/null +++ b/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