Stringify Sidekiq job args in exception logs

If these logs are sent to Elasticsearch, it will not be able to process
nested object fields, as this causes a type mismatch with scalar
elements in the same array across log lines.

This was done in
https://gitlab.com/gitlab-org/gitlab/-/merge_requests/26267, but that
change did not apply to Sidekiq exceptions.

We also move all Sidekiq agument formatting into the JSON formatter.
This puts the formatting of job logs in one place and avoids the
pitfalls of altering job arguments in the actual payload.

Closes https://gitlab.com/gitlab-org/gitlab/-/issues/213639

changelogs/unreleased/sh-flatten-sidekiq-exception-logs.yml

+---
+title: Stringify Sidekiq job args in exception logs
+merge_request: 28996
+author:
+type: fixed

lib/gitlab/sidekiq_logging/json_formatter.rb

@@ -19,6 +19,7 @@ module Gitlab
           output[:message] = data
         when Hash
           convert_to_iso8601!(data)
+          stringify_args!(data)
           output.merge!(data)
         end
 
@@ -39,6 +40,10 @@ module Gitlab
 
         Time.at(timestamp).utc.iso8601(3)
       end
+
+      def stringify_args!(payload)
+        payload['args'] = Gitlab::Utils::LogLimitedArray.log_limited_array(payload['args'].map(&:to_s)) if payload['args']
+      end
     end
   end
 end

lib/gitlab/sidekiq_logging/logs_jobs.rb

@@ -7,6 +7,7 @@ module Gitlab
         "#{payload['class']} JID-#{payload['jid']}"
       end
 
+      # NOTE: Arguments are truncated/stringified in sidekiq_logging/json_formatter.rb
       def parse_job(job)
         # Error information from the previous try is in the payload for
         # displaying in the Sidekiq UI, but is very confusing in logs!
@@ -16,7 +17,6 @@ module Gitlab
         job['pid'] = ::Process.pid
 
         job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
-        job['args'] = Gitlab::Utils::LogLimitedArray.log_limited_array(job['args'].map(&:to_s)) if job['args']
 
         job
       end

spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb

@@ -9,6 +9,8 @@ describe Gitlab::SidekiqLogging::JSONFormatter do
   let(:timestamp_iso8601) { now.iso8601(3) }
 
   describe 'with a Hash' do
+    subject { JSON.parse(described_class.new.call('INFO', now, 'my program', hash_input)) }
+
     let(:hash_input) do
       {
         foo: 1,
@@ -23,9 +25,6 @@ describe Gitlab::SidekiqLogging::JSONFormatter do
     end
 
     it 'properly formats timestamps into ISO 8601 form' do
-      result = subject.call('INFO', now, 'my program', hash_input)
-
-      data = JSON.parse(result)
       expected_output = hash_input.stringify_keys.merge!(
         {
           'severity' => 'INFO',
@@ -39,20 +38,39 @@ describe Gitlab::SidekiqLogging::JSONFormatter do
         }
       )
 
-      expect(data).to eq(expected_output)
+      expect(subject).to eq(expected_output)
+    end
+
+    context 'when the job args are bigger than the maximum allowed' do
+      it 'keeps args from the front until they exceed the limit' do
+        half_limit = Gitlab::Utils::LogLimitedArray::MAXIMUM_ARRAY_LENGTH / 2
+        hash_input['args'] = [1, 2, 'a' * half_limit, 'b' * half_limit, 3]
+
+        expected_args = hash_input['args'].take(3).map(&:to_s) + ['...']
+
+        expect(subject['args']).to eq(expected_args)
+      end
+    end
+
+    it 'properly flattens arguments to a String' do
+      hash_input['args'] = [1, "test", 2, { 'test' => 1 }]
+
+      expect(subject['args']).to eq(["1", "test", "2", %({"test"=>1})])
     end
   end
 
-  it 'wraps a String' do
-    result = subject.call('DEBUG', now, 'my string', message)
+  describe 'with a String' do
+    it 'accepts strings with no changes' do
+      result = subject.call('DEBUG', now, 'my string', message)
 
-    data = JSON.parse(result)
-    expected_output = {
-      severity: 'DEBUG',
-      time: timestamp_iso8601,
-      message: message
-    }
+      data = JSON.parse(result)
+      expected_output = {
+        severity: 'DEBUG',
+        time: timestamp_iso8601,
+        message: message
+      }
 
-    expect(data).to eq(expected_output.stringify_keys)
+      expect(data).to eq(expected_output.stringify_keys)
+    end
   end
 end

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -30,7 +30,6 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
     let(:clock_thread_cputime_end) { 1.333333799 }
     let(:start_payload) do
       job.except('error_backtrace', 'error_class', 'error_message').merge(
-        'args' => %w(1234 hello {"key"=>"value"}),
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
         'job_status' => 'start',
         'pid' => Process.pid,
@@ -113,24 +112,6 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
           end
         end
       end
-
-      context 'when the job args are bigger than the maximum allowed' do
-        it 'keeps args from the front until they exceed the limit' do
-          Timecop.freeze(timestamp) do
-            half_limit = Gitlab::Utils::LogLimitedArray::MAXIMUM_ARRAY_LENGTH / 2
-            job['args'] = [1, 2, 'a' * half_limit, 'b' * half_limit, 3]
-
-            expected_args = job['args'].take(3).map(&:to_s) + ['...']
-
-            expect(logger).to receive(:info).with(start_payload.merge('args' => expected_args)).ordered
-            expect(logger).to receive(:info).with(end_payload.merge('args' => expected_args)).ordered
-            expect(subject).to receive(:log_job_start).and_call_original
-            expect(subject).to receive(:log_job_done).and_call_original
-
-            subject.call(job, 'test_queue') { }
-          end
-        end
-      end
     end
 
     context 'with SIDEKIQ_LOG_ARGUMENTS disabled' do