From cf91669e8b66c884a3a1ec8cfa15b649164592c4 Mon Sep 17 00:00:00 2001 From: Daria Mayorova Date: Thu, 25 May 2023 23:39:08 +0200 Subject: [PATCH 1/4] Log sidekiq worker arguments --- config/initializers/sidekiq.rb | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/config/initializers/sidekiq.rb b/config/initializers/sidekiq.rb index b1cfa5a266..eaf5c00d6a 100644 --- a/config/initializers/sidekiq.rb +++ b/config/initializers/sidekiq.rb @@ -3,6 +3,7 @@ require 'three_scale/sidekiq_retry_support' require 'three_scale/sidekiq_logging_middleware' require 'sidekiq/throttled' +require 'sidekiq/logging' Sidekiq::Throttled.setup! @@ -49,3 +50,19 @@ chain.add ThreeScale::SidekiqLoggingMiddleware end end + +module Sidekiq + module Logging + # override existing log to include the arguments passed to `perform` + # source: https://github.com/sidekiq/sidekiq/issues/1786#issuecomment-313461945 + # NOTE: needs to be changed after upgrading to Sidekiq 6 + def self.job_hash_context(job_hash) + # If we're using a wrapper class, like ActiveJob, use the "wrapped" + # attribute to expose the underlying thing. + klass = job_hash['wrapped'] || job_hash['class'] + bid = job_hash['bid'] + args = job_hash['args'] + "#{klass} JID-#{job_hash['jid']}#{" BID-#{bid}" if bid}#{" ARGS-#{args}" if args}" + end + end +end From 79e97d6c08739b1aa25872845836afe09b7a1f82 Mon Sep 17 00:00:00 2001 From: Daria Mayorova Date: Mon, 29 May 2023 13:02:37 +0200 Subject: [PATCH 2/4] WIP Adding a test --- test/unit/sidekiq_initializer_test.rb | 24 ++++++++++++++++++++++++ 1 file changed, 24 insertions(+) create mode 100644 test/unit/sidekiq_initializer_test.rb diff --git a/test/unit/sidekiq_initializer_test.rb b/test/unit/sidekiq_initializer_test.rb new file mode 100644 index 0000000000..f2e965e504 --- /dev/null +++ b/test/unit/sidekiq_initializer_test.rb @@ -0,0 +1,24 @@ +require 'test_helper' +require 'sidekiq/manager' + +class SidekiqInitializerTest < ActiveSupport::TestCase + + test 'log job arguments' do + options = {:queues => ['default']} + + logger = Sidekiq.logger = Sidekiq::Logging.initialize_logger + + mgr = Sidekiq::Manager.new(options) + processor = ::Sidekiq::Processor.new(mgr) + + invoice = FactoryBot.create(:invoice) + + msg = Sidekiq.dump_json({ 'class' => InvoiceFriendlyIdWorker.to_s, 'args' => [invoice.id] }) + job = Sidekiq::BasicFetch::UnitOfWork.new('queue:default', msg) + processor.send(:process, job) + + # Sidekiq.logger.expects(:info) #.with { |message| message.match("ARGS-[#{invoice.id}]") } + + logger.expects(:info) + end +end From b5615a3b6676b263f7dfebb9a22162c42aa1efff Mon Sep 17 00:00:00 2001 From: "Aleksandar N. Kostadinov" Date: Tue, 30 May 2023 22:17:05 +0300 Subject: [PATCH 3/4] skeleton of sidekiq logging test --- test/unit/sidekiq_initializer_test.rb | 35 +++++++++++++-------------- 1 file changed, 17 insertions(+), 18 deletions(-) diff --git a/test/unit/sidekiq_initializer_test.rb b/test/unit/sidekiq_initializer_test.rb index f2e965e504..6b7f163942 100644 --- a/test/unit/sidekiq_initializer_test.rb +++ b/test/unit/sidekiq_initializer_test.rb @@ -1,24 +1,23 @@ +# frozen_string_literal: true + require 'test_helper' -require 'sidekiq/manager' +require 'sidekiq/testing' class SidekiqInitializerTest < ActiveSupport::TestCase - test 'log job arguments' do - options = {:queues => ['default']} - - logger = Sidekiq.logger = Sidekiq::Logging.initialize_logger - - mgr = Sidekiq::Manager.new(options) - processor = ::Sidekiq::Processor.new(mgr) - - invoice = FactoryBot.create(:invoice) - - msg = Sidekiq.dump_json({ 'class' => InvoiceFriendlyIdWorker.to_s, 'args' => [invoice.id] }) - job = Sidekiq::BasicFetch::UnitOfWork.new('queue:default', msg) - processor.send(:process, job) - - # Sidekiq.logger.expects(:info) #.with { |message| message.match("ARGS-[#{invoice.id}]") } - - logger.expects(:info) + logged = false + ActiveRecord::Base.transaction + SphinxIndexationWorker.stubs(:perform_later) + Rails.logger.stubs(:info).with do |msg| + next(true) if msg.start_with?("[EventBroker] ") + + logged = msg =~ /^Failed to reprocess invoice logo for.*/ + end + + buyer = FactoryBot.create(:buyer_account) + assert logged + Testing.inline! do + BillingWorker.enqueue_for_buyer(buyer, Time.zone.now) + end end end From fedcd2becb1efb090f2edf1a7df32aea88bf46b8 Mon Sep 17 00:00:00 2001 From: Daria Mayorova Date: Wed, 31 May 2023 10:25:02 +0200 Subject: [PATCH 4/4] Update the test --- test/unit/sidekiq_initializer_test.rb | 17 ++++++++--------- 1 file changed, 8 insertions(+), 9 deletions(-) diff --git a/test/unit/sidekiq_initializer_test.rb b/test/unit/sidekiq_initializer_test.rb index 6b7f163942..8e4b3422e8 100644 --- a/test/unit/sidekiq_initializer_test.rb +++ b/test/unit/sidekiq_initializer_test.rb @@ -1,23 +1,22 @@ # frozen_string_literal: true require 'test_helper' -require 'sidekiq/testing' class SidekiqInitializerTest < ActiveSupport::TestCase test 'log job arguments' do logged = false - ActiveRecord::Base.transaction - SphinxIndexationWorker.stubs(:perform_later) + invoice = FactoryBot.create(:invoice) + Rails.logger.stubs(:info).with do |msg| - next(true) if msg.start_with?("[EventBroker] ") + next(true) unless /Enqueued InvoiceFriendlyIdWorker/.match?(msg) - logged = msg =~ /^Failed to reprocess invoice logo for.*/ + logged = msg.include?("with args: [#{invoice.id}]") end - buyer = FactoryBot.create(:buyer_account) - assert logged - Testing.inline! do - BillingWorker.enqueue_for_buyer(buyer, Time.zone.now) + with_sidekiq do + InvoiceFriendlyIdWorker.perform_async(invoice.id) end + + assert logged end end