Merge branch 'sh-flatten-sidekiq-exception-logs' into 'master'

Stringify Sidekiq job args in exception logs

Closes #213639

See merge request gitlab-org/gitlab!28996

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