Sidekiq has recently been updated to major version 6, and it includes a bunch of new and interesting features. One that resonated a lot with me was the ability to log in JSON format by default, which is now possible thanks to the newly refactored set of classes that handle logging in the library.

Let’s have a quick look at how to use the new API to do something slightly controversial: logging job arguments.

First of all, a word of advise: logging job arguments is most likely a really bad idea. This is a feature that’s been requested a lot and has always been turned down as it’s a really dangerous thing to do. So if you are thinking of doing this, please make sure you understand the consequences of doing so: depending on the nature of your aguments and where these logs end up in, you may get in trouble very quickly. The last thing you need is to be logging sensitive or private information and sending those logs to the wrong place.

That being said, let’s see how we’d do this in Sidekiq 6.

First of all, enable JSON logging

This is strictly not required, but I am a big fan of JSON structured logging. When used with the right tools it makes logs so much useful, since you can start doing things like indexing and searching for specific fields in logs, rather than having to manually parse log lines.

This is now incredibly easy to do in Sidekiq 6. In your Sidekiq server initialiser, just add this line:

Sidekiq.configure_server do |config|
  config.log_formatter = Sidekiq::Logger::Formatters::JSON.new
end

And job done. No need to monkey patch and no need to use any third party gems anymore.

With this, whenever a job gets run, you’ll get the following log line in STDOUT:

{
    "ts": "2020-07-15T12:02:02.328Z",
    "pid": 23197,
    "tid": "2ert",
    "lvl": "INFO",
    "msg": "start",
    "ctx": {
        "class": "ExampleWorker",
        "jid": "dd3e1c0a1d56a4d31969538b"
    }
}

How to log job arguments

Let’s now get into how to also get the job arguments in that log line. Let’s imagine our worker looks like this:

class ExampleWorker

  include Sidekiq::Worker

  def perform(one_argument, another_argument)
    # write some code that disrupts something
  end
end

One could argue that logging the values of one_argument and another_argument is desirable to debug issues.

Sidekiq has a bunch of new classes in version 6. One of them is the Logger. You would think this is where to look for to add content to your logs, but that’s not the case. By the time Sidekiq has called the Logger class it’s already too late, and in there we have no access at all to the running job or any of its information.

Sidekiq 6 also introduced another class: JobLogger. This class is responsible for extracting any required information from a running job, and sending the relevant log messages to the logger at different stages of its life cycle (namely when the job starts and when it finishes, either successfully or unsuccessfully). And fortunately for us, Sidekiq 6 has been design with modularity in mind when it comes to logging, so we can actually override the JobLogger class in our Sidekiq workers and pass in our own class, which is exactly what we need to do.

Find below a class that inherits from the default JobLogger class and overrides the job_hash_context method:

class SidekiqJobLoggerWithArguments < Sidekiq::JobLogger
  def job_hash_context(job_hash)
    original_hash = super
    begin
      original_hash.merge("arguments" => job_arguments(job_hash))
    rescue
      original_hash
    end
  end

  private

  def job_arguments(job_hash)
    if job_hash.key?("wrapped")
      job_hash["args"].first["arguments"]
    else
      job_hash["args"]
    end
  end
end

What we do here is call super to get the original job context hash, and then we merge that with another hash containing the job arguments, which we can easily get from the job_hash attribute. Note that, similarly to what the JobLogger class does, we need to check where the actual job arguments are, since jobs run via Rails ActiveJob abstraction layer will have this information in a different place than jobs that include the Sidekiq::Worker mixin. I suggest you look at the code for the JobLogger class to fully understand why we have used inheritance and overridden this method.

Once you have this class in your Ruby application, you need to tell Sidekiq to use it instead of the default one:

Sidekiq.configure_server do |config|
  config.options[:job_logger] = SidekiqJobLoggerWithArguments
end

And that’s all, no monkeypatching required! With this in place, when running the following code:

ExampleWorker.perform_later("foo", "bar")

Instead of getting this log:

{
    "ts": "2020-07-15T12:02:02.328Z",
    "pid": 23197,
    "tid": "2ert",
    "lvl": "INFO",
    "msg": "start",
    "ctx": {
        "class": "ExampleWorker",
        "jid": "dd3e1c0a1d56a4d31969538b"
    }
}

We will get this instead:

{
    "ts": "2020-07-15T12:02:02.328Z",
    "pid": 23197,
    "tid": "2ert",
    "lvl": "INFO",
    "msg": "start",
    "ctx": {
        "class": "ExampleWorker",
        "jid": "dd3e1c0a1d56a4d31969538b",
        "arguments": ["foo", "bar"]
    }
}

Use at your own risk :-)