feat(logging): RHICOMPL-1217 sidekiq evidence for audit log

lib/audit_log/audit_log/formatter.rb

@@ -12,6 +12,7 @@ class Formatter < ManageIQ::Loggers::Container::Formatter
           ALLOWED_PAYLOAD_KEYS = %i[message account_number controller remote_ip
                                     transaction_id].freeze
 
+          # rubocop:disable Metrics/MethodLength
           def call(severity, time, progname, msg)
             payload = {
               '@timestamp': format_datetime(time),
@@ -22,23 +23,45 @@ def call(severity, time, progname, msg)
               level: translate_error(severity),
               account_number: account_number
             }
+            payload.merge!(framework_evidence)
             JSON.generate(merge_message(payload, msg).compact) << "\n"
           end
+          # rubocop:enable Metrics/MethodLength
+
+          def framework_evidence
+            sidekiq_ctx = sidekiq_current_ctx
+            if sidekiq_ctx
+              { controller: sidekiq_ctx[:class],
+                transaction_id: sidekiq_ctx[:jid] }
+            else
+              { transaction_id: rails_transation_id }
+            end
+          end
 
           def merge_message(payload, msg)
             if msg.is_a?(Hash)
               payload.merge!(msg.slice(*ALLOWED_PAYLOAD_KEYS))
             else
               payload[:message] = msg2str(msg)
             end
-            if payload[:transaction_id].blank?
-              payload[:transaction_id] = transaction_id
-            end
             payload
           end
 
           private
 
+          def sidekiq_current_ctx
+            return unless Module.const_defined?(:Sidekiq)
+
+            if ::Sidekiq.const_defined?(:Context)
+              Sidekiq::Context.current
+            else
+              # versions up to 6.0.0
+              Thread.current[:sidekiq_context]
+            end
+          rescue NoMethodError
+            nil
+          end
+
           def format_datetime(time)
             time.utc.strftime('%Y-%m-%dT%H:%M:%S.%6NZ')
           end
@@ -47,7 +70,7 @@ def account_number
             Thread.current[:audit_account_number]
           end
 
-          def transaction_id
+          def rails_transation_id
             ActiveSupport::Notifications.instrumenter.id
           end
         end

test/lib/audit_log/formatter_test.rb

@@ -28,4 +28,50 @@ class AuditLogFormatterTest < ActiveSupport::TestCase
     assert_equal '12345', log_msg['account_number']
     assert_equal '172.1.2.3', log_msg['remote_ip']
   end
+
+  context 'sidekiq' do
+    setup do
+      @test_sidekiq = !Module.const_defined?(:Sidekiq)
+      @sidekiq_module = if @test_sidekiq
+                          Object.const_set('Sidekiq', Module.new)
+                        else
+                          @sidekiq_module = Sidekiq
+                        end
+    end
+
+    teardown do
+      Object.send(:remove_const, :Sidekiq) if @test_sidekiq
+    end
+
+    should 'log sidekiq job id from Sidekiq::Context' do
+      orig_ctx_module = @sidekiq_module.const_defined?(:Context) \
+                         && @sidekiq_module::Context
+      ctx_module = Module.new
+      @sidekiq_module.const_set('Context', ctx_module)
+
+      begin
+        ctx_module.stubs(:current).returns(jid: '123')
+        assert Sidekiq::Context.current
+
+        line = @formatter.call('info', Time.zone.now, 'prog', 'Audit message')
+        log_msg = JSON.parse(line)
+        assert_equal '123', log_msg['transaction_id']
+      ensure
+        @sidekiq_module.send(:remove_const, :Context)
+        @sidekiq_module.const_set('Context', orig_ctx_module) if orig_ctx_module
+      end
+    end
+
+    should 'log sidekiq job id from thread local context' do
+      begin
+        Thread.current[:sidekiq_context] = { jid: '123' }
+
+        line = @formatter.call('info', Time.zone.now, 'prog', 'Audit message')
+        log_msg = JSON.parse(line)
+        assert_equal '123', log_msg['transaction_id']
+      ensure
+        Thread.current[:sidekiq_context] = nil
+      end
+    end
+  end
 end