From 3083db4e79c3ce947f029cb51892574791770c32 Mon Sep 17 00:00:00 2001 From: Dick Davis Date: Sat, 30 Sep 2023 01:53:53 -0500 Subject: [PATCH] Refactored to set request data in global state via middleware (#33) * Refactored to set request data in global state via middleware * Fix sanitization in event logger --- .../event_logger_rails/loggable_controller.rb | 7 +-- lib/event_logger_rails.rb | 8 ++- lib/event_logger_rails/current_request.rb | 9 ++++ lib/event_logger_rails/engine.rb | 4 ++ lib/event_logger_rails/event.rb | 7 +++ lib/event_logger_rails/event_logger.rb | 25 ++++++++-- .../middleware/capture_request_details.rb | 36 ++++++++++++++ .../loggable_controller_spec.rb | 10 +--- .../event_logger_rails/event_logger_spec.rb | 49 ++++++++++++++++++- spec/lib/event_logger_rails/event_spec.rb | 8 +++ 10 files changed, 143 insertions(+), 20 deletions(-) create mode 100644 lib/event_logger_rails/current_request.rb create mode 100644 lib/event_logger_rails/middleware/capture_request_details.rb diff --git a/app/controllers/concerns/event_logger_rails/loggable_controller.rb b/app/controllers/concerns/event_logger_rails/loggable_controller.rb index f4f85e0..976e039 100644 --- a/app/controllers/concerns/event_logger_rails/loggable_controller.rb +++ b/app/controllers/concerns/event_logger_rails/loggable_controller.rb @@ -10,12 +10,7 @@ module LoggableController def optional_data { action: action_name, - controller: controller_name.camelcase, - format: request.headers['Content-Type'], - method: request.method, - parameters: request.parameters.except(:controller, :action, :format), - path: request.path, - remote_ip: request.remote_ip + controller: controller_name.camelcase } end diff --git a/lib/event_logger_rails.rb b/lib/event_logger_rails.rb index 747d4d3..378fd88 100644 --- a/lib/event_logger_rails.rb +++ b/lib/event_logger_rails.rb @@ -2,13 +2,15 @@ require 'rails' require 'active_support/dependencies' -require 'event_logger_rails/version' require 'event_logger_rails/engine' -require 'event_logger_rails/event_logger' +require 'event_logger_rails/current_request' require 'event_logger_rails/event' +require 'event_logger_rails/event_logger' require 'event_logger_rails/exceptions/invalid_logger_level' require 'event_logger_rails/exceptions/unregistered_event' require 'event_logger_rails/extensions/loggable' +require 'event_logger_rails/middleware/capture_request_details' +require 'event_logger_rails/version' ## # Namespace for EventLoggerRails gem @@ -17,6 +19,8 @@ module EventLoggerRails autoload :Event, 'event_logger_rails/event' autoload :InvalidLoggerLevel, 'event_logger_rails/exceptions/invalid_logger_level' autoload :UnregisteredEvent, 'event_logger_rails/exceptions/unregistered_event' + autoload :CurrentRequest, 'event_logger_rails/current_request' + autoload :CaptureRequestDetails, 'event_logger_rails/middleware/capture_request_details' mattr_accessor :logdev mattr_accessor :logger_class diff --git a/lib/event_logger_rails/current_request.rb b/lib/event_logger_rails/current_request.rb new file mode 100644 index 0000000..3e39364 --- /dev/null +++ b/lib/event_logger_rails/current_request.rb @@ -0,0 +1,9 @@ +# frozen_string_literal: true + +module EventLoggerRails + ## + # Provides global state with request details + class CurrentRequest < ActiveSupport::CurrentAttributes + attribute :id, :format, :method, :parameters, :path, :remote_ip + end +end diff --git a/lib/event_logger_rails/engine.rb b/lib/event_logger_rails/engine.rb index 3b1db58..2ed01bf 100644 --- a/lib/event_logger_rails/engine.rb +++ b/lib/event_logger_rails/engine.rb @@ -14,6 +14,10 @@ class Engine < ::Rails::Engine config.event_logger_rails.logdev = "log/event_logger_rails.#{Rails.env}.log" config.event_logger_rails.logger_class = Logger + initializer 'event_logger_rails.add_middleware' do |app| + app.middleware.use EventLoggerRails::Middleware::CaptureRequestDetails + end + config.after_initialize do |app| EventLoggerRails.setup do |engine| engine.registered_events = Rails.application.config_for(:event_logger_rails) diff --git a/lib/event_logger_rails/event.rb b/lib/event_logger_rails/event.rb index d77523e..7c67a88 100644 --- a/lib/event_logger_rails/event.rb +++ b/lib/event_logger_rails/event.rb @@ -28,6 +28,13 @@ def valid? identifier.present? end + def to_h + { + event_identifier: identifier, + event_description: description + } + end + def to_s identifier&.to_s || provided_identifier.to_s end diff --git a/lib/event_logger_rails/event_logger.rb b/lib/event_logger_rails/event_logger.rb index e928ba2..07c0d8a 100644 --- a/lib/event_logger_rails/event_logger.rb +++ b/lib/event_logger_rails/event_logger.rb @@ -1,5 +1,6 @@ # frozen_string_literal: true +require_relative 'current_request' require_relative 'event' require_relative 'exceptions/invalid_logger_level' require_relative 'exceptions/unregistered_event' @@ -29,24 +30,42 @@ def log(event, level, data = {}) attr_reader :logger + def sanitizer + @sanitizer ||= ActiveSupport::ParameterFilter.new(EventLoggerRails.sensitive_fields) + end + def log_message(event, level, data) logger.send(level) do - filtered_data = ActiveSupport::ParameterFilter.new(EventLoggerRails.sensitive_fields).filter(data) - { event_identifier: event.identifier, event_description: event.description }.merge(filtered_data) + event.to_h.merge(sanitizer.filter(data)) end rescue NoMethodError raise EventLoggerRails::Exceptions::InvalidLoggerLevel.new(logger_level: level) end + # rubocop:disable Metrics/MethodLength def structured_output(level:, timestamp:, message:) { - host: Socket.gethostname, environment: Rails.env, + format: EventLoggerRails::CurrentRequest.format, + host: Socket.gethostname, + id: EventLoggerRails::CurrentRequest.id, service_name: Rails.application.class.module_parent_name, level:, + method: EventLoggerRails::CurrentRequest.method, + parameters: sanitizer.filter(EventLoggerRails::CurrentRequest.parameters), + path: EventLoggerRails::CurrentRequest.path, + remote_ip: EventLoggerRails::CurrentRequest.remote_ip, timestamp: timestamp.iso8601(3), **message } end + # rubocop:enable Metrics/MethodLength + + def event_data(event) + { + event_identifier: event.identifier, + event_description: event.description + } + end end end diff --git a/lib/event_logger_rails/middleware/capture_request_details.rb b/lib/event_logger_rails/middleware/capture_request_details.rb new file mode 100644 index 0000000..759a75f --- /dev/null +++ b/lib/event_logger_rails/middleware/capture_request_details.rb @@ -0,0 +1,36 @@ +# frozen_string_literal: true + +require_relative '../current_request' + +module EventLoggerRails + module Middleware + ## + # Middleware to capture request details and store in global state + class CaptureRequestDetails + def initialize(app) + @app = app + end + + # rubocop:disable Metrics/AbcSize, Metrics/MethodLength + def call(env) + begin + request = ActionDispatch::Request.new(env) + + EventLoggerRails::CurrentRequest.id = env['action_dispatch.request_id'] + EventLoggerRails::CurrentRequest.format = request.headers['Content-Type'] + EventLoggerRails::CurrentRequest.method = request.method + EventLoggerRails::CurrentRequest.parameters = request.parameters.except(:controller, :action, :format) + EventLoggerRails::CurrentRequest.path = request.path + EventLoggerRails::CurrentRequest.remote_ip = request.remote_ip + + status, headers, body = @app.call(env) + ensure + EventLoggerRails::CurrentRequest.reset + end + + [status, headers, body] + end + # rubocop:enable Metrics/AbcSize, Metrics/MethodLength + end + end +end diff --git a/spec/app/controllers/concerns/event_logger_rails/loggable_controller_spec.rb b/spec/app/controllers/concerns/event_logger_rails/loggable_controller_spec.rb index 2a10679..54eafcc 100644 --- a/spec/app/controllers/concerns/event_logger_rails/loggable_controller_spec.rb +++ b/spec/app/controllers/concerns/event_logger_rails/loggable_controller_spec.rb @@ -25,16 +25,10 @@ def test_three RSpec.describe EventLoggerRails::LoggableController, type: :request do let(:params) { { 'foo' => 'bar' } } - let(:headers) { { 'Content-Type' => 'text/html' } } let(:data_from_request) do { action: controller.action_name, - controller: controller.controller_name.camelcase, - format: 'text/html', - method: request.method, - parameters: request.params.except(:controller, :action, :format), - path: request.path, - remote_ip: request.remote_ip + controller: controller.controller_name.camelcase } end @@ -55,7 +49,7 @@ def test_three end it 'calls the event logger with data from the request' do - get(test_one_path, params:, headers:) + get(test_one_path, params:) expect(logger_spy) .to have_received(:log) .with( diff --git a/spec/lib/event_logger_rails/event_logger_spec.rb b/spec/lib/event_logger_rails/event_logger_spec.rb index 59a5b99..235c2e4 100644 --- a/spec/lib/event_logger_rails/event_logger_spec.rb +++ b/spec/lib/event_logger_rails/event_logger_spec.rb @@ -18,6 +18,12 @@ before do allow(IO).to receive(:open).and_return(buffer) + EventLoggerRails::CurrentRequest.id = '1234' + EventLoggerRails::CurrentRequest.format = 'text/html' + EventLoggerRails::CurrentRequest.method = 'GET' + EventLoggerRails::CurrentRequest.parameters = { foo: 'bar' } + EventLoggerRails::CurrentRequest.path = '/' + EventLoggerRails::CurrentRequest.remote_ip = '10.1.1.1' end # rubocop:disable RSpec/ExampleLength @@ -28,8 +34,14 @@ environment: 'test', event_description: event.description, event_identifier: event.identifier, + format: 'text/html', host: anything, + id: '1234', level: 'WARN', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/), **data @@ -49,8 +61,14 @@ environment: 'test', event_description: event.description, event_identifier: event.identifier, + format: 'text/html', host: anything, + id: '1234', level: 'WARN', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/), **filtered_data @@ -70,8 +88,14 @@ environment: 'test', event_description: 'Event reserved for testing.', event_identifier: 'event_logger_rails.event.testing', + format: 'text/html', host: anything, + id: '1234', level: 'WARN', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/), **data @@ -91,9 +115,14 @@ environment: 'test', event_description: 'Indicates provided event was unregistered.', event_identifier: 'event_logger_rails.event.unregistered', + format: 'text/html', host: anything, + id: '1234', level: 'ERROR', - message: 'Event provided not registered: foo.bar', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/) ) @@ -112,8 +141,14 @@ environment: 'test', event_description: event.description, event_identifier: event.identifier, + format: 'text/html', host: anything, + id: '1234', level: 'INFO', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/) ) @@ -132,9 +167,15 @@ environment: 'test', event_description: 'Indicates provided level was invalid.', event_identifier: 'event_logger_rails.logger_level.invalid', + format: 'text/html', host: anything, + id: '1234', level: 'ERROR', message: "Invalid logger level provided: 'foo'. Valid levels: :debug, :info, :warn, :error, :unknown.", + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/) ) @@ -153,8 +194,14 @@ environment: 'test', event_description: event.description, event_identifier: event.identifier, + format: 'text/html', host: anything, + id: '1234', level: 'WARN', + method: 'GET', + parameters: { foo: 'bar' }, + path: '/', + remote_ip: '10.1.1.1', service_name: 'Dummy', timestamp: match(/\A\d{4}-\d{2}-\d{2}T\d{2}:\d{2}:\d{2}(\.\d{3})?([+-]\d{2}:\d{2}|Z)?\z/) ) diff --git a/spec/lib/event_logger_rails/event_spec.rb b/spec/lib/event_logger_rails/event_spec.rb index 7bd8d01..da726f5 100644 --- a/spec/lib/event_logger_rails/event_spec.rb +++ b/spec/lib/event_logger_rails/event_spec.rb @@ -75,6 +75,14 @@ end end + describe '#to_h' do + subject(:method_call) { event.to_h } + + let(:identifier) { 'foo.bar' } + + it { is_expected.to eq({ event_identifier: event.identifier, event_description: event.description }) } + end + describe '#to_s' do subject(:method_call) { event.to_s }