Sidekiq: Show arguments passed to the worker on the logs

[ezilocchi]

Currently the logs are being displayed like this:

2014-06-17T21:17:02Z 16566 TID-ospmsznzk MyWorker JID-474923f4986cb3dc0a00a007 INFO: start
2014-06-17T21:17:03Z 16566 TID-ospmsznzk MyWorker JID-474923f4986cb3dc0a00a007 INFO: done: 1.491 sec

I would like to show which are the arguments that have been passed to the worker on that execution. So it will be much easier to debug on production
Example:

2014-06-17T21:17:02Z 16566 TID-ospmsznzk MyWorker with { first: 'some value', second: 'another value' } JID-474923f4986cb3dc0a00a007 INFO: start
2014-06-17T21:17:03Z 16566 TID-ospmsznzk MyWorker JID-474923f4986cb3dc0a00a007 INFO: done: 1.491 sec

Based on what I understood from the wiki (https://github.com/mperham/sidekiq/wiki/Logging) the only way of modifying the logging message is replacing the Formatter:

Sidekiq.logger.formatter = MyFormatter.new

But It doesn't receives the actual arguments, only (severity, time, program_name, message):
lib/sidekiq/logging.rb

    class Pretty < Logger::Formatter
      # Provide a call() method that returns the formatted message.
      def call(severity, time, program_name, message)
        "#{time.utc.iso8601} #{Process.pid} TID-#{Thread.current.object_id.to_s(36)}#{context} #{severity}: #{message}\n"
      end

      def context
        c = Thread.current[:sidekiq_context]
        c ? " #{c}" : ''
      end
    end

Is there any way of doing this? I found that probably some work can be done on this other class lib/sidekiq/middleware/server/logging.rb where item contains exactly what I need, but it's not being passed to Sidekiq::Logging where I can override the Sidekiq.logger.formatter:

        def call(worker, item, queue)
          Sidekiq::Logging.with_context("#{worker.class.to_s} JID-#{item['jid']}") do
            begin
              start = Time.now
              logger.info { "start" }
              yield
              logger.info { "done: #{elapsed(start)} sec" }
            rescue Exception
              logger.info { "fail: #{elapsed(start)} sec" }
              raise
            end
          end
        end

Any suggestion?
Thanks

[mperham]

There are several gems which modify Sidekiq's logger one way or another. I'd suggest looking around at a few (gem list -r sidekiq) as I have no plans to add this to Sidekiq core.

[khoan]

@ezilocchi, which gem did you end up using, or did you customize log message when server picks up a job to include args?

FYI warning includes: args in log

2015-03-30T02:03:44.212Z 3 TID-or9azxdfo WARN: {"retry"=>false, "queue"=>"data_default", "class"=>"Bam", "args"=>["54ed06db6235000"], "jid"=>"ecda47e40ee045fc8452239a", "enqueued_at"=>1426933296.3268554}

[ezilocchi]

@khoan To be honest with you, I don't remember quite well. I think that I followed a different approach. And thank you very much, I couldn't find it when I was working on it.

[khoan]

@ezilocchi that's cool. thanks.

[timdorr]

For anyone stumbling across this like me, here's one way you can do it:

require 'sidekiq'
require 'sidekiq/middleware/server/logging'

class ParamsLogging < Sidekiq::Middleware::Server::Logging
  def log_context(worker, item)
    klass = item['wrapped'.freeze] || worker.class.to_s
    "#{klass} (#{item['args'].try(:join, ' ')}) JID-#{item['jid'.freeze]}"
  end
end

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.remove Sidekiq::Middleware::Server::Logging
    chain.add ParamsLogging
  end
end

Note that I'm using ActiveSupport's try in there for some extra safety (I'm not sure if args is ever a nil or other type), so make sure you either have that available or just remove it if I'm wrong.

[Empact]

A small tweak to @timdorr's patch - this relies on super to help ensure you'll pick up future changes to Sidekiq's server logging. In this case including the "BID" in the logging.
https://github.com/mperham/sidekiq/blob/master/lib/sidekiq/middleware/server/logging.rb

require 'sidekiq'
require 'sidekiq/middleware/server/logging'

class ParamsLogging < Sidekiq::Middleware::Server::Logging
  def log_context(worker, item)
    if item['args']
      "#{super} (#{item['args'].map(&:inspect).join(' ')})"
    else
      super
    end
  end
end

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.remove Sidekiq::Middleware::Server::Logging
    chain.add ParamsLogging
  end
end

[heironimus]

@Empact 's changes above no longer work with 5.0. Does anyone have a fix for 5.0?

[Empact]

@heironimus You can override Sidekiq::Logging.job_hash_context, see #3463

[heironimus]

FWIW, here is what I added to my config/initializers/sidekiq.rb for Sidekiq >= 5.0.3

require 'sidekiq'
require 'sidekiq/logging'

module Sidekiq
  module Logging
    # override existing log to include the arguments passed to `perform`
    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'.freeze] || job_hash["class".freeze]
      bid = job_hash['bid'.freeze]
      args = job_hash['args'.freeze]
      "#{klass} #{" ARGS-#{args}" if args} JID-#{job_hash['jid'.freeze]}#{" BID-#{bid}" if bid}"
    end
  end
end

[kurko]

For Sidekiq 6, add the following in config/initializers/sidekiq.rb (@heironimus' snippet above doesn't work anymore):

# Monkey patching Sidekiq logs
module Sidekiq
  class JobLogger

    # For a perform method with args param1 and param2, this will append in the
    # logs,
    #
    # ...  args=(param1=a, param2=b) INFO: start
    #
    def job_hash_context(job_hash)
      # If we're using a wrapper class, like ActiveJob, use the "wrapped"
      # attribute to expose the underlying thing.
      hash = {
        class: job_hash["wrapped"] || job_hash["class"],
        jid: job_hash["jid"],
      }
      hash[:bid] = job_hash["bid"] if job_hash["bid"]
      hash[:tags] = job_hash["tags"] if job_hash["tags"]

      if job_hash["args"].present?
        parameters = hash[:class].constantize.new.method(:perform).parameters
        params_and_values = parameters.each_with_object([]) { |param_keys, params_and_values|
          value = job_hash["args"][params_and_values.count]

          # In case it's too long of a value, truncate it.
          value = "[omitted]" if value.to_s.size > 15

          params_and_values << "#{param_keys[1]}=#{value}"
          params_and_values
        }.join(", ")

        hash[:args] = "(#{params_and_values})"
      end

      hash
    end
  end
end