From 364c3d4adbb0443b5bab41211c5364e97f6fa23e Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:30:07 +1300 Subject: [PATCH 1/6] Keep Rails' filter_parameters and set component loggers in load hooks merge_rails_filter_parameters! copied Rails' filter_parameters into LogStruct's filters and then cleared Rails' list. Everything else that reads that list stopped filtering: request.filtered_parameters, Sentry's and other error reporters' parameter filters, ActionDispatch's request inspection and ActiveRecord's filter_attributes. Rails' list is now left in place, and values Rails has already replaced are logged as "[FILTERED]" instead of a second _filtered summary. ActiveRecord::Base.filter_attributes was also empty for a second reason: replace_rails_logger referenced ActiveRecord::Base, ActionController::Base, ActionMailer::Base, ActiveJob::Base and ActionView::Base during boot to set their loggers. Loading those classes that early runs their on_load hooks before the app's initializers, so ActiveRecord copied an empty filter_parameters into filter_attributes and inspected records showed passwords and tokens. The loggers are now set from on_load hooks, and the ActionMailer integration registers its prepends the same way. --- .cspell/project-words.txt | 1 + README.md | 2 +- lib/log_struct/concerns/configuration.rb | 15 +------ lib/log_struct/formatter.rb | 14 +++--- lib/log_struct/integrations/action_mailer.rb | 21 +++------ lib/log_struct/semantic_logger/setup.rb | 21 +++++---- .../integration/filter_parameters_test.rb | 43 +++++++++++++++++++ test/log_struct/configuration_test.rb | 17 ++------ test/log_struct/formatter_test.rb | 6 +++ 9 files changed, 79 insertions(+), 61 deletions(-) create mode 100644 rails_test_app/templates/test/integration/filter_parameters_test.rb diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index e26c45aa..59519c3e 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -47,6 +47,7 @@ nonblock nonblocking optparse parseable +passw pentester pentesters popen diff --git a/README.md b/README.md index bcc34c03..18aeea91 100644 --- a/README.md +++ b/README.md @@ -55,7 +55,7 @@ Once initialized (and enabled), the gem automatically includes its modules into - Lograge request logs include request metadata (request_id, source_ip, user_agent, referer, host, content_type, accept) and custom fields from `lograge_custom_options` - A Rack middleware is inserted to catch and log errors, including security violations (IP spoofing, CSRF, blocked hosts, etc.) - Structured logging is set up for ActiveJob, Sidekiq, Shrine, etc. -- Rails `config.filter_parameters` are merged into LogStruct's filters and then cleared (to avoid double filtering). Configure sensitive keys via `LogStruct.config.filters`. +- Rails `config.filter_parameters` are copied into LogStruct's filters, so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. - When `RAILS_LOG_TO_STDOUT` is set, we log to STDOUT only. Otherwise, we log to STDOUT by default without adding a file appender to avoid duplicate logs. ### Default behavior by process type diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index c7ed69f5..9a4293cf 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -86,7 +86,6 @@ def merge_rails_filter_parameters! symbol_filters = T.let([], T::Array[Symbol]) matchers = T.let([], T::Array[ConfigStruct::FilterMatcher]) - leftovers = T.let([], T::Array[T.untyped]) rails_filter_params.each do |entry| matcher = build_filter_matcher(entry) @@ -97,11 +96,7 @@ def merge_rails_filter_parameters! end normalized_symbol = normalize_filter_symbol(entry) - if normalized_symbol - symbol_filters << normalized_symbol - else - leftovers << entry - end + symbol_filters << normalized_symbol if normalized_symbol end if symbol_filters.any? @@ -116,8 +111,6 @@ def merge_rails_filter_parameters! config.filters.filter_matchers << matcher unless existing end end - - replace_filter_parameters(rails_filter_params, leftovers) end private @@ -251,12 +244,6 @@ def arity_for_filter(filter) filter.respond_to?(:arity) ? filter.arity : 2 end - sig { params(filter_params: T::Array[T.untyped], leftovers: T::Array[T.untyped]).void } - def replace_filter_parameters(filter_params, leftovers) - filter_params.clear - filter_params.concat(leftovers) - end - sig { params(error: StandardError, filter: T.untyped, key: String).void } def handle_filter_error(error, filter, key) context = { diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index ba909f05..d898c454 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -49,6 +49,9 @@ def scrub_string(string) StringScrubber.scrub(string) end + # The mask Rails' parameter filter puts in place of filtered values + RAILS_FILTERED_MASK = "[FILTERED]" + sig { params(arg: T.untyped, recursion_depth: Integer).returns(T.untyped) } def process_values(arg, recursion_depth: 0) # Prevent infinite recursion in case any args have circular references @@ -62,12 +65,13 @@ def process_values(arg, recursion_depth: 0) # Process each key-value pair arg.each do |key, value| # Check if this key should be filtered at any depth - result[key] = if ParamFilters.should_filter_key?(key, value) - # Filter the value - {_filtered: ParamFilters.summarize_json_attribute(key, value)} - else - # Process the value normally + result[key] = if !ParamFilters.should_filter_key?(key, value) process_values(value, recursion_depth: recursion_depth + 1) + elsif value == RAILS_FILTERED_MASK + # Rails' parameter filter has already replaced the value + value + else + {_filtered: ParamFilters.summarize_json_attribute(key, value)} end end diff --git a/lib/log_struct/integrations/action_mailer.rb b/lib/log_struct/integrations/action_mailer.rb index 59eeafa2..1a1f69e1 100644 --- a/lib/log_struct/integrations/action_mailer.rb +++ b/lib/log_struct/integrations/action_mailer.rb @@ -28,28 +28,17 @@ def self.setup(config) return nil unless config.enabled return nil unless config.integrations.enable_actionmailer - # Silence default ActionMailer logs (we use our own structured logging) - # This is required because we replace the logging using our own callbacks - if defined?(::ActionMailer::Base) - ::ActionMailer::Base.logger = ::Logger.new(File::NULL) - end - - # Register our custom observers and handlers - # Registering these at the class level means all mailers will use them + # Register our custom observers and handlers on all mailers. The hook runs right away + # if ActionMailer::Base is already loaded. ActiveSupport.on_load(:action_mailer) do + # Silence default ActionMailer logs (we use our own structured logging) + T.unsafe(self).logger = ::Logger.new(File::NULL) + prepend LogStruct::Integrations::ActionMailer::EventLogging prepend LogStruct::Integrations::ActionMailer::ErrorHandling prepend LogStruct::Integrations::ActionMailer::MetadataCollection end - # If ActionMailer::Base is already loaded, the on_load hooks won't run - # So we need to apply the modules directly - if defined?(::ActionMailer::Base) - ::ActionMailer::Base.prepend(LogStruct::Integrations::ActionMailer::EventLogging) - ::ActionMailer::Base.prepend(LogStruct::Integrations::ActionMailer::ErrorHandling) - ::ActionMailer::Base.prepend(LogStruct::Integrations::ActionMailer::MetadataCollection) - end - true end end diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index 17da83cb..d1edfeca 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -227,17 +227,16 @@ def self.replace_rails_logger(app) # unless this reference is updated along with Rails.logger. ActiveSupport::LogSubscriber.logger = logger - # Also replace various component loggers - ActiveRecord::Base.logger = logger if defined?(ActiveRecord::Base) - ActionController::Base.logger = logger if defined?(ActionController::Base) - if defined?(ActionMailer::Base) - ActionMailer::Base.logger = logger - # Ensure ActionMailer.logger is also set (it might be accessed directly) - T.unsafe(::ActionMailer).logger = logger if T.unsafe(::ActionMailer).respond_to?(:logger=) - end - ActiveJob::Base.logger = logger if defined?(ActiveJob::Base) - ActionView::Base.logger = logger if defined?(ActionView::Base) - ActionCable.server.config.logger = logger if defined?(ActionCable) + # Also replace the component loggers. Use load hooks rather than referencing the base + # classes: loading them this early would apply their on_load hooks before the app's + # initializers run, e.g. ActiveRecord would copy an empty filter_parameters into + # filter_attributes. + ActiveSupport.on_load(:active_record) { T.unsafe(self).logger = logger } + ActiveSupport.on_load(:action_controller) { T.unsafe(self).logger = logger } + ActiveSupport.on_load(:action_mailer) { T.unsafe(self).logger = logger } + ActiveSupport.on_load(:active_job) { T.unsafe(self).logger = logger } + ActiveSupport.on_load(:action_view) { T.unsafe(self).logger = logger } + ActiveSupport.on_load(:action_cable) { T.unsafe(self).logger = logger } # Store reference in app config app.config.logger = logger diff --git a/rails_test_app/templates/test/integration/filter_parameters_test.rb b/rails_test_app/templates/test/integration/filter_parameters_test.rb new file mode 100644 index 00000000..294d6308 --- /dev/null +++ b/rails_test_app/templates/test/integration/filter_parameters_test.rb @@ -0,0 +1,43 @@ +# typed: true +# frozen_string_literal: true + +require "test_helper" + +class FilterParametersTest < ActionDispatch::IntegrationTest + def setup + @log_output = StringIO.new + ::SemanticLogger.clear_appenders! + ::SemanticLogger.add_appender(io: @log_output, formatter: LogStruct::SemanticLogger::Formatter.new, async: false) + end + + def test_rails_keeps_its_filter_parameters + filter = ActiveSupport::ParameterFilter.new(Rails.application.config.filter_parameters) + + assert_equal "[FILTERED]", filter.filter("password" => "hunter2")["password"] + end + + def test_active_record_filter_attributes_still_filter + assert_includes ActiveRecord::Base.filter_attributes, :passw + end + + def test_request_filtered_parameters_still_filter + get "/logging/basic", params: {password: "hunter2", name: "visible"} + + assert_response :success + assert_equal "[FILTERED]", request.filtered_parameters["password"] + assert_equal "visible", request.filtered_parameters["name"] + end + + def test_request_log_shows_rails_filtered_values_as_filtered + get "/logging/basic", params: {password: "hunter2"} + + ::SemanticLogger.flush + @log_output.rewind + output = @log_output.read.to_s + request_line = output.lines.find { |line| line.include?('"evt":"request"') } + + assert request_line, "Expected a request log line. Output:\n#{output}" + assert_not_includes output, "hunter2" + assert_equal "[FILTERED]", JSON.parse(request_line).dig("params", "password") + end +end diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index 0c987116..78ade4fe 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -116,7 +116,6 @@ def test_merge_rails_filter_parameters # Set up mock filter parameters with a mix of symbols and strings filter_params = [:credit_card, "ssn", :password, "existing_key"] - clear_called = T.let(false, T::Boolean) # Define necessary methods on our mock mock_config.define_singleton_method(:filter_parameters) { filter_params } @@ -124,12 +123,6 @@ def test_merge_rails_filter_parameters method_name.to_sym == :filter_parameters || super(method_name) end - # Add a clear method to the filter_parameters array - filter_params.define_singleton_method(:clear) do - clear_called = true - filter_params.replace([]) - end - # Set up mock Rails.application mock_app = T.unsafe(Object.new) mock_app.define_singleton_method(:config) { mock_config } @@ -153,9 +146,8 @@ def test_merge_rails_filter_parameters assert_equal 1, LogStruct.config.filters.filter_keys.count(:existing_key) assert_equal 5, LogStruct.config.filters.filter_keys.size - # Verify Rails filter parameters were cleared - assert_empty filter_params - assert clear_called, "filter_parameters.clear should have been called" + # Rails keeps its own list for filtered_parameters, filter_attributes, etc. + assert_equal [:credit_card, "ssn", :password, "existing_key"], filter_params end # Restore original filter keys @@ -169,10 +161,6 @@ def test_merge_rails_filter_parameters_preserves_regex_filters regex_filter = /\Aapi_/i filter_params = [regex_filter] - filter_params.define_singleton_method(:clear) do - T.unsafe(self).replace([]) - end - mock_config = T.unsafe(Object.new) mock_config.define_singleton_method(:filter_parameters) { filter_params } mock_config.define_singleton_method(:respond_to?) do |method_name, include_private = false| @@ -193,6 +181,7 @@ def test_merge_rails_filter_parameters_preserves_regex_filters end assert ParamFilters.should_filter_key?("api_token"), "regex-based Rails filters should continue filtering keys" + assert_equal [regex_filter], filter_params ensure LogStruct.config.filters.filter_keys = T.must(original_filter_keys) LogStruct.config.filters.filter_matchers = T.must(original_matchers) diff --git a/test/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 7f307c28..8a91a62c 100644 --- a/test/log_struct/formatter_test.rb +++ b/test/log_struct/formatter_test.rb @@ -231,6 +231,12 @@ def test_process_values_handles_recursive_structures assert_equal 2, result[:hash2][:b] end + def test_keeps_values_rails_already_filtered + result = @formatter.process_values({password: "[FILTERED]", secret_answer: "blue"}) + + assert_equal "[FILTERED]", result[:password] + end + def test_generate_json data = {key: "value"} From 03e37fda28f5e5c2f67ac4f8448cf92c176faf21 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:30:26 +1300 Subject: [PATCH 2/6] Summarize values past the depth limit instead of logging them raw process_values stops recursing after 20 levels so circular references can't loop forever, but it returned the remaining value untouched. Keys below that depth skipped filtering and string scrubbing, so a password or email nested deep enough was written to the log as is. The rescue at the end of process_values had the same problem: any error while processing a value logged the original value. Both paths now return a summary of the value (its class and size) instead. Hash and T::Struct log values were also symbolized with deep_symbolize_keys, which recursed forever on a circular hash before process_values ever saw it; symbolize_keys stops at the same depth. Fixes #15 --- lib/log_struct/formatter.rb | 52 +++++++++++++++++++++++++++---- test/log_struct/formatter_test.rb | 48 ++++++++++++++++++++++++++++ 2 files changed, 94 insertions(+), 6 deletions(-) diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index d898c454..1ed0891e 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -49,14 +49,16 @@ def scrub_string(string) StringScrubber.scrub(string) end + MAX_RECURSION_DEPTH = 20 + # The mask Rails' parameter filter puts in place of filtered values RAILS_FILTERED_MASK = "[FILTERED]" sig { params(arg: T.untyped, recursion_depth: Integer).returns(T.untyped) } def process_values(arg, recursion_depth: 0) - # Prevent infinite recursion in case any args have circular references - # or are too deeply nested. Just return args. - return arg if recursion_depth > 20 + # Circular references and deeply nested values stop here. Values below this depth + # would skip filtering and scrubbing, so they're summarized instead of logged. + return summarize_unprocessed_value(arg) if recursion_depth > MAX_RECURSION_DEPTH case arg when Hash @@ -114,7 +116,45 @@ def process_values(arg, recursion_depth: 0) recursion_depth: recursion_depth } LogStruct.handle_exception(e, source: Source::Internal, context: context) - arg + summarize_unprocessed_value(arg) + end + + # Like deep_symbolize_keys, but stops at the depth where process_values stops, so that + # circular references don't recurse forever. + sig { params(value: T.untyped, recursion_depth: Integer).returns(T.untyped) } + def symbolize_keys(value, recursion_depth: 0) + return value if recursion_depth > MAX_RECURSION_DEPTH + + case value + when Hash + value.each_with_object({}) do |(key, nested_value), result| + symbol_key = key.respond_to?(:to_sym) ? key.to_sym : key + result[symbol_key] = symbolize_keys(nested_value, recursion_depth: recursion_depth + 1) + end + when Array + value.map { |item| symbolize_keys(item, recursion_depth: recursion_depth + 1) } + else + value + end + end + + # Describes a value without filtering, scrubbing or serializing it, so that values which + # couldn't be processed are never logged raw. Hashes and arrays are not serialized because + # they may contain circular references. + sig { params(arg: T.untyped).returns(T.untyped) } + def summarize_unprocessed_value(arg) + case arg + when Hash + {_filtered: {_class: arg.class.name, _keys_count: arg.size}} + when Array + {_filtered: {_class: arg.class.name, _count: arg.size}} + when String + {_filtered: {_class: arg.class.name, _bytes: arg.bytesize}} + when Numeric, Symbol, TrueClass, FalseClass, NilClass + arg + else + {_filtered: {_class: arg.class.name}} + end end sig { params(log_value: T.untyped, time: Time).returns(T::Hash[Symbol, T.untyped]) } @@ -126,11 +166,11 @@ def log_value_to_hash(log_value, time:) when T::Struct # Default T::Struct.serialize methods returns a hash with string keys, so convert them to symbols - log_value.serialize.deep_symbolize_keys + symbolize_keys(log_value.serialize) when Hash # Use hash as is and convert string keys to symbols - log_value.dup.deep_symbolize_keys + symbolize_keys(log_value) else # Create a Plain log with the message as a string and serialize it with symbol keys diff --git a/test/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 8a91a62c..6bf5325e 100644 --- a/test/log_struct/formatter_test.rb +++ b/test/log_struct/formatter_test.rb @@ -231,6 +231,54 @@ def test_process_values_handles_recursive_structures assert_equal 2, result[:hash2][:b] end + def test_filters_and_scrubs_values_nested_past_the_depth_limit + deep = {password: "hunter2", note: "a@b.com", items: [1, 2, 3]} + 22.times { deep = {n: deep} } + + log_line = @formatter.call(@severity, @time, @progname, {msg: "deep", ctx: deep}) + + assert_not_includes log_line, "hunter2" + assert_not_includes log_line, "a@b.com" + JSON.parse(log_line) + end + + def test_summarizes_each_type_past_the_depth_limit + too_deep = 21 + + assert_equal({_filtered: {_class: "Hash", _keys_count: 2}}, + @formatter.process_values({a: 1, b: 2}, recursion_depth: too_deep)) + assert_equal({_filtered: {_class: "Array", _count: 3}}, + @formatter.process_values([1, 2, 3], recursion_depth: too_deep)) + assert_equal({_filtered: {_class: "String", _bytes: 7}}, + @formatter.process_values("a@b.com", recursion_depth: too_deep)) + assert_equal 42, @formatter.process_values(42, recursion_depth: too_deep) + assert_nil @formatter.process_values(nil, recursion_depth: too_deep) + end + + def test_logs_circular_hashes_without_raising + circular = {name: "loop"} + circular[:self] = circular + + log_line = @formatter.call(@severity, @time, @progname, {msg: "circular", ctx: circular}) + + assert_equal "loop", JSON.parse(log_line).dig("ctx", "name") + end + + def test_does_not_log_raw_values_when_processing_fails + exploding_hash = Class.new(Hash) do + def each(*) + raise "boom" + end + end.new + exploding_hash[:password] = "hunter2" + + LogStruct.stub(:handle_exception, nil) do + result = @formatter.process_values(exploding_hash) + + assert_equal({_filtered: {_class: exploding_hash.class.name, _keys_count: 1}}, result) + end + end + def test_keeps_values_rails_already_filtered result = @formatter.process_values({password: "[FILTERED]", secret_answer: "blue"}) From 004cc39225a71b912265cb975063e39d2913cada Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:46:13 +1300 Subject: [PATCH 3/6] Pin json below 3 in the Rails test app json 3 rejects the quirks_mode option that ActiveSupport's JSON encoder passes to JSON.generate in every released Rails version up to 8.0.4, so a freshly generated test app raised ArgumentError on every to_json call. Rails main no longer passes it. --- rails_test_app/create_app.rb | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/rails_test_app/create_app.rb b/rails_test_app/create_app.rb index a695d554..01d3bb1f 100755 --- a/rails_test_app/create_app.rb +++ b/rails_test_app/create_app.rb @@ -321,6 +321,14 @@ def copy_template(file, target_path = nil) # e.g., %i[ mri mingw x64_mingw ] -> %i[ mri windows ] gemfile_content.gsub!(%r{%i\[\s*mri\s+mingw\s+x64_mingw\s*\]}, "%i[ mri windows ]") + # ActiveSupport's JSON encoder passes quirks_mode to JSON.generate, which json 3 rejects + # (fixed on Rails main) + if rails_version != "main" + gemfile_content += <<~GEMS + gem "json", "< 3" + GEMS + end + # Have to pin concurrent-ruby to 1.3.4 for Rails 7.0 compatibility if rails_version.start_with?("7.0") gemfile_content += <<~GEMS From 1e676b48afbfe8f5b62349aa42aa0b6d79610bcf Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 17:31:29 +1300 Subject: [PATCH 4/6] Match Rails' filter_parameters the way Rails does LogStruct turned Rails' filter_parameters entries into exact key names, so keys Rails filters by partial match (:passw filters user_password, :_key filters stripe_key) were logged in job arguments and logged Hashes. Symbols, Strings and Regexps now go through ActiveSupport::ParameterFilter, so they match the keys Rails matches. Merging again replaces the earlier list. Partial matches don't apply to the names of LogStruct's own fields at the top of a line, so Rails' default :_key doesn't filter GoodJob's cron_key. Exact names and LogStruct's own filters still do, and the fields' values are filtered as before. Rails' filter blocks may change the value they're given, as the Rails guides' example does, so they now get copies instead of the logged value. Tests restore the filters after each test, since several change them in place. --- .cspell/project-words.txt | 1 + README.md | 2 +- .../docs/filtering-sensitive-data/page.tsx | 24 +++ lib/log_struct/concerns/configuration.rb | 103 ++++++------ lib/log_struct/config_struct/filters.rb | 9 +- lib/log_struct/formatter.rb | 7 +- lib/log_struct/param_filters.rb | 9 +- test/log_struct/configuration_test.rb | 154 +++++++++++------- test/test_helper.rb | 10 ++ 9 files changed, 202 insertions(+), 117 deletions(-) diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 59519c3e..38120f9c 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -15,6 +15,7 @@ defn demodulize docspring dotenv +duplicable Dotenv ESRCH Fanout diff --git a/README.md b/README.md index 18aeea91..0260b8d8 100644 --- a/README.md +++ b/README.md @@ -55,7 +55,7 @@ Once initialized (and enabled), the gem automatically includes its modules into - Lograge request logs include request metadata (request_id, source_ip, user_agent, referer, host, content_type, accept) and custom fields from `lograge_custom_options` - A Rack middleware is inserted to catch and log errors, including security violations (IP spoofing, CSRF, blocked hosts, etc.) - Structured logging is set up for ActiveJob, Sidekiq, Shrine, etc. -- Rails `config.filter_parameters` are copied into LogStruct's filters, so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. +- LogStruct also filters the keys in Rails' `config.filter_parameters`, matched the way Rails matches them (`:passw` filters `user_password`), so the same keys are filtered in every log line. Rails' own list is left in place, so `request.filtered_parameters`, `ActiveRecord::Base.filter_attributes` and other Rails features keep filtering, and values Rails has already replaced are logged as `[FILTERED]`. Configure extra sensitive keys via `LogStruct.config.filters`. - When `RAILS_LOG_TO_STDOUT` is set, we log to STDOUT only. Otherwise, we log to STDOUT by default without adding a file appender to avoid duplicate logs. ### Default behavior by process type diff --git a/docs/app/docs/filtering-sensitive-data/page.tsx b/docs/app/docs/filtering-sensitive-data/page.tsx index 22fd8213..cfcb3b7b 100644 --- a/docs/app/docs/filtering-sensitive-data/page.tsx +++ b/docs/app/docs/filtering-sensitive-data/page.tsx @@ -89,6 +89,30 @@ export default function FilteringSensitiveDataPage() { :credit_card, :ssn, :social_security`} + + Rails filter_parameters + +

+ LogStruct also filters the keys in your app's config.filter_parameters, + and matches them the way Rails does: a Symbol or String matches any key that contains it, + ignoring case (:passw filters user_password), and a Regexp is + matched as it is. Rails matches entries with a dot ( + "credit_card.code") against the path of a nested request parameter. + LogStruct checks one key at a time, so it only filters a key that contains the whole entry. + Partial matches don't apply to the names of LogStruct's own fields at the top of a + line, so Rails' default :_key doesn't filter cron_key. + Exact names and Regexps do. Rails' list is left in place, so{' '} + request.filtered_parameters and{' '} + ActiveRecord::Base.filter_attributes keep working, and values Rails has already + replaced are logged as [FILTERED]. +

+

+ Filter blocks ({'->(key, value) { ... }'}) get copies of the key and value, as + they do in Rails. LogStruct filters a key when its block returns a truthy value or changes + the String it was given (Rails' blocks mask a value by changing it in place). A block + that takes Rails' third argument, the request's parameters, gets an empty Hash. +

+ Email Hashing for Request Tracing diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index 9a4293cf..586af7d2 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -1,6 +1,8 @@ # typed: strict # frozen_string_literal: true +require "active_support/parameter_filter" +require "active_support/core_ext/object/duplicable" require_relative "../configuration" module LogStruct @@ -13,6 +15,11 @@ module ClassMethods CONSOLE_COMMAND_ARGS = T.let(["console", "c"].freeze, T::Array[String]) EMPTY_ARGV = T.let([].freeze, T::Array[String]) CI_FALSE_VALUES = T.let(["false", "0", "no"].freeze, T::Array[String]) + RAILS_PATTERNS_LABEL = "Rails filter_parameters" + RAILS_REGEXPS_LABEL = "Rails filter_parameters (Regexps)" + RAILS_PATTERN_LABELS = T.let([RAILS_PATTERNS_LABEL, RAILS_REGEXPS_LABEL].freeze, T::Array[String]) + RAILS_FILTER_MASK = "[FILTERED]" + RAILS_FILTER_PROBE = "value" sig { params(block: T.proc.params(config: LogStruct::Configuration).void).void } def configure(&block) @@ -84,32 +91,25 @@ def merge_rails_filter_parameters! return unless rails_filter_params.is_a?(Array) return if rails_filter_params.empty? - symbol_filters = T.let([], T::Array[Symbol]) - matchers = T.let([], T::Array[ConfigStruct::FilterMatcher]) - - rails_filter_params.each do |entry| - matcher = build_filter_matcher(entry) - - if matcher - matchers << matcher - next - end - - normalized_symbol = normalize_filter_symbol(entry) - symbol_filters << normalized_symbol if normalized_symbol + blocks, patterns = rails_filter_params.partition { |entry| callable_filter?(entry) } + regexps, partial_names = patterns.partition { |entry| entry.is_a?(Regexp) } + matchers = blocks.map { |block| build_callable_filter_matcher(block) } + if partial_names.any? + matchers << build_rails_pattern_matcher(partial_names, label: RAILS_PATTERNS_LABEL, matches_logstruct_fields: false) end - - if symbol_filters.any? - config.filters.filter_keys |= symbol_filters + if regexps.any? + matchers << build_rails_pattern_matcher(regexps, label: RAILS_REGEXPS_LABEL, matches_logstruct_fields: true) end - if matchers.any? - matchers.each do |matcher| - existing = config.filters.filter_matchers.any? do |registered| - registered.label == matcher.label - end - config.filters.filter_matchers << matcher unless existing - end + # Exact names also filter LogStruct's own fields, which the partial matches skip + names = patterns.filter_map { |entry| entry.to_s.downcase.to_sym if entry.is_a?(Symbol) || entry.is_a?(String) } + config.filters.filter_keys |= names + + registered = config.filters.filter_matchers + # The latest list replaces the patterns merged before + registered.reject! { |matcher| RAILS_PATTERN_LABELS.include?(matcher.label) } + matchers.each do |matcher| + registered << matcher unless registered.any? { |existing| existing.label == matcher.label } end end @@ -176,34 +176,21 @@ def ci_build? !CI_FALSE_VALUES.include?(normalized) end - sig { params(filter: T.untyped).returns(T.nilable(Symbol)) } - def normalize_filter_symbol(filter) - return filter if filter.is_a?(Symbol) - return filter.downcase.to_sym if filter.is_a?(String) - - return nil unless filter.respond_to?(:to_sym) - - begin - sym = filter.to_sym - sym.is_a?(Symbol) ? sym : nil - rescue - nil + # Rails matches Symbols and Strings as case-insensitive substrings (:passw filters + # "user_password") and Regexps as they are. Entries with a dot match nested request + # parameters by their path in Rails. LogStruct checks one key at a time, so they only + # match a key that contains the whole path. + # + # The substring matches skip LogStruct's own fields (Rails' :_key would hide GoodJob's + # cron_key); their exact names are added to filter_keys instead. A Regexp says exactly + # what it matches, so Regexps apply to every key, LogStruct's fields included. + sig { params(patterns: T::Array[T.untyped], label: String, matches_logstruct_fields: T::Boolean).returns(ConfigStruct::FilterMatcher) } + def build_rails_pattern_matcher(patterns, label:, matches_logstruct_fields:) + parameter_filter = ::ActiveSupport::ParameterFilter.new(patterns, mask: RAILS_FILTER_MASK) + callable = Kernel.lambda do |key, _value| + parameter_filter.filter_param(key, RAILS_FILTER_PROBE) == RAILS_FILTER_MASK end - end - - sig { params(filter: T.untyped).returns(T.nilable(ConfigStruct::FilterMatcher)) } - def build_filter_matcher(filter) - case filter - when ::Regexp - callable = Kernel.lambda do |key, _value| - filter.match?(key) - end - return ConfigStruct::FilterMatcher.new(callable: callable, label: filter.inspect) - else - return build_callable_filter_matcher(filter) if callable_filter?(filter) - end - - nil + ConfigStruct::FilterMatcher.new(callable: callable, label: label, matches_logstruct_fields: matches_logstruct_fields) end sig { params(filter: T.untyped).returns(T::Boolean) } @@ -211,20 +198,30 @@ def callable_filter?(filter) filter.respond_to?(:call) end - sig { params(filter: T.untyped).returns(T.nilable(ConfigStruct::FilterMatcher)) } + # Rails gives filter blocks copies of the key and value, ignores what they return, and + # logs the value as the block left it: the Rails guides' example reverses it in place, + # and a block can replace it with "[FILTERED]". LogStruct filters a key when its block + # returns a truthy value or changes a String it's given, and never changes the logged + # value itself. Rails passes blocks with three arguments the request's parameters as + # well; LogStruct checks one key at a time, so they get an empty Hash. + sig { params(filter: T.untyped).returns(ConfigStruct::FilterMatcher) } def build_callable_filter_matcher(filter) - callable = Kernel.lambda do |key, value| + callable = Kernel.lambda do |original_key, original_value| + key = original_key.dup + value = original_value.duplicable? ? original_value.dup : original_value call_args = case arity_for_filter(filter) when 0 [] when 1 [key] + when 3 + [key, value, {}] else [key, value] end result = filter.call(*call_args) - !!result + !!result || (value.is_a?(String) && value != original_value) rescue ArgumentError begin !!filter.call(key) diff --git a/lib/log_struct/config_struct/filters.rb b/lib/log_struct/config_struct/filters.rb index 56600f47..a7852506 100644 --- a/lib/log_struct/config_struct/filters.rb +++ b/lib/log_struct/config_struct/filters.rb @@ -8,6 +8,9 @@ class FilterMatcher < T::Struct const :callable, T.proc.params(key: String, value: T.untyped).returns(T::Boolean) const :label, String + # Whether the matcher also applies to the names of LogStruct's own fields at the top of a line. + # LogStruct's matcher for Rails' partial matches doesn't: Rails' default :_key would filter cron_key. + const :matches_logstruct_fields, T::Boolean, default: true sig { params(key: String, value: T.untyped).returns(T::Boolean) } def matches?(key, value) @@ -101,9 +104,9 @@ class Filters < T::Struct Regexp ) - # Additional filter matchers built from Rails filter_parameters entries that aren't simple symbols. - # Each matcher receives the key (String) and optional value, returning true when the pair should be filtered. - # By default, includes a regex matcher for common sensitive key patterns. + # Matchers for keys that aren't listed by name in filter_keys. Each matcher receives the key (String) + # and optional value, returning true when the pair should be filtered. Includes a regex matcher for + # common sensitive key patterns, and LogStruct adds matchers for Rails' filter_parameters at boot. prop :filter_matchers, T::Array[FilterMatcher], factory: -> { diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index 1ed0891e..fd3f121d 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -7,6 +7,7 @@ require "globalid" require_relative "enums/source" require_relative "enums/event" +require_relative "enums/log_field" require_relative "string_scrubber" require_relative "log" require_relative "param_filters" @@ -54,6 +55,9 @@ def scrub_string(string) # The mask Rails' parameter filter puts in place of filtered values RAILS_FILTERED_MASK = "[FILTERED]" + # LogStruct's own fields, which some filters don't apply to at the top of a line + LOG_FIELD_KEYS = T.let(LogField.values.map(&:serialize).to_set.freeze, T::Set[T.untyped]) + sig { params(arg: T.untyped, recursion_depth: Integer).returns(T.untyped) } def process_values(arg, recursion_depth: 0) # Circular references and deeply nested values stop here. Values below this depth @@ -66,8 +70,9 @@ def process_values(arg, recursion_depth: 0) # Process each key-value pair arg.each do |key, value| + logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key) # Check if this key should be filtered at any depth - result[key] = if !ParamFilters.should_filter_key?(key, value) + result[key] = if !ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field) process_values(value, recursion_depth: recursion_depth + 1) elsif value == RAILS_FILTERED_MASK # Rails' parameter filter has already replaced the value diff --git a/lib/log_struct/param_filters.rb b/lib/log_struct/param_filters.rb index 81bec032..109e7862 100644 --- a/lib/log_struct/param_filters.rb +++ b/lib/log_struct/param_filters.rb @@ -13,9 +13,10 @@ class ParamFilters class << self extend T::Sig - # Check if a key should be filtered based on our defined sensitive keys - sig { params(key: T.untyped, value: T.untyped).returns(T::Boolean) } - def should_filter_key?(key, value = nil) + # Check if a key should be filtered based on our defined sensitive keys. + # logstruct_field: the key is one of LogStruct's own fields at the top of a line. + sig { params(key: T.untyped, value: T.untyped, logstruct_field: T::Boolean).returns(T::Boolean) } + def should_filter_key?(key, value = nil, logstruct_field: false) filters = LogStruct.config.filters normalized_key = key.to_s normalized_symbol = normalized_key.downcase.to_sym @@ -23,6 +24,8 @@ def should_filter_key?(key, value = nil) return true if filters.filter_keys.include?(normalized_symbol) filters.filter_matchers.any? do |matcher| + next false if logstruct_field && !matcher.matches_logstruct_fields + matcher.matches?(normalized_key, value) rescue => e handle_filter_matcher_error(e, matcher, normalized_key) diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index 78ade4fe..8fb2eb9e 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -105,86 +105,116 @@ def test_enabled_env_var_takes_precedence_over_environment end end - def test_merge_rails_filter_parameters - # Store original filter keys - original_filter_keys = LogStruct.config.filters.filter_keys.dup + def test_merge_rails_filter_parameters_matches_keys_the_way_rails_does + filter_params = [:passw, "Card_Number", :_key] - # Create a mock for Rails.application.config - # T.unsafe is needed to work around sorbet limitations in tests - # This is acceptable since this is just a test method - mock_config = T.unsafe(Object.new) + with_rails_filter_parameters(filter_params) do + LogStruct.merge_rails_filter_parameters! + end - # Set up mock filter parameters with a mix of symbols and strings - filter_params = [:credit_card, "ssn", :password, "existing_key"] + %w[password new_PASSWORD card_number_last4 stripe_key].each do |key| + assert ParamFilters.should_filter_key?(key), "#{key} should be filtered" + end + %w[name keyboard].each do |key| + refute ParamFilters.should_filter_key?(key), "#{key} should not be filtered" + end + # Rails keeps its own list for filtered_parameters, filter_attributes, etc. + assert_equal [:passw, "Card_Number", :_key], filter_params + end - # Define necessary methods on our mock - mock_config.define_singleton_method(:filter_parameters) { filter_params } - mock_config.define_singleton_method(:respond_to?) do |method_name| - method_name.to_sym == :filter_parameters || super(method_name) + def test_merge_rails_filter_parameters_preserves_regex_filters + regex_filter = /\Aapi_/i + filter_params = [regex_filter] + + with_rails_filter_parameters(filter_params) do + LogStruct.merge_rails_filter_parameters! end - # Set up mock Rails.application - mock_app = T.unsafe(Object.new) - mock_app.define_singleton_method(:config) { mock_config } + assert ParamFilters.should_filter_key?("api_token"), "regex-based Rails filters should continue filtering keys" + refute ParamFilters.should_filter_key?("rapid_api_value") + assert_equal [regex_filter], filter_params + end - # Set our initial filter keys - LogStruct.config.filters.filter_keys = [:existing_key, :another_key] + def test_merge_rails_filter_parameters_again_uses_the_latest_list + with_rails_filter_parameters([:first_word]) { LogStruct.merge_rails_filter_parameters! } + with_rails_filter_parameters([:second_word]) { LogStruct.merge_rails_filter_parameters! } - # Stub Rails.application - Rails.stub(:application, mock_app) do - # Run the method we're testing + assert ParamFilters.should_filter_key?("second_word_count") + refute ParamFilters.should_filter_key?("first_word_count") + end + + def test_rails_partial_matches_skip_logstruct_fields + with_rails_filter_parameters([:_key, :metadata]) do LogStruct.merge_rails_filter_parameters! + end - # Check that all Rails filter parameters were merged - assert_includes LogStruct.config.filters.filter_keys, :credit_card - assert_includes LogStruct.config.filters.filter_keys, :ssn - assert_includes LogStruct.config.filters.filter_keys, :password - assert_includes LogStruct.config.filters.filter_keys, :existing_key - assert_includes LogStruct.config.filters.filter_keys, :another_key + log_line = Formatter.new.call(::Logger::INFO, + Time.now, + nil, + {msg: "Stored", cron_key: "daily_cleanup", metadata: {size: 1}, data: {stripe_key: "sk_live_123"}}) + + result = JSON.parse(log_line) + # Rails' :_key would filter GoodJob's cron_key + assert_equal "daily_cleanup", result["cron_key"] + # Exact names still filter LogStruct's own fields + assert result["metadata"].key?("_filtered"), "metadata should be filtered: #{log_line}" + assert_not_includes log_line, "sk_live_123" + end - # Check that duplicates were removed (existing_key appears in both) - assert_equal 1, LogStruct.config.filters.filter_keys.count(:existing_key) - assert_equal 5, LogStruct.config.filters.filter_keys.size + def test_rails_filter_blocks_get_a_copy_of_the_value + reverse_secrets = ->(key, value) { value.reverse! if key.include?("answer") } + value = +"blue" - # Rails keeps its own list for filtered_parameters, filter_attributes, etc. - assert_equal [:credit_card, "ssn", :password, "existing_key"], filter_params + with_rails_filter_parameters([reverse_secrets]) do + LogStruct.merge_rails_filter_parameters! end - # Restore original filter keys - LogStruct.config.filters.filter_keys = original_filter_keys + assert ParamFilters.should_filter_key?("security_answer", value) + assert_equal "blue", value end - def test_merge_rails_filter_parameters_preserves_regex_filters - original_filter_keys = LogStruct.config.filters.filter_keys.dup - original_matchers = LogStruct.config.filters.filter_matchers.dup + def test_rails_regexps_filter_logstruct_fields_too + with_rails_filter_parameters([/\Adata\z/, :_key]) do + LogStruct.merge_rails_filter_parameters! + end - regex_filter = /\Aapi_/i - filter_params = [regex_filter] + log_line = Formatter.new.call(::Logger::INFO, Time.now, nil, {msg: "Stored", cron_key: "daily", data: {note: "regexp-secret"}}) - mock_config = T.unsafe(Object.new) - mock_config.define_singleton_method(:filter_parameters) { filter_params } - mock_config.define_singleton_method(:respond_to?) do |method_name, include_private = false| - if method_name.to_sym == :filter_parameters - true - else - super(method_name, include_private) - end + assert_not_includes log_line, "regexp-secret" + assert JSON.parse(log_line)["data"].key?("_filtered"), "data should be filtered: #{log_line}" + # The partial match still skips LogStruct's own fields + assert_equal "daily", JSON.parse(log_line)["cron_key"] + end + + def test_rails_filter_blocks_that_replace_the_value_filter_it + # Rails ignores a block's return value and logs the value as the block left it + mask_notes = ->(key, value) { + value.replace("[FILTERED]") if key == "private_note" && value.is_a?(String) + nil + } + value = +"block-secret" + + with_rails_filter_parameters([mask_notes]) do + LogStruct.merge_rails_filter_parameters! end - mock_app = T.unsafe(Object.new) - mock_app.define_singleton_method(:config) { mock_config } + assert ParamFilters.should_filter_key?("private_note", value) + refute ParamFilters.should_filter_key?("public_note", +"hello") + assert_equal "block-secret", value + log_line = Formatter.new.call(::Logger::INFO, Time.now, nil, {msg: "Saved", private_note: +"block-secret"}) - LogStruct.config.filters.filter_keys = [] + assert_not_includes log_line, "block-secret" + end + + def test_rails_filter_blocks_with_three_arguments + pin_filter = ->(key, _value, _params) { key == "pin" } - Rails.stub(:application, mock_app) do + with_rails_filter_parameters([pin_filter]) do LogStruct.merge_rails_filter_parameters! end - assert ParamFilters.should_filter_key?("api_token"), "regex-based Rails filters should continue filtering keys" - assert_equal [regex_filter], filter_params - ensure - LogStruct.config.filters.filter_keys = T.must(original_filter_keys) - LogStruct.config.filters.filter_matchers = T.must(original_matchers) + assert ParamFilters.should_filter_key?("pin", "1234") + refute ParamFilters.should_filter_key?("name", "Ada") end # Test that development server process is DISABLED by default @@ -410,5 +440,17 @@ def test_enabled_for_puma_via_argv_in_production LogStruct.server_mode = T.must(original_server_mode) ::Rails.const_set(:Server, Class.new) if had_rails_server && !defined?(::Rails::Server) end + + private + + def with_rails_filter_parameters(filter_params, &block) + mock_config = T.unsafe(Object.new) + mock_config.define_singleton_method(:filter_parameters) { filter_params } + mock_app = T.unsafe(Object.new) + mock_app.define_singleton_method(:config) { mock_config } + LogStruct.config.filters.filter_keys = [] + + Rails.stub(:application, mock_app, &block) + end end end diff --git a/test/test_helper.rb b/test/test_helper.rb index 6d714fba..4c3fc057 100644 --- a/test/test_helper.rb +++ b/test/test_helper.rb @@ -114,6 +114,16 @@ class ActiveSupport::TestCase setup do TEST_LOG_IO.truncate(0) TEST_LOG_IO.rewind + @saved_filter_keys = T.let(LogStruct.config.filters.filter_keys.dup, T.nilable(T::Array[Symbol])) + @saved_filter_matchers = T.let(LogStruct.config.filters.filter_matchers.dup, + T.nilable(T::Array[LogStruct::ConfigStruct::FilterMatcher])) + end + + # Tests change the filters in place, so later tests would see them. Runs after each test + # class's own teardown has put back the configuration it replaced. + teardown do + LogStruct.config.filters.filter_keys = T.must(@saved_filter_keys) + LogStruct.config.filters.filter_matchers = T.must(@saved_filter_matchers) end # Helper method for tests that need to capture and parse log output From ade7ebf74318dbb642fbfef1fc6916419b70106a Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 17:31:43 +1300 Subject: [PATCH 5/6] Filter objects and stop at circular references in the formatter Structs, ActionController::Parameters and other objects were written by to_json without filtering or scrubbing, so a password in logged params was logged raw. The formatter now filters what as_json returns. A Hash that referred back to itself from two keys took exponential time and wrote a huge line, because only the depth limit stopped it. The formatter now tracks the Hashes and Arrays it's inside and summarizes a value that refers back to one of them. --- lib/log_struct/formatter.rb | 88 +++++++++++++++++++------------ lib/log_struct/param_filters.rb | 25 +++++++-- test/log_struct/formatter_test.rb | 73 ++++++++++++++++++++++++- 3 files changed, 147 insertions(+), 39 deletions(-) diff --git a/lib/log_struct/formatter.rb b/lib/log_struct/formatter.rb index fd3f121d..d37572db 100644 --- a/lib/log_struct/formatter.rb +++ b/lib/log_struct/formatter.rb @@ -58,33 +58,24 @@ def scrub_string(string) # LogStruct's own fields, which some filters don't apply to at the top of a line LOG_FIELD_KEYS = T.let(LogField.values.map(&:serialize).to_set.freeze, T::Set[T.untyped]) - sig { params(arg: T.untyped, recursion_depth: Integer).returns(T.untyped) } - def process_values(arg, recursion_depth: 0) + sig { params(arg: T.untyped, recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T.untyped) } + def process_values(arg, recursion_depth: 0, ancestors: {}.compare_by_identity) # Circular references and deeply nested values stop here. Values below this depth # would skip filtering and scrubbing, so they're summarized instead of logged. - return summarize_unprocessed_value(arg) if recursion_depth > MAX_RECURSION_DEPTH + return summarize_unprocessed_value(arg) if recursion_depth > MAX_RECURSION_DEPTH || ancestors.key?(arg) case arg - when Hash - result = {} - - # Process each key-value pair - arg.each do |key, value| - logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key) - # Check if this key should be filtered at any depth - result[key] = if !ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field) - process_values(value, recursion_depth: recursion_depth + 1) - elsif value == RAILS_FILTERED_MASK - # Rails' parameter filter has already replaced the value - value + when Hash, Array + ancestors[arg] = true + begin + if arg.is_a?(Hash) + process_hash(arg, recursion_depth: recursion_depth, ancestors: ancestors) else - {_filtered: ParamFilters.summarize_json_attribute(key, value)} + process_array(arg, recursion_depth: recursion_depth, ancestors: ancestors) end + ensure + ancestors.delete(arg) end - - result - when Array - process_array(arg, recursion_depth: recursion_depth) when GlobalID::Identification begin arg.to_global_id @@ -109,9 +100,12 @@ def process_values(arg, recursion_depth: 0) scrub_string(arg) when Time arg.iso8601(3) - else - # Any other type (e.g. Symbol, Integer, Float, Boolean etc.) + when Numeric, Symbol, TrueClass, FalseClass, NilClass arg + else + # Structs, ActionController::Parameters and other objects: filter and scrub what + # to_json would write + process_values(arg.as_json, recursion_depth: recursion_depth + 1, ancestors: ancestors) end rescue => e # Report error through LogStruct's framework @@ -124,20 +118,46 @@ def process_values(arg, recursion_depth: 0) summarize_unprocessed_value(arg) end - # Like deep_symbolize_keys, but stops at the depth where process_values stops, so that - # circular references don't recurse forever. - sig { params(value: T.untyped, recursion_depth: Integer).returns(T.untyped) } - def symbolize_keys(value, recursion_depth: 0) - return value if recursion_depth > MAX_RECURSION_DEPTH + sig { params(hash: T::Hash[T.untyped, T.untyped], recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T::Hash[T.untyped, T.untyped]) } + def process_hash(hash, recursion_depth:, ancestors:) + result = {} + + hash.each do |key, value| + logstruct_field = recursion_depth == 0 && LOG_FIELD_KEYS.include?(key) + # Check if this key should be filtered at any depth + result[key] = if !ParamFilters.should_filter_key?(key, value, logstruct_field: logstruct_field) + process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) + elsif value == RAILS_FILTERED_MASK + # Rails' parameter filter has already replaced the value + value + else + {_filtered: ParamFilters.summarize_json_attribute(key, value)} + end + end + + result + end + + # Like deep_symbolize_keys, but stops at circular references and at the depth where + # process_values stops, leaving those values for process_values to summarize + sig { params(value: T.untyped, recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T.untyped) } + def symbolize_keys(value, recursion_depth: 0, ancestors: {}.compare_by_identity) + return value if recursion_depth > MAX_RECURSION_DEPTH || ancestors.key?(value) case value when Hash - value.each_with_object({}) do |(key, nested_value), result| + ancestors[value] = true + result = value.each_with_object({}) do |(key, nested_value), symbolized| symbol_key = key.respond_to?(:to_sym) ? key.to_sym : key - result[symbol_key] = symbolize_keys(nested_value, recursion_depth: recursion_depth + 1) + symbolized[symbol_key] = symbolize_keys(nested_value, recursion_depth: recursion_depth + 1, ancestors: ancestors) end + ancestors.delete(value) + result when Array - value.map { |item| symbolize_keys(item, recursion_depth: recursion_depth + 1) } + ancestors[value] = true + result = value.map { |item| symbolize_keys(item, recursion_depth: recursion_depth + 1, ancestors: ancestors) } + ancestors.delete(value) + result else value end @@ -254,18 +274,18 @@ def generate_json(data) "#{data.to_json}\n" end - sig { params(array: T::Array[T.untyped], recursion_depth: Integer).returns(T::Array[T.untyped]) } - def process_array(array, recursion_depth:) + sig { params(array: T::Array[T.untyped], recursion_depth: Integer, ancestors: T::Hash[T.untyped, T::Boolean]).returns(T::Array[T.untyped]) } + def process_array(array, recursion_depth:, ancestors:) return [] if array.empty? if looks_like_backtrace_array?(array) - array.map { |value| process_values(value, recursion_depth: recursion_depth + 1) } + array.map { |value| process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) } else processed = [] array.each_with_index do |value, index| break if index >= 10 - processed << process_values(value, recursion_depth: recursion_depth + 1) + processed << process_values(value, recursion_depth: recursion_depth + 1, ancestors: ancestors) end if array.size > 10 diff --git a/lib/log_struct/param_filters.rb b/lib/log_struct/param_filters.rb index 109e7862..9396717c 100644 --- a/lib/log_struct/param_filters.rb +++ b/lib/log_struct/param_filters.rb @@ -2,6 +2,7 @@ # frozen_string_literal: true require "digest" +require "json" require_relative "hash_utils" require_relative "config_struct/filters" require_relative "enums/source" @@ -90,7 +91,10 @@ def summarize_hash(hash) } # Only add byte size if no sensitive keys are present - summary[:_bytes] = hash.to_json.bytesize unless has_sensitive_keys + unless has_sensitive_keys + bytes = json_bytesize(hash) + summary[:_bytes] = bytes if bytes + end summary end @@ -100,11 +104,24 @@ def summarize_hash(hash) def summarize_array(array) return {_class: "Array", _empty: true} if array.empty? - { + summary = { _class: Array, - _count: array.size, - _bytes: array.to_json.bytesize + _count: array.size } + bytes = json_bytesize(array) + summary[:_bytes] = bytes if bytes + + summary + end + + # The size of a filtered Hash or Array as JSON. JSON.generate stops at its nesting limit, + # which a circular reference reaches, and writes other objects with to_s instead of walking + # their attributes. nil when the value can't be written as JSON. + sig { params(value: T.any(T::Hash[T.untyped, T.untyped], T::Array[T.untyped])).returns(T.nilable(Integer)) } + def json_bytesize(value) + ::JSON.generate(value).bytesize + rescue ::JSON::NestingError, ::JSON::GeneratorError + nil end private diff --git a/test/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 6bf5325e..b587a9f8 100644 --- a/test/log_struct/formatter_test.rb +++ b/test/log_struct/formatter_test.rb @@ -199,7 +199,7 @@ def initialize @touched_indices = [] end - def process_values(value, recursion_depth: 0) + def process_values(value, **options) if value.respond_to?(:touch!) value.touch! @touched_indices << value.index if value.respond_to?(:index) @@ -264,6 +264,77 @@ def test_logs_circular_hashes_without_raising assert_equal "loop", JSON.parse(log_line).dig("ctx", "name") end + def test_logs_hashes_with_several_back_references_once + circular = {name: "loop"} + circular[:first] = circular + circular[:second] = circular + + log_line = @formatter.call(@severity, @time, @progname, {msg: "circular", ctx: circular}) + + ctx = JSON.parse(log_line).fetch("ctx") + + assert_equal "loop", ctx["name"] + assert_equal "loop", ctx.dig("first", "name") + assert_equal({"_class" => "Hash", "_keys_count" => 3}, ctx.dig("first", "first", "_filtered")) + assert_operator log_line.bytesize, :<, 1000 + end + + def test_summarizes_circular_values_under_filtered_keys + circular_array = [] + circular_array << circular_array + circular_hash = {name: "loop"} + circular_hash[:self] = circular_hash + + log_line = @formatter.call(@severity, @time, @progname, {msg: "circular", password: circular_array, token: circular_hash}) + + result = JSON.parse(log_line) + + assert_equal({"_class" => "Array", "_count" => 1}, result.dig("password", "_filtered")) + assert_equal "Hash", result.dig("token", "_filtered", "_class") + refute result.dig("token", "_filtered").key?("_bytes") + end + + def test_filtered_summaries_have_the_json_size_of_plain_values + log_line = @formatter.call(@severity, @time, @progname, {msg: "sizes", password: ["ab", 1], token: {a: "b"}}) + + result = JSON.parse(log_line) + + assert_equal ["ab", 1].to_json.bytesize, result.dig("password", "_filtered", "_bytes") + assert_equal({a: "b"}.to_json.bytesize, result.dig("token", "_filtered", "_bytes")) + end + + def test_logs_a_value_shared_by_two_keys_in_full_each_time + shared = {id: 1} + + result = @formatter.process_values({first: shared, second: shared}) + + assert_equal({first: {id: 1}, second: {id: 1}}, result) + end + + def test_filters_structs_parameters_and_other_objects + login = Struct.new(:username, :password).new("alice", "hunter2") + require "action_controller" + params = ActionController::Parameters.new(password: "hunter2", name: "visible") + account = Class.new { + def initialize + @api_token = "hunter2" + @plan = "pro" + end + }.new + + log_line = @formatter.call(@severity, + @time, + @progname, + {msg: "update", login: login, params: params, account: account}) + + assert_not_includes log_line, "hunter2" + result = JSON.parse(log_line) + + assert_equal "alice", result.dig("login", "username") + assert_equal "visible", result.dig("params", "name") + assert_equal "pro", result.dig("account", "plan") + end + def test_does_not_log_raw_values_when_processing_fails exploding_hash = Class.new(Hash) do def each(*) From e2a5bbda51f69383293881c5ba7bc61050717161 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 17:36:03 +1300 Subject: [PATCH 6/6] Turn off verbose query logs without loading ActiveRecord::Base The SQL logging integration checked ActiveRecord::Base for verbose_query_logs=, which loaded ActiveRecord::Base during setup and never matched, because the setting is on the ActiveRecord module. --- lib/log_struct/integrations/active_record.rb | 5 ++-- .../integrations/active_record_test.rb | 25 ++++++++++++++++--- 2 files changed, 24 insertions(+), 6 deletions(-) diff --git a/lib/log_struct/integrations/active_record.rb b/lib/log_struct/integrations/active_record.rb index 2e0e03d0..a69b34b5 100644 --- a/lib/log_struct/integrations/active_record.rb +++ b/lib/log_struct/integrations/active_record.rb @@ -63,9 +63,8 @@ def self.setup(config) # Disable verbose query logs ("↳ caller") since LogStruct provides # structured context and these lines are noisy/unstructured. - if ::ActiveRecord::Base.respond_to?(:verbose_query_logs=) - T.unsafe(::ActiveRecord::Base).verbose_query_logs = false - end + # (A setting on the ActiveRecord module, so ActiveRecord::Base isn't loaded early.) + ::ActiveRecord.verbose_query_logs = false subscribe_to_sql_notifications true diff --git a/test/log_struct/integrations/active_record_test.rb b/test/log_struct/integrations/active_record_test.rb index c433b3ab..a901822b 100644 --- a/test/log_struct/integrations/active_record_test.rb +++ b/test/log_struct/integrations/active_record_test.rb @@ -31,6 +31,16 @@ class ActiveRecordTest < ActiveSupport::TestCase assert_includes ActiveRecord.singleton_class.included_modules, IntegrationInterface end + test "turns off Rails' verbose query logs" do + stub_const("::ActiveRecord::Base", Class.new) do + ::ActiveRecord.verbose_query_logs = true + + ActiveRecord.setup(LogStruct.config) + + refute ::ActiveRecord.verbose_query_logs + end + end + test "returns early when SQL logging is disabled" do LogStruct.config.integrations.enable_sql_logging = false result = ActiveRecord.setup(LogStruct.config) @@ -53,7 +63,7 @@ class ActiveRecordTest < ActiveSupport::TestCase test "subscribes to sql.active_record notifications when properly configured" do # First create the ActiveRecord module if it doesn't exist unless defined?(::ActiveRecord) - Object.const_set(:ActiveRecord, Module.new) + Object.const_set(:ActiveRecord, fake_active_record_module) end # Then set ActiveRecord::Base @@ -456,7 +466,7 @@ class ActiveRecordTest < ActiveSupport::TestCase def setup_activerecord_for_test # Create ActiveRecord::Base for this test unless defined?(::ActiveRecord) - Object.const_set(:ActiveRecord, Module.new) + Object.const_set(:ActiveRecord, fake_active_record_module) end unless defined?(::ActiveRecord::Base) ::ActiveRecord.const_set(:Base, Class.new) @@ -528,7 +538,7 @@ def stub_const(name, value) when "::ActiveRecord::Base" had_active_record = Object.const_defined?(:ActiveRecord) unless had_active_record - Object.const_set(:ActiveRecord, Module.new) + Object.const_set(:ActiveRecord, fake_active_record_module) end had_const = ::ActiveRecord.const_defined?(:Base, false) @@ -563,6 +573,15 @@ def stub_const(name, value) private + # Stands in for the ActiveRecord module, with the settings LogStruct changes + def fake_active_record_module + Module.new do + class << self + attr_accessor :verbose_query_logs + end + end + end + def assert_sql_attribute(test_cases, attribute) logged_events = [] LogStruct.stub(:info, ->(log) { logged_events << log }) do