Logging Sidekiq and Rails

  • 26/5/2020
  • 3-minute read

Sidekiq is an efficient way to process background jobs in ruby. Sidekiq makes use of threads to process multiple jobs at the same time in the same process.

We as developer when something goes wrong we relay on application logs to find out what exactly happens, But in a multithreaded server finding log for a particular job is not an easy task unless you tag it with enough information.

By default sidekiq logs have process id and thread id appended at the start of the logs, you can see them when it start and finish a job.e.g.,

171 <190>1 2020-06-03T17:39:23.478290+00:00 app worker.1 - - 4 TID-gpcol38ws YourAwesomeJobWorker JID-70cae479d8084030b4e3a1fe INFO: start
...
181 <190>1 2020-06-03T17:39:23.555938+00:00 app worker.1 - - 4 TID-gpcol38ws YourAwesomeJobWorker JID-70cae479d8084030b4e3a1fe INFO: done: 0.078 sec

here 4 the process id and TID-gpcol38ws is the thread id.

But all other logs which are logged by Rails.logger instance e.g., ActiveRecord queries log, Mailer logs, etc don’t have any information about job-id or thread-id

To get the job context (JID,TID) in our Rails logs we need to change the formatter for Rails.logger instance. Let’s do this,

Sidekiq.configure_server do |config|
  Rails.logger.formatter = Sidekiq::Logging.logger.formatter 
end

Here we had set Rails.logger.formatter to Sidekiq::Logging.logger.formatter after doing this our Rails logs will something like this,

343 <190>1 2020-06-03T17:57:03.247017+00:00 app worker.1 - - 4 TID-vf0vw YourAwesomeJobWorker JID-b59552097f12abbe8e618704 DEBUG: User Load (1.9ms) SELECT `users`.* FROM `users` WHERE `users`.`id` = 77670112

Now you can filter all logs belong to a particular job together to debug issues in the job.

We still have one problem, we don’t know what is the job-id for you job with specific parameter with which we have some problem e.g., YourAwesomeJobWorker.perform_async(parameters)

To solve this issue we will log job parameters also at the start of our job. To achive this we need to monkey patch Sidekiq::JobLogger#call method like below,

module Sidekiq
  class JobLogger 
    def call(item, queue)
      start = ::Process.clock_gettime(::Process::CLOCK_MONOTONIC)
      item_str = "args:#{item["args"]}, queue:#{item["queue"]}, created_at:#{item["created_at"]}, enqueued_at:#{item["enqueued_at"]}"
      logger.info("start => #{item_str}")
      yield
      logger.info("done: #{elapsed(start)} sec => #{item_str}")
    rescue Exception
      logger.info("fail: #{elapsed(start)} sec => #{item_str}")
      raise
    end
  end
end

After adding it in an initilizer we will get something like this.

294 <190>1 2020-06-03T17:57:03.204317+00:00 app worker.1 - - 4 TID-vf0vw YourAwesomeJobWorker JID-b59552097f12abbe8e618704 INFO: start => args:["parameter1", "parameter2"], queue:default, created_at:1591207023.2046888, enqueued_at:1591207023.2047386

After doing these two steps we will able to find worker logs for any job easily.

Bonus

If you using newrelic you had faced issues when looking for performance problems in backgroud jobs which are enqued with .delay proxy of ActiveJob, Since all jobs enqued with .delay presented as single transaction in new-relic so you don’t get which delayed method taking more time.

To fix this issue we will set custom transaction name based on the Class and method where .delay method get used.


module DelayedExtention
  def perform(yml) #set_newrelic_name for delayed jobs
    (target, method_name, args) = YAML.load(yml)
    target_name = (target.is_a? ActiveRecord::Base) ? "#{target.class.name}#" : "#{target}/"
    NewRelic::Agent.set_transaction_name("#{target_name}#{method_name}")
    target.__send__(method_name, *args)
  end 
end

module MailerDelayedExtention
  def perform(yml)
        (target, method_name, args) = YAML.load(yml)
        NewRelic::Agent.set_transaction_name("#{target}/#{method_name}")
        msg = target.public_send(method_name, *args)
        if msg
          deliver(msg)
        else
          raise "#{target.name}##{method_name} returned an undeliverable mail object"
        end
      end
end
module Sidekiq
  module Extensions
    class DelayedModel
      prepend DelayedExtention 
    end
    class DelayedClass
      prepend DelayedExtention
    end
    class DelayedMailer
      prepend MailerDelayedExtention
    end
  end
end

This will replace Sidekiq::DelayedModel#perform with actual Class and method name.

Related Posts

rails