Make Sidekiq timestamps consistently ISO 8601

Previously when an exception occurred in Sidekiq, Sidekiq would export
logs with timestamps (e.g. created_at, enqueued_at) in floating point
seconds, while other jobs would report in ISO 8601 format. This
inconsistency in data types would cause Elasticsearch to drop logs that
did not match the schema type (date in most cases).

This commit moves the responsibility of formatting timestamps to the
Sidekiq JSON formatter where it properly belongs. The job logger now
generates timestamps with floats, just as Sidekiq does. This ensures
that timestamps are manipulated only in one place.

See https://gitlab.com/gitlab-com/gl-infra/infrastructure/issues/8269

changelogs/unreleased/sh-fix-sidekiq-timestamps.yml

+---
+title: Make Sidekiq timestamps consistently ISO 8601
+merge_request: 22750
+author:
+type: fixed

lib/gitlab/sidekiq_logging/json_formatter.rb

@@ -3,6 +3,8 @@
 module Gitlab
   module SidekiqLogging
     class JSONFormatter
+      TIMESTAMP_FIELDS = %w[created_at enqueued_at started_at retried_at failed_at completed_at].freeze
+
       def call(severity, timestamp, progname, data)
         output = {
           severity: severity,
@@ -13,11 +15,27 @@ module Gitlab
         when String
           output[:message] = data
         when Hash
+          convert_to_iso8601!(data)
           output.merge!(data)
         end
 
         output.to_json + "\n"
       end
+
+      private
+
+      def convert_to_iso8601!(payload)
+        TIMESTAMP_FIELDS.each do |key|
+          value = payload[key]
+          payload[key] = format_time(value) if value.present?
+        end
+      end
+
+      def format_time(timestamp)
+        return timestamp unless timestamp.is_a?(Numeric)
+
+        Time.at(timestamp).utc.iso8601(3)
+      end
     end
   end
 end

lib/gitlab/sidekiq_logging/structured_logger.rb

@@ -6,8 +6,6 @@ require 'active_record/log_subscriber'
 module Gitlab
   module SidekiqLogging
     class StructuredLogger
-      START_TIMESTAMP_FIELDS = %w[created_at enqueued_at].freeze
-      DONE_TIMESTAMP_FIELDS = %w[started_at retried_at failed_at completed_at].freeze
       MAXIMUM_JOB_ARGUMENTS_LENGTH = 10.kilobytes
 
       def call(job, queue)
@@ -65,8 +63,6 @@ module Gitlab
           payload['job_status'] = 'done'
         end
 
-        convert_to_iso8601(payload, DONE_TIMESTAMP_FIELDS)
-
         payload['db_duration'] = ActiveRecord::LogSubscriber.runtime
         payload['db_duration_s'] = payload['db_duration'] / 1000
 
@@ -79,7 +75,7 @@ module Gitlab
         # ignore `cpu_s` if the platform does not support Process::CLOCK_THREAD_CPUTIME_ID (time[:cputime] == 0)
         # supported OS version can be found at: https://www.rubydoc.info/stdlib/core/2.1.6/Process:clock_gettime
         payload['cpu_s'] = time[:cputime].round(6) if time[:cputime] > 0
-        payload['completed_at'] = Time.now.utc
+        payload['completed_at'] = Time.now.utc.to_f
       end
 
       def parse_job(job)
@@ -91,17 +87,9 @@ module Gitlab
         job.delete('args') unless ENV['SIDEKIQ_LOG_ARGUMENTS']
         job['args'] = limited_job_args(job['args']) if job['args']
 
-        convert_to_iso8601(job, START_TIMESTAMP_FIELDS)
-
         job
       end
 
-      def convert_to_iso8601(payload, keys)
-        keys.each do |key|
-          payload[key] = format_time(payload[key]) if payload[key]
-        end
-      end
-
       def elapsed(t0)
         t1 = get_time
         {
@@ -121,12 +109,6 @@ module Gitlab
         Gitlab::Metrics::System.monotonic_time
       end
 
-      def format_time(timestamp)
-        return timestamp if timestamp.is_a?(String)
-
-        Time.at(timestamp).utc.iso8601(3)
-      end
-
       def limited_job_args(args)
         return unless args.is_a?(Array)
 

spec/lib/gitlab/sidekiq_logging/json_formatter_spec.rb

@@ -3,28 +3,53 @@
 require 'spec_helper'
 
 describe Gitlab::SidekiqLogging::JSONFormatter do
-  let(:hash_input) { { foo: 1, bar: 'test' } }
   let(:message) { 'This is a test' }
-  let(:timestamp) { Time.now }
-
-  it 'wraps a Hash' do
-    result = subject.call('INFO', timestamp, 'my program', hash_input)
-
-    data = JSON.parse(result)
-    expected_output = hash_input.stringify_keys
-    expected_output['severity'] = 'INFO'
-    expected_output['time'] = timestamp.utc.iso8601(3)
-
-    expect(data).to eq(expected_output)
+  let(:now) { Time.now }
+  let(:timestamp) { now.utc.to_f }
+  let(:timestamp_iso8601) { now.iso8601(3) }
+
+  describe 'with a Hash' do
+    let(:hash_input) do
+      {
+        foo: 1,
+        'bar' => 'test',
+        'created_at' => timestamp,
+        'enqueued_at' => timestamp,
+        'started_at' => timestamp,
+        'retried_at' => timestamp,
+        'failed_at' => timestamp,
+        'completed_at' => timestamp_iso8601
+      }
+    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',
+          'time' => timestamp_iso8601,
+          'created_at' => timestamp_iso8601,
+          'enqueued_at' => timestamp_iso8601,
+          'started_at' => timestamp_iso8601,
+          'retried_at' => timestamp_iso8601,
+          'failed_at' => timestamp_iso8601,
+          'completed_at' => timestamp_iso8601
+        }
+      )
+
+      expect(data).to eq(expected_output)
+    end
   end
 
   it 'wraps a String' do
-    result = subject.call('DEBUG', timestamp, 'my string', message)
+    result = subject.call('DEBUG', now, 'my string', message)
 
     data = JSON.parse(result)
     expected_output = {
       severity: 'DEBUG',
-      time: timestamp.utc.iso8601(3),
+      time: timestamp_iso8601,
       message: message
     }
 

spec/lib/gitlab/sidekiq_logging/structured_logger_spec.rb

@@ -30,8 +30,8 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: start',
         'job_status' => 'start',
         'pid' => Process.pid,
-        'created_at' => created_at.iso8601(3),
-        'enqueued_at' => created_at.iso8601(3),
+        'created_at' => created_at.to_f,
+        'enqueued_at' => created_at.to_f,
         'scheduling_latency_s' => scheduling_latency_s
       )
     end
@@ -40,7 +40,7 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
         'message' => 'TestWorker JID-da883554ee4fe414012f5f42: done: 0.0 sec',
         'job_status' => 'done',
         'duration' => 0.0,
-        'completed_at' => timestamp.iso8601(3),
+        'completed_at' => timestamp.to_f,
         'cpu_s' => 1.111112,
         'db_duration' => 0,
         'db_duration_s' => 0
@@ -227,17 +227,17 @@ describe Gitlab::SidekiqLogging::StructuredLogger do
   describe '#add_time_keys!' do
     let(:time) { { duration: 0.1231234, cputime: 1.2342345 } }
     let(:payload) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status' } }
-    let(:current_utc_time) { '2019-09-23 10:00:58 UTC' }
-    let(:payload_with_time_keys) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status', 'duration' => 0.123123, 'cpu_s' => 1.234235, 'completed_at' => current_utc_time } }
+    let(:current_utc_time) { Time.now.utc }
+    let(:payload_with_time_keys) { { 'class' => 'my-class', 'message' => 'my-message', 'job_status' => 'my-job-status', 'duration' => 0.123123, 'cpu_s' => 1.234235, 'completed_at' => current_utc_time.to_f } }
 
     subject { described_class.new }
 
     it 'update payload correctly' do
-      expect(Time).to receive_message_chain(:now, :utc).and_return(current_utc_time)
+      Timecop.freeze(current_utc_time) do
+        subject.send(:add_time_keys!, time, payload)
 
-      subject.send(:add_time_keys!, time, payload)
-
-      expect(payload).to eq(payload_with_time_keys)
+        expect(payload).to eq(payload_with_time_keys)
+      end
     end
   end
 end