Log Sidekiq and Puma errors with typed fields, and an ActiveJob job's Sidekiq error unless ActiveJob logged it

docs/lib/log-generation/log-generator.ts

@@ -114,8 +114,20 @@ export class LogGenerator extends RandomDataGenerator {
           }
         }
 
-        case LogType.SIDEKIQ:
-          return Sidekiq.SidekiqLog.random(this).serialize();
+        case LogType.SIDEKIQ: {
+          switch (evt ?? this.sample([Event.Log, Event.Error])) {
+            case Event.Error:
+              return Sidekiq.SidekiqError.random(this, {
+                level: Level.Warn,
+                error_class: 'ArgumentError',
+                message: 'Template not found',
+                error_context: 'Job raised exception',
+                queue_name: 'default',
+              }).serialize();
+            default:
+              return Sidekiq.SidekiqLog.random(this).serialize();
+          }
+        }
 
         case LogType.ACTIVESTORAGE: {
           switch (
@@ -202,9 +214,18 @@ export class LogGenerator extends RandomDataGenerator {
         }
 
         case LogType.PUMA: {
-          switch (evt ?? this.sample([Event.Start, Event.Shutdown])) {
+          switch (evt ?? this.sample([Event.Start, Event.Shutdown, Event.Error])) {
             case Event.Shutdown:
               return Puma.PumaShutdown.random(this).serialize();
+            case Event.Error:
+              return Puma.PumaError.random(this, {
+                level: Level.Error,
+                error_class: 'Puma::HttpParserError',
+                message: 'Invalid HTTP format, parsing fails.',
+                error_context: 'HTTP parse error, malformed request',
+                http_method: 'GET',
+                path: '/',
+              }).serialize();
             default:
               return Puma.PumaStart.random(this, {
                 listening_addresses: [`tcp://127.0.0.1:${this.randomInt(3000, 3999)}`],

docs/lib/log-generation/sample-data.ts

@@ -239,6 +239,7 @@ export const SampleByLogField: Readonly<Record<LogField, (gen: RandomGen) => unk
   [LogField.Priority]: (gen: RandomGen) => gen.randomInt(0, 100),
   [LogField.Vars]: (_gen: RandomGen) => ['API_KEY'],
   [LogField.ErrorMessage]: (_gen: RandomGen) => 'Something failed',
+  [LogField.ErrorContext]: (_gen: RandomGen) => 'Job raised exception',
   [LogField.ProcessId]: SampleHelpers.processId,
   [LogField.Snapshot]: (_gen: RandomGen) => true,
   [LogField.Context]: (_gen: RandomGen) => ({ ctx: 'demo' }),

docs/lib/log-structure-descriptions.ts

@@ -24,14 +24,14 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record<string, string> = {
   Url: 'URL generation event for a stored file (ActiveStorage)',
   Shrine: 'For Shrine file upload events',
   CarrierWave: 'For CarrierWave upload events',
-  Sidekiq: 'For Sidekiq job processing',
+  Sidekiq: "For Sidekiq's own log lines and failed jobs",
   Security: 'For security-related events',
   BlockedHost:
     'Request blocked by ActionDispatch::HostAuthorization (host not on the allowed list)',
   CSRFViolation: 'Request rejected due to a CSRF token violation',
   IPSpoof: 'Request rejected because the IP address spoofing check failed',
   GoodJob: "For GoodJob's own log lines and thread errors",
-  Log: 'Structured GoodJob log output captured from the worker process',
+  Log: "A log line: a plain message, or a line from GoodJob's, Sidekiq's or Ahoy's own logger",
   SQL: 'For ActiveRecord SQL query events and performance metrics',
   ActiveModelSerializers:
     'For render events produced by ActiveModelSerializers (serializer, adapter, resource, duration)',
@@ -42,7 +42,7 @@ export const LOG_STRUCTURE_DESCRIPTIONS: Record<string, string> = {
   Restore: 'dotenv-rails restore event rolling back to the last saved state',
   Save: 'dotenv-rails save event persisting environment variables',
   Update: 'dotenv-rails update event after manipulating environment values',
-  Puma: 'For Puma server lifecycle events',
+  Puma: 'For Puma server lifecycle events and request errors',
   Shutdown: 'Puma server shutdown event',
 };
 

lib/log_struct/enums/log_field.rb

@@ -91,6 +91,8 @@ class LogField < T::Enum
       Priority = new(:priority)
       CronKey = new(:cron_key)
       ErrorMessage = new(:error_message)
+      # What the integration was doing when the error happened, e.g. Sidekiq's "Job raised exception"
+      ErrorContext = new(:error_context)
       Result = new(:result)
       EnqueueCaller = new(:enqueue_caller)
 

lib/log_struct/integrations/puma.rb

@@ -392,16 +392,17 @@ module ErrorLoggerPatch
         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)
+          return super unless error.is_a?(Exception)
 
           env = options[:req]&.env
-          details = {
-            context: options[:text],
-            method: env&.dig("REQUEST_METHOD"),
+          ::LogStruct.error(::LogStruct::Log::Puma::Error.new(
+            error_class: error.class,
+            message: error.message,
+            backtrace: error.backtrace,
+            error_context: options[:text]&.to_s,
+            http_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)

lib/log_struct/integrations/sidekiq.rb

@@ -86,33 +86,37 @@ def self.replace_default_error_handler(sidekiq_config)
         handlers.unshift(JOB_ERROR_HANDLER)
       end
 
+      # The line has the job's ID and class in ctx, like the lines logged while the job ran (Sidekiq
+      # calls its error handlers after the job's middleware has finished).
       sig { params(error: Exception, context: T::Hash[T.untyped, T.untyped]).void }
       def self.log_job_error(error, context)
+        # LogStruct's ActiveJob integration logs the errors it sees an ActiveJob job raise. An
+        # error raised before ActiveJob ran the job (a job class a deploy removed, say) is logged
+        # here.
+        return if LogStruct::LoggedErrors.logged?(error)
+
         job = context[:job]
         job = nil unless job.is_a?(Hash)
-
-        # LogStruct's ActiveJob integration already logs the errors of ActiveJob jobs
-        return if job&.key?("wrapped") && LogStruct.config.integrations.enable_activejob
-
-        details = {
-          context: context[:context],
-          jid: job&.dig("jid"),
-          job_class: job && (job["wrapped"] || job["class"]),
-          queue: job&.dig("queue"),
+        error_context = context[:context]
+
+        line = Log::Sidekiq::Error.new(
+          error_class: error.class,
+          message: error.message,
+          backtrace: error.backtrace,
+          error_context: error_context&.to_s,
+          queue_name: job&.dig("queue")&.to_s,
           retry_count: job&.dig("retry_count")
-        }.compact
-
-        if error.is_a?(StandardError)
-          ::Rails.logger.warn(Log.from_exception(Source::Sidekiq, error, details))
-        else
-          # Log::Error only takes a StandardError; Sidekiq also reports others (e.g. NoMemoryError)
-          ::Rails.logger.warn(Log::Sidekiq.new(
-            level: Level::Warn,
-            event: Event::Error,
-            message: "#{error.class.name}: #{error.message}",
-            context: details
-          ))
+        )
+        if job.nil?
+          ::Rails.logger.warn(line)
+          return
         end
+
+        job_context = {
+          jid: job["jid"],
+          class: job["display_class"] || job["wrapped"] || job["class"]
+        }.compact
+        ::SemanticLogger.named_tagged(sidekiq_context: job_context) { ::Rails.logger.warn(line) }
       end
 
       JOB_ERROR_HANDLER = T.let(

lib/log_struct/integrations/sidekiq/logger.rb

@@ -16,7 +16,7 @@ def self.tid
         Thread.current["sidekiq_tid"] ||= (Thread.current.object_id ^ ::Process.pid).to_s(36)
       end
 
-      # Custom Logger for Sidekiq that creates LogStruct::Log::Sidekiq entries
+      # Custom Logger for Sidekiq that creates LogStruct::Log::Sidekiq::Log entries
       class Logger < LogStruct::SemanticLogger::Logger
         extend T::Sig
 
@@ -31,7 +31,7 @@ class Logger < LogStruct::SemanticLogger::Logger
             end
 
             # Create a Sidekiq log struct with the message
-            log_struct = Log::Sidekiq.new(
+            log_struct = Log::Sidekiq::Log.new(
               level: LogStruct::Level.from_severity(level.to_s.upcase),
               event: Event::Log,
               message: msg,

lib/log_struct/log/puma.rb

@@ -8,3 +8,4 @@
 
 require_relative "puma/start"
 require_relative "puma/shutdown"
+require_relative "puma/error"

lib/log_struct/log/puma/error.rb

@@ -0,0 +1,63 @@
+# typed: strict
+# frozen_string_literal: true
+
+# AUTO-GENERATED: DO NOT EDIT
+# Generated by scripts/generate_structs.rb
+# Schemas dir: schemas/log_sources/
+# Template: tools/codegen/templates/sorbet/event.rb.erb
+
+require "log_struct/shared/interfaces/common_fields"
+require "log_struct/shared/interfaces/additional_data_field"
+require "log_struct/shared/interfaces/request_fields"
+require "log_struct/shared/serialize_common"
+require "log_struct/shared/merge_additional_data_fields"
+require "log_struct/shared/add_request_fields"
+require_relative "../../enums/source"
+require_relative "../../enums/event"
+require_relative "../../enums/level"
+require_relative "../../enums/log_field"
+
+module LogStruct
+  module Log
+    class Puma
+      class Error < T::Struct
+        extend T::Sig
+
+        # Shared/common fields
+        const :source, Source::Puma, default: Source::Puma
+        const :event, Event, default: Event::Error
+        const :timestamp, Time, factory: -> { Time.now }
+        const :level, Level, default: Level::Info
+
+        # Event-specific fields
+        const :error_class, T.class_of(Exception)
+        const :message, String
+        const :backtrace, T.nilable(T::Array[String]), default: nil
+        const :error_context, T.nilable(String), default: nil
+        const :http_method, T.nilable(String), default: nil
+        const :path, T.nilable(String), default: nil
+
+        # Additional data
+        include LogStruct::Log::Interfaces::AdditionalDataField
+        const :additional_data, T.nilable(T::Hash[T.any(String, Symbol), T.untyped]), default: nil
+        include LogStruct::Log::Shared::MergeAdditionalDataFields
+
+        # Serialize shared fields
+        include LogStruct::Log::Interfaces::CommonFields
+        include LogStruct::Log::Shared::SerializeCommon
+
+        sig { returns(T::Hash[LogStruct::LogField, T.untyped]) }
+        def to_h
+          h = T.let({}, T::Hash[LogStruct::LogField, T.untyped])
+          h[LogField::ErrorClass] = error_class
+          h[LogField::Message] = message
+          h[LogField::Backtrace] = backtrace unless backtrace.nil?
+          h[LogField::ErrorContext] = error_context unless error_context.nil?
+          h[LogField::HttpMethod] = http_method unless http_method.nil?
+          h[LogField::Path] = path unless path.nil?
+          h
+        end
+      end
+    end
+  end
+end

lib/log_struct/log/sidekiq.rb

@@ -4,49 +4,7 @@
 # AUTO-GENERATED: DO NOT EDIT
 # Generated by scripts/generate_structs.rb
 # Schemas dir: schemas/log_sources/
-# Template: tools/codegen/templates/sorbet/event.rb.erb
+# Template: tools/codegen/templates/sorbet/source_parent.rb.erb
 
-require "log_struct/shared/interfaces/common_fields"
-require "log_struct/shared/interfaces/additional_data_field"
-require "log_struct/shared/interfaces/request_fields"
-require "log_struct/shared/serialize_common"
-require "log_struct/shared/merge_additional_data_fields"
-require "log_struct/shared/add_request_fields"
-require_relative "../enums/source"
-require_relative "../enums/event"
-require_relative "../enums/level"
-require_relative "../enums/log_field"
-
-module LogStruct
-  module Log
-    class Sidekiq < T::Struct
-      extend T::Sig
-
-      # Shared/common fields
-      const :source, Source::Sidekiq, default: Source::Sidekiq
-      const :event, Event, default: Event::Log
-      const :timestamp, Time, factory: -> { Time.now }
-      const :level, Level, default: Level::Info
-
-      # Event-specific fields
-      const :message, T.nilable(String), default: nil
-      const :context, T.nilable(T::Hash[Symbol, T.untyped]), default: nil
-      const :process_id, T.nilable(Integer), default: nil
-      const :thread_id, T.nilable(T.any(Integer, String)), default: nil
-
-      # Serialize shared fields
-      include LogStruct::Log::Interfaces::CommonFields
-      include LogStruct::Log::Shared::SerializeCommon
-
-      sig { returns(T::Hash[LogStruct::LogField, T.untyped]) }
-      def to_h
-        h = T.let({}, T::Hash[LogStruct::LogField, T.untyped])
-        h[LogField::Message] = message unless message.nil?
-        h[LogField::Context] = context unless context.nil?
-        h[LogField::ProcessId] = process_id unless process_id.nil?
-        h[LogField::ThreadId] = thread_id unless thread_id.nil?
-        h
-      end
-    end
-  end
-end
+require_relative "sidekiq/log"
+require_relative "sidekiq/error"

lib/log_struct/log/sidekiq/error.rb

@@ -0,0 +1,58 @@
+# typed: strict
+# frozen_string_literal: true
+
+# AUTO-GENERATED: DO NOT EDIT
+# Generated by scripts/generate_structs.rb
+# Schemas dir: schemas/log_sources/
+# Template: tools/codegen/templates/sorbet/event.rb.erb
+
+require "log_struct/shared/interfaces/common_fields"
+require "log_struct/shared/interfaces/additional_data_field"
+require "log_struct/shared/interfaces/request_fields"
+require "log_struct/shared/serialize_common"
+require "log_struct/shared/merge_additional_data_fields"
+require "log_struct/shared/add_request_fields"
+require_relative "../../enums/source"
+require_relative "../../enums/event"
+require_relative "../../enums/level"
+require_relative "../../enums/log_field"
+
+module LogStruct
+  module Log
+    class Sidekiq
+      class Error < T::Struct
+        extend T::Sig
+
+        # Shared/common fields
+        const :source, Source::Sidekiq, default: Source::Sidekiq
+        const :event, Event, default: Event::Error
+        const :timestamp, Time, factory: -> { Time.now }
+        const :level, Level, default: Level::Info
+
+        # Event-specific fields
+        const :error_class, T.class_of(Exception)
+        const :message, String
+        const :backtrace, T.nilable(T::Array[String]), default: nil
+        const :error_context, T.nilable(String), default: nil
+        const :queue_name, T.nilable(String), default: nil
+        const :retry_count, T.nilable(Integer), default: nil
+
+        # Serialize shared fields
+        include LogStruct::Log::Interfaces::CommonFields
+        include LogStruct::Log::Shared::SerializeCommon
+
+        sig { returns(T::Hash[LogStruct::LogField, T.untyped]) }
+        def to_h
+          h = T.let({}, T::Hash[LogStruct::LogField, T.untyped])
+          h[LogField::ErrorClass] = error_class
+          h[LogField::Message] = message
+          h[LogField::Backtrace] = backtrace unless backtrace.nil?
+          h[LogField::ErrorContext] = error_context unless error_context.nil?
+          h[LogField::QueueName] = queue_name unless queue_name.nil?
+          h[LogField::RetryCount] = retry_count unless retry_count.nil?
+          h
+        end
+      end
+    end
+  end
+end