Merge branch 'sh-fix-sidekiq-timestamps' into 'master'

Make Sidekiq timestamps consistently ISO 8601

Closes #194116

See merge request gitlab-org/gitlab!22750

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