DEV: Improve logging of Sidekiq errors when logstash logger is enabled (#27855)

This commit improves the logging of Sidekiq errors when
`ENABLE_LOGSTASH_LOGGER` is set to 1. Prior to this change, we would
only log the message and the backtrace. After this change, useful
information like `job.class`, `job.opts`, `job.problem_db`,
`exception.class` and `exception.message` are included in the log line
as well.

lib/discourse_logstash_logger.rb

@@ -91,12 +91,18 @@ class DiscourseLogstashLogger < Logger
           event["exception.class"] = $1
           event["exception.message"] = $2.strip
         end
+
+        ALLOWED_HEADERS_FROM_ENV.each do |header|
+          event["request.headers.#{header.downcase}"] = opts.dig(:env, header)
+        end
       end
 
-      if (env = opts&.dig(:env)).present?
+      if progname == "sidekiq-exception"
-        ALLOWED_HEADERS_FROM_ENV.each do |header|
+        event["job.class"] = opts.dig(:context, :job)
-          event["request.headers.#{header.downcase}"] = opts[:env][header]
+        event["job.opts"] = opts.dig(:context, :opts)
-        end
+        event["job.problem_db"] = opts.dig(:context, :problem_db)
+        event["exception.class"] = opts[:exception_class]
+        event["exception.message"] = opts[:exception_message]
       end
     end
 

lib/sidekiq_logster_reporter.rb

@@ -9,13 +9,21 @@ class SidekiqLogsterReporter
     fake_env = {}
     context.each { |key, value| Logster.add_to_env(fake_env, key, value) }
 
-    text = "Job exception: #{ex}\n"
+    text = "Job exception: #{ex}"
     Logster.add_to_env(fake_env, :backtrace, ex.backtrace) if ex.backtrace
-
     Logster.add_to_env(fake_env, :current_hostname, Discourse.current_hostname)
 
     Thread.current[Logster::Logger::LOGSTER_ENV] = fake_env
-    Logster.logger.error(text)
+
+    Logster.logger.add_with_opts(
+      ::Logger::Severity::ERROR,
+      text,
+      "sidekiq-exception",
+      backtrace: ex.backtrace,
+      exception_class: ex.class.to_s,
+      exception_message: ex.message.strip,
+      context:,
+    )
   rescue => e
     Logster.logger.fatal(
       "Failed to log exception #{ex} #{hash}\nReason: #{e.class} #{e}\n#{e.backtrace.join("\n")}",

spec/lib/discourse_logstash_logger_spec.rb

@@ -49,36 +49,102 @@ RSpec.describe DiscourseLogstashLogger do
       expect(parsed["message"]).to eq("error message")
     end
 
-    it "logs a JSON string with the `exception_class` and `exception_message` fields when `progname` is `web-exception`" do
+    context "when `progname` is `sidekiq-exception`" do
-      logger = described_class.logger(logdev: output, type: "test")
+      it "logs a JSON string with the `exception.class`, `exception.message`, `job.class`, `job.opts` and `job.problem_db` fields" do
+        logger = described_class.logger(logdev: output, type: "test")
 
-      logger.add(
+        logger.add_with_opts(
-        Logger::ERROR,
+          Logger::ERROR,
-        "Some::StandardError (this is a normal message)\ntest",
+          "Job exception: some job error message",
-        "web-exception",
+          "sidekiq-exception",
-      )
+          exception_class: "Some::StandardError",
+          exception_message: "some job error message",
+          context: {
+            opts: {
+              user_id: 1,
+            },
+            problem_db: "some_db",
+            job: "SomeJob",
+          },
+        )
 
-      output.rewind
+        output.rewind
-      parsed = JSON.parse(output.read.chomp)
+        parsed = JSON.parse(output.read.chomp)
 
-      expect(parsed["exception.class"]).to eq("Some::StandardError")
+        expect(parsed["exception.class"]).to eq("Some::StandardError")
-      expect(parsed["exception.message"]).to eq("this is a normal message")
+        expect(parsed["exception.message"]).to eq("some job error message")
+        expect(parsed["job.class"]).to eq("SomeJob")
+        expect(parsed["job.opts"]).to eq({ "user_id" => 1 })
+        expect(parsed["job.problem_db"]).to eq("some_db")
+      end
     end
 
-    it "logs a JSON string with the `exception_class` and `exception_message` fields when `progname` is `web-exception` and the exception message contains newlines" do
+    context "when `progname` is `web-exception`" do
-      logger = described_class.logger(logdev: output, type: "test")
+      it "logs a JSON string with the `exception.class` and `exception.message` fields" do
+        logger = described_class.logger(logdev: output, type: "test")
 
-      logger.add(
+        logger.add(
-        Logger::ERROR,
+          Logger::ERROR,
-        "Some::StandardError (\n\nsome error message\n\nsomething else\n\n)\ntest",
+          "Some::StandardError (this is a normal message)\ntest",
-        "web-exception",
+          "web-exception",
-      )
+        )
 
-      output.rewind
+        output.rewind
-      parsed = JSON.parse(output.read.chomp)
+        parsed = JSON.parse(output.read.chomp)
 
-      expect(parsed["exception.class"]).to eq("Some::StandardError")
+        expect(parsed["exception.class"]).to eq("Some::StandardError")
-      expect(parsed["exception.message"]).to eq("some error message\n\nsomething else")
+        expect(parsed["exception.message"]).to eq("this is a normal message")
+      end
+
+      it "logs a JSON string with the `exception_class` and `exception_message` fields when the exception message contains newlines" do
+        logger = described_class.logger(logdev: output, type: "test")
+
+        logger.add(
+          Logger::ERROR,
+          "Some::StandardError (\n\nsome error message\n\nsomething else\n\n)\ntest",
+          "web-exception",
+        )
+
+        output.rewind
+        parsed = JSON.parse(output.read.chomp)
+
+        expect(parsed["exception.class"]).to eq("Some::StandardError")
+        expect(parsed["exception.message"]).to eq("some error message\n\nsomething else")
+      end
+
+      described_class::ALLOWED_HEADERS_FROM_ENV.each do |header|
+        it "includes `#{header}` from `env` keyword argument in the logged JSON string" do
+          logger.add(
+            Logger::ERROR,
+            lograge_logstash_formatter_formatted_message,
+            "web-exception",
+            env: {
+              header => "header",
+            },
+          )
+
+          output.rewind
+          parsed = JSON.parse(output.read.chomp)
+
+          expect(parsed["request.headers.#{header.downcase}"]).to eq("header")
+        end
+      end
+
+      it "does not include keys from `env` keyword argument in the logged JSOn string which are not in the allow list" do
+        logger.add(
+          Logger::ERROR,
+          lograge_logstash_formatter_formatted_message,
+          "web-exception",
+          env: {
+            "SOME_RANDOM_HEADER" => "header",
+          },
+        )
+
+        output.rewind
+        parsed = JSON.parse(output.read.chomp)
+
+        expect(parsed).not_to have_key("request.headers.some_random_header")
+      end
     end
 
     it "logs a JSON string with the right fields when `customize_event` attribute is set" do
@@ -124,56 +190,6 @@ RSpec.describe DiscourseLogstashLogger do
       expect(parsed["backtrace"]).to eq("backtrace")
     end
 
-    described_class::ALLOWED_HEADERS_FROM_ENV.each do |header|
-      it "does not include `#{header}` from `env` keyword argument in the logged JSON string when severity is less than `Logger::WARN`" do
-        logger.add(
-          Logger::INFO,
-          lograge_logstash_formatter_formatted_message,
-          nil,
-          env: {
-            header => "header",
-          },
-        )
-
-        output.rewind
-        parsed = JSON.parse(output.read.chomp)
-
-        expect(parsed).not_to have_key("request.headers.#{header.downcase}")
-      end
-
-      it "includes `#{header}` from `env` keyword argument in the logged JSON string when severity is at least `Logger::WARN`" do
-        logger.add(
-          Logger::ERROR,
-          lograge_logstash_formatter_formatted_message,
-          nil,
-          env: {
-            header => "header",
-          },
-        )
-
-        output.rewind
-        parsed = JSON.parse(output.read.chomp)
-
-        expect(parsed["request.headers.#{header.downcase}"]).to eq("header")
-      end
-    end
-
-    it "does not include keys from `env` keyword argument in the logged JSOn string which are not in the allow list" do
-      logger.add(
-        Logger::ERROR,
-        lograge_logstash_formatter_formatted_message,
-        nil,
-        env: {
-          "SOME_RANDOM_HEADER" => "header",
-        },
-      )
-
-      output.rewind
-      parsed = JSON.parse(output.read.chomp)
-
-      expect(parsed).not_to have_key("request.headers.some_random_header")
-    end
-
     it "does not log the event if message matches a pattern configured by `Logster.store.ignore`" do
       original_logster_store_ignore = Logster.store.ignore
       Logster.store.ignore = [/^Some::StandardError/]