From d12c8945e84404821df0cbc64989a461e74b28be Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:52:02 +1300 Subject: [PATCH 1/7] Stop Shrine's default log subscriber logging the events LogStruct logs Apps usually load Shrine's instrumentation plugin in their own initializer, which subscribes Shrine's default log subscriber: it writes each upload, download, open, exists, delete and metadata event to Shrine.logger as a line of text, next to LogStruct's structured line. LogStruct only removed it when the plugin was already configured, and that path listened on the wrong notification names ("shrine.upload" instead of "upload.shrine"), unsubscribed every other listener for those events and passed ActiveSupport events where Shrine's were expected. LogStruct now loads the plugin without the default subscriber, subscribes its own with Shrine.subscribe, and skips those events in Shrine's default subscriber whenever the app loads it, before or after LogStruct. It also points Shrine.logger at SemanticLogger, so other plugins' log lines and Shrine's warnings are written as JSON instead of plain text. --- lib/log_struct/integrations/shrine.rb | 76 +++++-------------- .../test/integration/shrine_logging_test.rb | 37 +++++---- sorbet/rbi/shims/shrine.rbi | 8 ++ 3 files changed, 44 insertions(+), 77 deletions(-) create mode 100644 sorbet/rbi/shims/shrine.rbi diff --git a/lib/log_struct/integrations/shrine.rb b/lib/log_struct/integrations/shrine.rb index be8b8dad..6f157197 100644 --- a/lib/log_struct/integrations/shrine.rb +++ b/lib/log_struct/integrations/shrine.rb @@ -88,71 +88,33 @@ def self.setup(config) ::SemanticLogger[::Shrine].info(log_data) end) - # Check if instrumentation plugin is already loaded - # If so, we need to replace the existing subscribers, not add duplicates - if instrumentation_already_configured? - replace_existing_subscribers(shrine_log_subscriber) - else - # First time setup - configure the instrumentation plugin - ::Shrine.plugin :instrumentation, - events: SHRINE_EVENTS, - log_subscriber: shrine_log_subscriber + # Load the instrumentation plugin without Shrine's default log subscriber, which logs + # each event as a line of text (a no-op if the app has loaded it already). Shrine + # ignores a subscriber that's already subscribed. + ::Shrine.plugin :instrumentation, log_subscriber: nil + SHRINE_EVENTS.each do |event_name| + T.unsafe(::Shrine).subscribe(event_name, &shrine_log_subscriber) end - true - end - - sig { returns(T::Boolean) } - def self.instrumentation_already_configured? - return false unless defined?(::Shrine) - - opts = T.unsafe(::Shrine).opts - return false unless opts.is_a?(Hash) + # The app may load the plugin with the default log subscriber too, before or after this + ::Shrine::Plugins::Instrumentation::LogSubscriber.singleton_class.prepend(SkipLoggedEvents) - instrumentation_opts = opts[:instrumentation] - return false unless instrumentation_opts.is_a?(Hash) + # Other plugins' log subscribers and Shrine's warnings write text to Shrine.logger + ::Shrine.logger = ::SemanticLogger[::Shrine] - subscribers = instrumentation_opts[:subscribers] - return false unless subscribers.is_a?(Hash) - - !subscribers.empty? + true end - sig { params(new_subscriber: T.untyped).void } - def self.replace_existing_subscribers(new_subscriber) - opts = T.unsafe(::Shrine).opts - instrumentation_opts = opts[:instrumentation] - subscribers = instrumentation_opts[:subscribers] + # Prepended to Shrine's default instrumentation log subscriber, so it doesn't log the + # events that LogStruct logs + module SkipLoggedEvents + extend T::Sig - # Clear all existing subscribers and add our new one - SHRINE_EVENTS.each do |event_name| - # Clear existing subscribers for this event - subscribers[event_name] = [] if subscribers[event_name] - - # Add our subscriber - subscribers[event_name] ||= [] - subscribers[event_name] << new_subscriber - - # Also re-subscribe via ActiveSupport::Notifications - # Shrine uses "shrine.#{event_name}" as the notification name - notification_name = "shrine.#{event_name}" - - # Unsubscribe existing listeners for this event - # ActiveSupport::Notifications stores subscriptions, we need to find and remove them - notifier = ::ActiveSupport::Notifications.notifier - if notifier.respond_to?(:listeners_for) - # Rails 7.0+ uses listeners_for - listeners = notifier.listeners_for(notification_name) - listeners.each do |listener| - ::ActiveSupport::Notifications.unsubscribe(listener) - end - end + sig { params(event: T.untyped).returns(T.untyped) } + def call(event) + return if SHRINE_EVENTS.include?(event.name) - # Subscribe our new subscriber - ::ActiveSupport::Notifications.subscribe(notification_name) do |*args| - event = ::ActiveSupport::Notifications::Event.new(*args) - new_subscriber.call(event) - end + super end end end diff --git a/rails_test_app/templates/test/integration/shrine_logging_test.rb b/rails_test_app/templates/test/integration/shrine_logging_test.rb index 33dbb78d..15683cc1 100644 --- a/rails_test_app/templates/test/integration/shrine_logging_test.rb +++ b/rails_test_app/templates/test/integration/shrine_logging_test.rb @@ -134,31 +134,28 @@ def test_shrine_logs_are_json_not_ruby_inspect end end - def test_shrine_default_log_format_is_suppressed - # Capture STDOUT to check for Shrine's default log format - # Shrine's default format looks like: "Upload (0ms) – {storage: :store, ...}" - original_stdout = $stdout - stdout_capture = StringIO.new - $stdout = stdout_capture + def test_shrine_default_log_subscriber_does_not_log_events + # config/initializers/shrine.rb loads the instrumentation plugin with Shrine's default + # log subscriber, which writes lines like "Upload (0ms) – {storage: :store, ...}" + shrine_log = StringIO.new + original_logger = Shrine.logger + Shrine.logger = Logger.new(shrine_log) get "/logging/shrine_upload" assert_response :success + refute_match(/(Upload|Metadata|Open|Download|Exists|Delete) \(\d+ms\) –/, shrine_log.string) + ensure + Shrine.logger = original_logger + end + + def test_shrine_logger_writes_json + Shrine.warn("test warning") ::SemanticLogger.flush - $stdout = original_stdout - stdout_capture.rewind - stdout_output = stdout_capture.read.to_s - - # Shrine's default log format should NOT appear - refute_match(/Upload \(\d+ms\) – \{/, - stdout_output, - "Shrine's default log format should not appear in stdout") - refute_match(/Metadata \(\d+ms\) – \{/, - stdout_output, - "Shrine's default metadata format should not appear in stdout") - refute_match(/Open \(\d+ms\) – \{/, - stdout_output, - "Shrine's default open format should not appear in stdout") + line = @log_output.string.lines.find { |l| l.include?("test warning") } + + assert line, "Expected the Shrine warning in the LogStruct output:\n#{@log_output.string}" + assert_equal "SHRINE WARNING: test warning", JSON.parse(line)["msg"] end end diff --git a/sorbet/rbi/shims/shrine.rbi b/sorbet/rbi/shims/shrine.rbi new file mode 100644 index 00000000..36a30ae0 --- /dev/null +++ b/sorbet/rbi/shims/shrine.rbi @@ -0,0 +1,8 @@ +# typed: true + +# Shrine loads its plugins on demand, so Tapioca doesn't generate RBIs for them +module Shrine::Plugins::Instrumentation + class LogSubscriber + def self.call(event); end + end +end From 2eae3376caddad9645acc6e4b5b5f3c14e043ec3 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:52:08 +1300 Subject: [PATCH 2/7] Detach ActiveModelSerializers' own log subscriber AMS attaches a log subscriber that writes "Rendered UserSerializer with ActiveModelSerializers::Adapter::Attributes (0.1ms)" for every render, so each render was logged twice: once as that line of text and once as LogStruct's structured ams.render line. --- .../integrations/active_model_serializers.rb | 5 ++++ .../test/integration/ams_logging_test.rb | 23 ++++++++----------- 2 files changed, 15 insertions(+), 13 deletions(-) diff --git a/lib/log_struct/integrations/active_model_serializers.rb b/lib/log_struct/integrations/active_model_serializers.rb index e19020f2..b79e858b 100644 --- a/lib/log_struct/integrations/active_model_serializers.rb +++ b/lib/log_struct/integrations/active_model_serializers.rb @@ -17,6 +17,11 @@ def self.setup(config) # Only activate if AMS appears to be present return nil unless defined?(::ActiveModelSerializers) + # AMS logs each render as a line of text too + if defined?(::ActiveModelSerializers::Logging::LogSubscriber) + ::ActiveModelSerializers::Logging::LogSubscriber.detach_from(:active_model_serializers) + end + # Subscribe to common AMS notification names; keep broad but specific pattern = /\.active_model_serializers\z/ diff --git a/rails_test_app/templates/test/integration/ams_logging_test.rb b/rails_test_app/templates/test/integration/ams_logging_test.rb index 60f049f7..3159c71a 100644 --- a/rails_test_app/templates/test/integration/ams_logging_test.rb +++ b/rails_test_app/templates/test/integration/ams_logging_test.rb @@ -59,22 +59,19 @@ def test_ams_logs_are_not_ruby_hash_inspect_format def test_ams_logs_do_not_pollute_with_default_format raise "AMS not available" unless defined?(::ActiveModelSerializers) - # Capture both SemanticLogger output and stdout - original_stdout = $stdout - stdout_capture = StringIO.new - $stdout = stdout_capture + # AMS's own log subscriber writes "Rendered UserSerializer with ... (0.1ms)" to this logger + ams_log = StringIO.new + original_logger = ActiveModelSerializers.logger + ActiveModelSerializers.logger = ActiveSupport::TaggedLogging.new(Logger.new(ams_log)) - get "/logging/basic" + get "/logging/ams" ::SemanticLogger.flush - $stdout = original_stdout - stdout_capture.rewind - stdout_output = stdout_capture.read.to_s - - # AMS default logs like "Rendered X with Y (Zms)" should NOT appear in stdout - refute_match(/Rendered\s+\S+Serializer\s+with/, - stdout_output, - "AMS default log format should not appear in stdout") + + assert_includes @log_output.string, '"msg":"ams.render"' + refute_match(/Rendered\s+\S+\s+with/, ams_log.string, "AMS default log lines should not be logged") + ensure + ActiveModelSerializers.logger = original_logger end def test_ams_logs_adapter_class_name_not_serialized_output From bbc2ce36fe445ac6214bc200da9199410d115500 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 15:52:12 +1300 Subject: [PATCH 3/7] Set up integrations after config/initializers The logstruct.setup initializer only had to run before the middleware stack was built, so it ran before the app's config/initializers. The documented place to configure LogStruct is config/initializers/ logstruct.rb, so its integration toggles were ignored, and filters that other initializers added to filter_parameters (such as Rails' default filter_parameter_logging.rb) were never merged into LogStruct's filters. It now runs after :load_config_initializers. `config.enabled` and `config.enabled_environments` set in an initializer were ignored too, because LogStruct decides whether it's enabled when it's required, and the logger is replaced as soon as Rails creates it. The logger is still replaced early, so boot-time logs and code that keeps a reference to Rails.logger use it, but setup now replaces it late if an initializer enabled LogStruct, and puts the original loggers back if an initializer disabled it. As documented, LOGSTRUCT_ENABLED takes precedence, then `enabled`, then `enabled_environments`. --- lib/log_struct/concerns/configuration.rb | 31 +++++++++- lib/log_struct/integrations.rb | 4 +- lib/log_struct/railtie.rb | 26 +++++---- lib/log_struct/semantic_logger/setup.rb | 53 +++++++++++++++-- .../config/initializers/logstruct.rb | 8 +++ .../integration/boot_logs_integration_test.rb | 58 +++++++++++++++++++ .../integration/filter_parameters_test.rb | 13 +++++ test/log_struct/configuration_test.rb | 43 ++++++++++++++ 8 files changed, 215 insertions(+), 21 deletions(-) diff --git a/lib/log_struct/concerns/configuration.rb b/lib/log_struct/concerns/configuration.rb index 586af7d2..7e611b8d 100644 --- a/lib/log_struct/concerns/configuration.rb +++ b/lib/log_struct/concerns/configuration.rb @@ -61,15 +61,32 @@ def set_enabled_from_rails_env! # 3. Otherwise, leave as config.enabled (defaults to true) # Then check if LOGSTRUCT_ENABLED env var is set - config.enabled = if ENV["LOGSTRUCT_ENABLED"] - %w[true t yes y 1].include?(ENV["LOGSTRUCT_ENABLED"]&.strip&.downcase) - else + env_var_enabled = enabled_from_env_var + config.enabled = if env_var_enabled.nil? is_console = console_process? is_server = server_process? ci_build? in_enabled_env = config.enabled_environments.include?(::Rails.env.to_sym) in_enabled_env && !is_console && (is_server || ::Rails.env.test?) + else + env_var_enabled + end + + # apply_initializer_settings! compares the settings with these + @enabled_from_rails_env = T.let(config.enabled, T.nilable(T::Boolean)) + @enabled_environments_from_rails_env = T.let(config.enabled_environments.dup, T.nilable(T::Array[Symbol])) + end + + # After config/initializers run: LOGSTRUCT_ENABLED takes precedence, then `config.enabled` + # if an initializer changed it, then `config.enabled_environments` if an initializer changed that + sig { void } + def apply_initializer_settings! + env_var_enabled = enabled_from_env_var + if !env_var_enabled.nil? + config.enabled = env_var_enabled + elsif config.enabled == @enabled_from_rails_env && config.enabled_environments != @enabled_environments_from_rails_env + set_enabled_from_rails_env! end end @@ -115,6 +132,14 @@ def merge_rails_filter_parameters! private + sig { returns(T.nilable(T::Boolean)) } + def enabled_from_env_var + value = ENV["LOGSTRUCT_ENABLED"] + return nil if value.nil? + + %w[true t yes y 1].include?(value.strip.downcase) + end + sig { returns(T::Boolean) } def console_process? return true if defined?(::Rails::Console) diff --git a/lib/log_struct/integrations.rb b/lib/log_struct/integrations.rb index 934e5c62..96b41875 100644 --- a/lib/log_struct/integrations.rb +++ b/lib/log_struct/integrations.rb @@ -33,8 +33,8 @@ def self.setup_initializers(railtie) LogStruct::Integrations::Dotenv.intercept_logger_setter! end - # Decide which set of boot logs to emit after user initializers - railtie.initializer "logstruct.resolve_boot_logs", after: :load_config_initializers do + # Decide which set of boot logs to emit once `enabled` is final + railtie.initializer "logstruct.resolve_boot_logs", after: "logstruct.setup" do LogStruct::Integrations::Dotenv.resolve_boot_logs! end end diff --git a/lib/log_struct/railtie.rb b/lib/log_struct/railtie.rb index 95697650..d783cdfb 100644 --- a/lib/log_struct/railtie.rb +++ b/lib/log_struct/railtie.rb @@ -10,7 +10,8 @@ module LogStruct # Railtie to integrate with Rails class Railtie < ::Rails::Railtie - # Configure early, right after logger initialization + # Replace the logger as soon as Rails creates it, so boot-time logs and anything that keeps + # a reference to Rails.logger use LogStruct's logger initializer "logstruct.configure_logger", after: :initialize_logger do |app| next unless LogStruct.enabled? @@ -18,23 +19,28 @@ class Railtie < ::Rails::Railtie LogStruct::SemanticLogger::Setup.configure_semantic_logger(app) end - # Setup all integrations after logger setup is complete - initializer "logstruct.setup", before: :build_middleware_stack do |app| + # Set up integrations after config/initializers, so that the settings in + # config/initializers/logstruct.rb and filter_parameters added by other initializers apply + initializer "logstruct.setup", after: :load_config_initializers, before: :build_middleware_stack do |app| + # An initializer may have changed `enabled` or `enabled_environments` after the logger was + # (or wasn't) replaced + LogStruct.apply_initializer_settings! + if LogStruct.enabled? + LogStruct::SemanticLogger::Setup.configure_semantic_logger(app) unless LogStruct::SemanticLogger::Setup.configured? + elsif LogStruct::SemanticLogger::Setup.configured? + LogStruct::SemanticLogger::Setup.restore_rails_logger(app) + end + next unless LogStruct.enabled? # Merge Rails filter parameters into our filters LogStruct.merge_rails_filter_parameters! - # Set up non-middleware integrations first Integrations.setup_integrations(stage: :non_middleware) - - # Note: Host allowances are managed by the test app itself. end - # Setup middleware integrations during Rails configuration (before middleware stack is built) - # Must be done in the Railtie class body, not in an initializer - initializer "logstruct.configure_middleware", before: :build_middleware_stack do |app| - # This runs before middleware stack is frozen, so we can configure it + # Add middleware before the middleware stack is built + initializer "logstruct.configure_middleware", after: "logstruct.setup", before: :build_middleware_stack do |app| next unless LogStruct.enabled? Integrations.setup_integrations(stage: :middleware) diff --git a/lib/log_struct/semantic_logger/setup.rb b/lib/log_struct/semantic_logger/setup.rb index d1edfeca..bb3164dc 100644 --- a/lib/log_struct/semantic_logger/setup.rb +++ b/lib/log_struct/semantic_logger/setup.rb @@ -62,6 +62,23 @@ module SemanticLogger module Setup extend T::Sig + # Load hooks for the framework components whose loggers LogStruct replaces + COMPONENT_LOAD_HOOKS = T.let( + %i[active_record action_controller action_mailer active_job action_view action_cable].freeze, + T::Array[Symbol] + ) + + # The logger LogStruct installed, and the loggers it replaced + @logger = T.let(nil, T.nilable(LogStruct::SemanticLogger::Logger)) + @original_rails_logger = T.let(nil, T.untyped) + @original_log_subscriber_logger = T.let(nil, T.untyped) + @original_app_logger = T.let(nil, T.untyped) + + sig { returns(T::Boolean) } + def self.configured? + !@logger.nil? + end + # Configures SemanticLogger as the primary logging engine for the Rails application # # This method replaces Rails' default logger with SemanticLogger, providing: @@ -217,6 +234,10 @@ def self.determine_filter def self.replace_rails_logger(app) # Create new SemanticLogger instance logger = LogStruct::SemanticLogger::Logger.new("Rails") + @logger = logger + @original_rails_logger = Rails.logger + @original_log_subscriber_logger = ActiveSupport::LogSubscriber.logger + @original_app_logger = app.config.logger # Replace Rails.logger Rails.logger = logger @@ -231,16 +252,36 @@ def self.replace_rails_logger(app) # 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 } + COMPONENT_LOAD_HOOKS.each do |hook| + ActiveSupport.on_load(hook) { T.unsafe(self).logger = logger } + end # Store reference in app config app.config.logger = logger end + + # Puts back the loggers that replace_rails_logger replaced. Used when an initializer + # disables LogStruct after the logger was replaced at boot. + sig { params(app: T.untyped).void } + def self.restore_rails_logger(app) + logger = @logger + return unless logger + + original_logger = @original_rails_logger + Rails.logger = original_logger + ActiveSupport::LogSubscriber.logger = @original_log_subscriber_logger + app.config.logger = @original_app_logger + + # These hooks run after the ones that installed LogStruct's logger, including for + # components that are already loaded + COMPONENT_LOAD_HOOKS.each do |hook| + ActiveSupport.on_load(hook) do + T.unsafe(self).logger = original_logger if T.unsafe(self).logger.equal?(logger) + end + end + + @logger = nil + end end end end diff --git a/rails_test_app/templates/config/initializers/logstruct.rb b/rails_test_app/templates/config/initializers/logstruct.rb index 53d2ad1b..b33a2ed5 100644 --- a/rails_test_app/templates/config/initializers/logstruct.rb +++ b/rails_test_app/templates/config/initializers/logstruct.rb @@ -7,6 +7,14 @@ # Specify which environments to enable in config.enabled_environments = [:development, :test, :production] + # Lets BootLogsIntegrationTest check that `enabled` and `enabled_environments` set here are honored + if ENV.key?("LOGSTRUCT_TEST_INITIALIZER_ENABLED") + config.enabled = ENV["LOGSTRUCT_TEST_INITIALIZER_ENABLED"] == "true" + end + if ENV.key?("LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS") + config.enabled_environments = ENV.fetch("LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS").split(",").map(&:to_sym) + end + # Specify which environments are considered local/development config.local_environments = [:development, :test] diff --git a/rails_test_app/templates/test/integration/boot_logs_integration_test.rb b/rails_test_app/templates/test/integration/boot_logs_integration_test.rb index ef0e8939..64d6fee0 100644 --- a/rails_test_app/templates/test/integration/boot_logs_integration_test.rb +++ b/rails_test_app/templates/test/integration/boot_logs_integration_test.rb @@ -58,8 +58,66 @@ def test_rails_runner_emits_original_dotenv_logs_when_disabled assert dotenv_lines.any? { |l| l.include?("Loaded ") }, "Expected a 'Loaded ...' line" end + def test_initializer_can_disable_logstruct_after_the_logger_was_replaced + result = runner_loggers( + "RAILS_ENV" => "test", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "false" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + refute_match(/LogStruct/, result[:active_record_logger]) + end + + def test_initializer_can_enable_logstruct + result = runner_loggers( + "RAILS_ENV" => "development", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "true" + ) + + assert_equal "true", result[:enabled] + assert_equal "LogStruct::SemanticLogger::Logger", result[:rails_logger] + assert_equal "LogStruct::SemanticLogger::Logger", result[:active_record_logger] + end + + def test_initializer_can_change_enabled_environments + result = runner_loggers( + "RAILS_ENV" => "test", + "LOGSTRUCT_ENABLED" => nil, + "LOGSTRUCT_TEST_INITIALIZER_ENVIRONMENTS" => "production" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + end + + def test_logstruct_enabled_env_var_overrides_the_initializer + result = runner_loggers( + "RAILS_ENV" => "development", + "LOGSTRUCT_ENABLED" => "false", + "LOGSTRUCT_TEST_INITIALIZER_ENABLED" => "true" + ) + + assert_equal "false", result[:enabled] + refute_match(/LogStruct/, result[:rails_logger]) + end + private + def runner_loggers(env) + script = 'puts "LOGGERS #{LogStruct.enabled?} #{Rails.logger.class} #{ActiveRecord::Base.logger.class}"' + stdout_str, stderr_str, status = Open3.capture3(env, "bundle", "exec", "rails", "runner", script) + + assert_predicate status, :success?, "rails runner failed: #{stderr_str}" + line = stdout_str.lines.find { |l| l.start_with?("LOGGERS ") } + + assert line, "Expected a LOGGERS line in:\n#{stdout_str}" + _, enabled, rails_logger, active_record_logger = T.must(line).split + {enabled: enabled, rails_logger: rails_logger, active_record_logger: active_record_logger} + end + def runner_output_lines(env) cmd = ["bundle", "exec", "rails", "runner", "puts LogStruct.enabled?"] stdout_str, stderr_str, status = Open3.capture3(env, *cmd) diff --git a/rails_test_app/templates/test/integration/filter_parameters_test.rb b/rails_test_app/templates/test/integration/filter_parameters_test.rb index 294d6308..378b3bc5 100644 --- a/rails_test_app/templates/test/integration/filter_parameters_test.rb +++ b/rails_test_app/templates/test/integration/filter_parameters_test.rb @@ -16,6 +16,19 @@ def test_rails_keeps_its_filter_parameters assert_equal "[FILTERED]", filter.filter("password" => "hunter2")["password"] end + def test_logstruct_filters_keys_from_initializers_the_way_rails_does + # :otp and :crypt come from config/initializers/filter_parameter_logging.rb, not LogStruct's + # defaults, and Rails matches them anywhere in a key + Rails.logger.info(msg: "Signed in", otp_attempt: "135790", encrypted_note: "hunter2") + + ::SemanticLogger.flush + output = @log_output.string + + assert_includes output, "Signed in" + assert_not_includes output, "135790" + assert_not_includes output, "hunter2" + end + def test_active_record_filter_attributes_still_filter assert_includes ActiveRecord::Base.filter_attributes, :passw end diff --git a/test/log_struct/configuration_test.rb b/test/log_struct/configuration_test.rb index 8fb2eb9e..df215913 100644 --- a/test/log_struct/configuration_test.rb +++ b/test/log_struct/configuration_test.rb @@ -105,6 +105,49 @@ def test_enabled_env_var_takes_precedence_over_environment end end + def test_enabled_environments_set_in_an_initializer_apply + ClimateControl.modify LOGSTRUCT_ENABLED: nil do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.config.enabled_environments = [:test, :production] + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled_environments = [:production] + LogStruct.apply_initializer_settings! + + refute LogStruct.config.enabled + end + end + end + + def test_enabled_set_in_an_initializer_wins_over_enabled_environments + ClimateControl.modify LOGSTRUCT_ENABLED: nil do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.config.enabled_environments = [:production] + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled = true + LogStruct.config.enabled_environments = [:staging] + LogStruct.apply_initializer_settings! + + assert LogStruct.config.enabled + end + end + end + + def test_logstruct_enabled_wins_over_settings_from_an_initializer + ClimateControl.modify LOGSTRUCT_ENABLED: "true" do + Rails.stub(:env, ActiveSupport::StringInquirer.new("test")) do + LogStruct.set_enabled_from_rails_env! + + LogStruct.config.enabled = false + LogStruct.config.enabled_environments = [:production] + LogStruct.apply_initializer_settings! + + assert LogStruct.config.enabled + end + end + end + def test_merge_rails_filter_parameters_matches_keys_the_way_rails_does filter_params = [:passw, "Card_Number", :_key] From 711c50f70b8866ed9e47cb7f08aa0bb23b082e38 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Thu, 15 Oct 2026 17:48:44 +1300 Subject: [PATCH 4/7] Set up GoodJob's logger and thread error handler Inside LogStruct::Integrations::GoodJob, `GoodJob` is that module, so the integration set the logger and thread error handler on itself and GoodJob kept its own logger. It now sets them on ::GoodJob. The thread error handler calls the handler the app set first (GoodJob's README sets one to report errors), then logs the error. --- lib/log_struct/integrations/good_job.rb | 16 ++++++--- sorbet/rbi/shims/good_job.rbi | 19 +++++++++++ test/log_struct/integrations/good_job_test.rb | 33 +++++++++++++++++++ 3 files changed, 64 insertions(+), 4 deletions(-) create mode 100644 sorbet/rbi/shims/good_job.rbi diff --git a/lib/log_struct/integrations/good_job.rb b/lib/log_struct/integrations/good_job.rb index 1f4dbf3d..93e595a9 100644 --- a/lib/log_struct/integrations/good_job.rb +++ b/lib/log_struct/integrations/good_job.rb @@ -65,22 +65,29 @@ def self.setup(config) true end + @thread_error_handler = T.let(nil, T.nilable(T.proc.params(exception: StandardError).void)) + # Configure GoodJob to use LogStruct's structured logger sig { void } def self.configure_logger return unless defined?(::GoodJob) - # Use direct reference to avoid const_get - GoodJob is guaranteed to be defined here - goodjob_module = T.unsafe(GoodJob) + # Not GoodJob, which here is this module + goodjob_module = ::GoodJob # Replace GoodJob.logger with our structured logger if GoodJob is available if goodjob_module.respond_to?(:logger=) goodjob_module.logger = LogStruct::Integrations::GoodJob::Logger.new("GoodJob") end - # Configure error handling for thread errors if GoodJob supports it + # Log thread errors, after calling the handler the app set (GoodJob's README sets one + # to report them to an error tracker). Setting up again keeps the one handler. if goodjob_module.respond_to?(:on_thread_error=) - goodjob_module.on_thread_error = ->(exception) do + app_handler = goodjob_module.on_thread_error + return if app_handler&.equal?(@thread_error_handler) + + @thread_error_handler = ->(exception) do + app_handler&.call(exception) log_entry = LogStruct::Log::GoodJob::Error.new( error_class: exception.class.name, error_message: exception.message, @@ -90,6 +97,7 @@ def self.configure_logger ) goodjob_module.logger.error(log_entry) end + goodjob_module.on_thread_error = @thread_error_handler end end diff --git a/sorbet/rbi/shims/good_job.rbi b/sorbet/rbi/shims/good_job.rbi new file mode 100644 index 00000000..67195a4f --- /dev/null +++ b/sorbet/rbi/shims/good_job.rbi @@ -0,0 +1,19 @@ +# typed: true + +# GoodJob isn't installed for development (it needs PostgreSQL), so Tapioca has no RBI for it. +# These are the settings the GoodJob integration changes. +module GoodJob + class << self + sig { returns(T.untyped) } + def logger; end + + sig { params(logger: T.untyped).void } + def logger=(logger); end + + sig { returns(T.nilable(T.proc.params(exception: StandardError).void)) } + def on_thread_error; end + + sig { params(handler: T.nilable(T.proc.params(exception: StandardError).void)).void } + def on_thread_error=(handler); end + end +end diff --git a/test/log_struct/integrations/good_job_test.rb b/test/log_struct/integrations/good_job_test.rb index 2525f194..26495169 100644 --- a/test/log_struct/integrations/good_job_test.rb +++ b/test/log_struct/integrations/good_job_test.rb @@ -2,6 +2,7 @@ # frozen_string_literal: true require "test_helper" +require "log_struct/integrations/good_job/logger" module LogStruct module Integrations @@ -56,6 +57,25 @@ class GoodJobTest < ActiveSupport::TestCase assert_includes GoodJob.private_methods, :configure_logger end + test "replaces GoodJob's logger and logs thread errors after the app's own handler" do + with_fake_goodjob do |fake| + reported = [] + fake.on_thread_error = ->(exception) { reported << exception.message } + + GoodJob.send(:configure_logger) + GoodJob.send(:configure_logger) + + assert_instance_of GoodJob::Logger, fake.logger + logged = [] + fake.logger.stub(:error, ->(entry) { logged << entry.error_message }) do + fake.on_thread_error.call(RuntimeError.new("boom")) + end + + assert_equal ["boom"], reported + assert_equal ["boom"], logged + end + end + test "subscribe_to_notifications method exists and is private" do assert_includes GoodJob.private_methods, :subscribe_to_notifications end @@ -80,6 +100,19 @@ class GoodJobTest < ActiveSupport::TestCase private + # Stands in for the GoodJob gem, which isn't installed for the tests + def with_fake_goodjob + fake = Module.new do + class << self + attr_accessor :logger, :on_thread_error + end + end + Object.const_set(:GoodJob, fake) + yield fake + ensure + Object.send(:remove_const, :GoodJob) + end + def skip_if_goodjob_defined if defined?(::GoodJob) skip "GoodJob is defined in test environment - cannot test undefined behavior" From a815896901c2eb64c0be511e4fa4645a0948674a Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 10:39:56 +1300 Subject: [PATCH 5/7] Replace Sidekiq's logger before config/initializers run Integrations are now set up after config/initializers, so Sidekiq kept its own text logger while they ran. An initializer that configures Sidekiq logs with that logger straight away (connecting to Redis, setting up a fetcher), so those lines were plain text. The Railtie now replaces Sidekiq's logger as soon as it replaces Rails.logger, and puts Sidekiq's logger back if an initializer turns LogStruct or the Sidekiq integration off. --- .cspell/project-words.txt | 1 + lib/log_struct/integrations/sidekiq.rb | 46 ++++++++++++++++---- lib/log_struct/railtie.rb | 6 +++ test/log_struct/integrations/sidekiq_test.rb | 37 ++++++++++++++++ 4 files changed, 81 insertions(+), 9 deletions(-) diff --git a/.cspell/project-words.txt b/.cspell/project-words.txt index 38120f9c..2d777d04 100644 --- a/.cspell/project-words.txt +++ b/.cspell/project-words.txt @@ -77,3 +77,4 @@ vercel wordlists xorshift yardoc +tsort diff --git a/lib/log_struct/integrations/sidekiq.rb b/lib/log_struct/integrations/sidekiq.rb index fbc72bb6..30a1a4e6 100644 --- a/lib/log_struct/integrations/sidekiq.rb +++ b/lib/log_struct/integrations/sidekiq.rb @@ -18,6 +18,8 @@ module Sidekiq extend T::Sig extend IntegrationInterface + @original_logger = T.let(nil, T.untyped) + # Set up Sidekiq structured logging sig { override.params(config: LogStruct::Configuration).returns(T.nilable(T::Boolean)) } def self.setup(config) @@ -25,10 +27,9 @@ def self.setup(config) return nil unless config.enabled return nil unless config.integrations.enable_sidekiq - # Configure Sidekiq server (worker) to use our logger - ::Sidekiq.configure_server do |sidekiq_config| - sidekiq_config.logger = LogStruct::Integrations::Sidekiq::Logger.new("Sidekiq-Server") + configure_logger + ::Sidekiq.configure_server do |sidekiq_config| # First in the chain, so lines logged by other middleware include the job too sidekiq_config.server_middleware do |chain| chain.prepend LogStruct::Integrations::Sidekiq::JobContextMiddleware @@ -37,14 +38,41 @@ def self.setup(config) replace_default_error_handler(sidekiq_config) end - # Configure Sidekiq client (Rails app) to use our logger - ::Sidekiq.configure_client do |sidekiq_config| - sidekiq_config.logger = LogStruct::Integrations::Sidekiq::Logger.new("Sidekiq-Client") - end - true end + # Use LogStruct's logger for Sidekiq's own lines. The Railtie calls this as soon as it replaces + # Rails.logger, before config/initializers run, because an initializer that configures Sidekiq + # (connecting to Redis, setting up a fetcher) logs with Sidekiq's logger straight away. + sig { void } + def self.configure_logger + return unless defined?(::Sidekiq) + + current = sidekiq_logger_config.logger + return if current.is_a?(LogStruct::Integrations::Sidekiq::Logger) + + @original_logger = current + name = ::Sidekiq.server? ? "Sidekiq-Server" : "Sidekiq-Client" + sidekiq_logger_config.logger = LogStruct::Integrations::Sidekiq::Logger.new(name) + end + + # Put Sidekiq's own logger back, when an initializer turned LogStruct or this integration off + # after configure_logger ran + sig { void } + def self.restore_logger + return unless defined?(::Sidekiq) + return if @original_logger.nil? + + sidekiq_logger_config.logger = @original_logger + @original_logger = nil + end + + # Sidekiq 7 keeps the logger on its default configuration, Sidekiq 6 on the module + sig { returns(T.untyped) } + def self.sidekiq_logger_config + ::Sidekiq.respond_to?(:default_configuration) ? ::Sidekiq.default_configuration : ::Sidekiq + end + # Sidekiq's default error handler logs three lines for each failed job: the job (with its # arguments) as a JSON string, the error, and the backtrace. Log one structured line instead, # without the arguments, which LogStruct can't filter inside a JSON string. @@ -92,7 +120,7 @@ def self.log_job_error(error, context) T.proc.params(error: Exception, context: T::Hash[T.untyped, T.untyped], config: T.untyped).void ) - private_class_method :replace_default_error_handler, :log_job_error + private_class_method :sidekiq_logger_config, :replace_default_error_handler, :log_job_error end end end diff --git a/lib/log_struct/railtie.rb b/lib/log_struct/railtie.rb index d783cdfb..390ff660 100644 --- a/lib/log_struct/railtie.rb +++ b/lib/log_struct/railtie.rb @@ -17,6 +17,9 @@ class Railtie < ::Rails::Railtie # Use SemanticLogger for powerful logging features LogStruct::SemanticLogger::Setup.configure_semantic_logger(app) + + # Initializers that configure Sidekiq log with its logger while config/initializers run + Integrations::Sidekiq.configure_logger if LogStruct.config.integrations.enable_sidekiq end # Set up integrations after config/initializers, so that the settings in @@ -30,6 +33,9 @@ class Railtie < ::Rails::Railtie elsif LogStruct::SemanticLogger::Setup.configured? LogStruct::SemanticLogger::Setup.restore_rails_logger(app) end + unless LogStruct.enabled? && LogStruct.config.integrations.enable_sidekiq + Integrations::Sidekiq.restore_logger + end next unless LogStruct.enabled? diff --git a/test/log_struct/integrations/sidekiq_test.rb b/test/log_struct/integrations/sidekiq_test.rb index 8119e4eb..3702e740 100644 --- a/test/log_struct/integrations/sidekiq_test.rb +++ b/test/log_struct/integrations/sidekiq_test.rb @@ -60,6 +60,43 @@ class SidekiqTest < ActiveSupport::TestCase assert_equal({"jid" => "abc123", "class" => "HardJob", "template_id" => "tpl_1"}, line["ctx"]) end + test "Sidekiq's logger is replaced before config/initializers run" do + names = Rails.application.initializers.tsort_each.map(&:name) + + assert_operator names.index("logstruct.configure_logger"), :<, names.index(:load_config_initializers) + + sidekiq_config = ::Sidekiq.default_configuration + saved = sidekiq_config.logger + sidekiq_config.logger = ::Logger.new(StringIO.new) + initializer = Rails.application.initializers.find { |i| i.name == "logstruct.configure_logger" } + + # Only the Sidekiq part: replacing Rails.logger again would reset the test appenders + LogStruct::SemanticLogger::Setup.stub(:configure_semantic_logger, nil) do + T.must(initializer).run(Rails.application) + end + + assert_kind_of Sidekiq::Logger, sidekiq_config.logger + ensure + sidekiq_config&.logger = saved + end + + test "restore_logger puts back the logger Sidekiq had" do + sidekiq_config = ::Sidekiq.default_configuration + saved = sidekiq_config.logger + original = ::Logger.new(StringIO.new) + sidekiq_config.logger = original + + Sidekiq.configure_logger + + assert_kind_of Sidekiq::Logger, sidekiq_config.logger + + Sidekiq.restore_logger + + assert_same original, sidekiq_config.logger + ensure + sidekiq_config&.logger = saved + end + test "a failed job is logged once, as a structured line without its arguments" do sidekiq_config = ::Sidekiq::Config.new sidekiq_config.logger = Sidekiq::Logger.new("Sidekiq-Server") From 5a804d2c08607ab2397ec6cce9bf86962e8e0f00 Mon Sep 17 00:00:00 2001 From: Nathan Broadbent Date: Fri, 16 Oct 2026 10:56:36 +1300 Subject: [PATCH 6/7] Log Puma's request errors as structured lines Puma::ErrorLogger writes request errors (an exception the app didn't handle, a malformed request, an SSL error) as a plain text line on STDERR: the time, the request line with its query string and client IP, and the error. LogStruct's Puma integration now logs them as error lines (src puma, evt error) with the error, method and path. The query string is left out, since tokens in it can't be filtered inside the line. --- lib/log_struct/integrations/puma.rb | 30 ++++++++++++++++++ .../log_struct/integrations/puma_unit_test.rb | 31 +++++++++++++++++++ 2 files changed, 61 insertions(+) diff --git a/lib/log_struct/integrations/puma.rb b/lib/log_struct/integrations/puma.rb index ba01106b..1ab27e6a 100644 --- a/lib/log_struct/integrations/puma.rb +++ b/lib/log_struct/integrations/puma.rb @@ -103,6 +103,9 @@ def install_patches! if puma_mod&.const_defined?(:LogWriter) T.unsafe(::Object.const_get("Puma::LogWriter")).prepend(LogWriterPatch) end + if puma_mod&.const_defined?(:ErrorLogger) + T.unsafe(::Object.const_get("Puma::ErrorLogger")).prepend(ErrorLoggerPatch) + end if puma_mod&.const_defined?(:Events) ev = T.unsafe(::Object.const_get("Puma::Events")) ev.prepend(EventsPatch) @@ -379,6 +382,33 @@ def info(msg) end end + # Puma::ErrorLogger writes request errors (an exception the app didn't handle, a malformed + # request, an SSL error) as plain text to STDERR, with the request's query string. Log them + # as structured lines, with the method and path but not the query string, which LogStruct + # can't filter there. + module ErrorLoggerPatch + extend T::Sig + + sig { params(options: T::Hash[Symbol, T.untyped]).returns(T.untyped) } + def info(options = {}) + error = options[:error] + # Log::Error only takes a StandardError + return super unless error.is_a?(StandardError) + + env = options[:req]&.env + details = { + context: options[:text], + method: env&.dig("REQUEST_METHOD"), + path: env && (env["REQUEST_PATH"] || env["PATH_INFO"]) + }.compact + ::LogStruct.error(::LogStruct::Log.from_exception(::LogStruct::Source::Puma, error, details)) + nil + rescue => e + ::LogStruct::Integrations::Puma.handle_integration_error(e) + super + end + end + # Patch Puma::Events as a fallback for some versions where Events handles output module EventsPatch extend T::Sig diff --git a/test/log_struct/integrations/puma_unit_test.rb b/test/log_struct/integrations/puma_unit_test.rb index e83881e1..b0101c25 100644 --- a/test/log_struct/integrations/puma_unit_test.rb +++ b/test/log_struct/integrations/puma_unit_test.rb @@ -65,6 +65,37 @@ def test_process_line_returns_false_for_unhandled_input refute PUMA.process_line("unrecognized line") end + # Stands in for Puma::ErrorLogger, which writes "