diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index e26c45aa..38120f9c 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -15,6 +15,7 @@ defn demodulize docspring dotenv +duplicable Dotenv ESRCH Fanout @@ -47,6 +48,7 @@ nonblock nonblocking optparse parseable +passw pentester pentesters popen diff --git a/README.md b/README.md index bcc34c03..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 merged into LogStruct's filters and then cleared (to avoid double filtering). Configure 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 c7ed69f5..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,40 +91,26 @@ 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]) - leftovers = T.let([], T::Array[T.untyped]) - - rails_filter_params.each do |entry| - matcher = build_filter_matcher(entry) - - if matcher - matchers << matcher - next - end - - normalized_symbol = normalize_filter_symbol(entry) - if normalized_symbol - symbol_filters << normalized_symbol - else - leftovers << entry - end + 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 - 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 - replace_filter_parameters(rails_filter_params, leftovers) + 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 private @@ -183,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 - 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) + # 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 - - nil + ConfigStruct::FilterMatcher.new(callable: callable, label: label, matches_logstruct_fields: matches_logstruct_fields) end sig { params(filter: T.untyped).returns(T::Boolean) } @@ -218,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) @@ -251,12 +241,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/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 ba909f05..d37572db 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" @@ -49,31 +50,32 @@ def scrub_string(string) StringScrubber.scrub(string) end - 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 + MAX_RECURSION_DEPTH = 20 + + # 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, 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 || ancestors.key?(arg) case arg - when Hash - result = {} - - # 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)} + when Hash, Array + ancestors[arg] = true + begin + if arg.is_a?(Hash) + process_hash(arg, recursion_depth: recursion_depth, ancestors: ancestors) else - # Process the value normally - process_values(value, recursion_depth: recursion_depth + 1) + 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 @@ -98,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 @@ -110,7 +115,71 @@ 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 + + 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 + ancestors[value] = true + result = value.each_with_object({}) do |(key, nested_value), symbolized| + symbol_key = key.respond_to?(:to_sym) ? key.to_sym : key + symbolized[symbol_key] = symbolize_keys(nested_value, recursion_depth: recursion_depth + 1, ancestors: ancestors) + end + ancestors.delete(value) + result + when Array + ancestors[value] = true + result = value.map { |item| symbolize_keys(item, recursion_depth: recursion_depth + 1, ancestors: ancestors) } + ancestors.delete(value) + result + 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]) } @@ -122,11 +191,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 @@ -205,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/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/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/lib/log_struct/param_filters.rb b/lib/log_struct/param_filters.rb index 81bec032..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" @@ -13,9 +14,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 +25,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) @@ -87,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 @@ -97,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/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/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 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..8fb2eb9e 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -105,97 +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) - - # 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) + with_rails_filter_parameters(filter_params) do + LogStruct.merge_rails_filter_parameters! + 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) + %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 - # Add a clear method to the filter_parameters array - filter_params.define_singleton_method(:clear) do - clear_called = true - filter_params.replace([]) + 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" - # Verify Rails filter parameters were cleared - assert_empty filter_params - assert clear_called, "filter_parameters.clear should have been called" + 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"}}) - filter_params.define_singleton_method(:clear) do - T.unsafe(self).replace([]) - 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 - 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 + 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 - Rails.stub(:application, mock_app) do + def test_rails_filter_blocks_with_three_arguments + pin_filter = ->(key, _value, _params) { key == "pin" } + + 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" - 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 @@ -421,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/log_struct/formatter_test.rb b/test/log_struct/formatter_test.rb index 7f307c28..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) @@ -231,6 +231,131 @@ 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_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(*) + 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"}) + + assert_equal "[FILTERED]", result[:password] + end + def test_generate_json data = {key: "value"} 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 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