Set up integrations after the app's initializers, and stop Shrine, AMS and Puma writing text lines

.cspell/project-words.txt

@@ -77,3 +77,4 @@ vercel
 wordlists
 xorshift
 yardoc
+tsort

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)

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

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/
 

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
 

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

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

lib/log_struct/integrations/sidekiq.rb

@@ -18,17 +18,18 @@ 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)
         return nil unless defined?(::Sidekiq)
         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

lib/log_struct/railtie.rb

@@ -10,31 +10,43 @@
 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?
 
       # 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
 
-    # 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
+      unless LogStruct.enabled? && LogStruct.config.integrations.enable_sidekiq
+        Integrations::Sidekiq.restore_logger
+      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)
@@ -53,10 +65,6 @@ class Railtie < ::Rails::Railtie
           process_id: Process.pid,
           listening_addresses: port ? ["tcp://127.0.0.1:#{port}"] : nil
         )
-        begin
-          warn("[logstruct] puma lifecycle init")
-        rescue
-        end
         LogStruct.info(started)
 
         at_exit do