diff --git a/lib/audit_log/audit_log/formatter.rb b/lib/audit_log/audit_log/formatter.rb index f4fe1303b..9837c8f12 100644 --- a/lib/audit_log/audit_log/formatter.rb +++ b/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,8 +23,20 @@ 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) @@ -31,14 +44,24 @@ def merge_message(payload, msg) 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 diff --git a/test/lib/audit_log/formatter_test.rb b/test/lib/audit_log/formatter_test.rb index 79705a11c..94a29ea4f 100644 --- a/test/lib/audit_log/formatter_test.rb +++ b/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