Logging

Sidekiq is a multi-threaded system which means you have a lot of things happening concurrently. To make for easier debugging in that type of environment, Sidekiq uses a custom logger which outputs additional information:

UTC Timestamp----------- PID------ Thread----- JobType--------- JID------------------------- More...
2019-08-31T15:36:07.569Z pid=82859 tid=11cy9br class=HardWorker jid=528f1b0ddc4a9d0690464fe4 INFO: start
2019-08-31T15:36:07.573Z pid=82859 tid=119pz7z class=HardWorker jid=b7f805c545c78770d30dc1fd elapsed=0.089 INFO: done
2019-08-31T15:36:07.573Z pid=82859 tid=119pz7z class=HardWorker jid=16925b0f545a15a75d391f3b INFO: start
2019-08-31T15:36:07.576Z pid=82859 tid=119py7b class=HardWorker jid=398d4bc5563b1f1b4cce846d elapsed=0.089 INFO: done
2019-08-31T15:36:07.585Z pid=82859 tid=11cy98z class=HardWorker jid=fe849e00b8371b33a1e8f16f elapsed=0.081 INFO: done
2019-08-31T15:36:07.586Z pid=82859 tid=119puzr class=HardWorker jid=7cdac3a6c25d13233bfb3f00 elapsed=0.076 INFO: done
2019-08-31T15:36:07.587Z pid=82859 tid=11cy8t7 class=HardWorker jid=ec7e77e8b1013659469d96fa elapsed=0.072 INFO: done

The Sidekiq process logs only to STDOUT. This is the way modern daemons should work.

All timestamps are in UTC. Timezones suck.

Logger

Sidekiq.configure_server do |config|
  config.logger = Sidekiq::Logger.new($stdout)
end

I recommend you log to STDOUT and let systemd or your process manager collect and rotate the log output. Don't replace Sidekiq's logger just to log directly to a file.

Writing to the log

Jobs can use logger.

class YourJob
  include Sidekiq::Job

  def perform(*args)
    logger.info "Things are happening."
    logger.debug { "My args: #{args.inspect}" }
  end
end

Log Redirection

As of Sidekiq 6.0, Sidekiq does not directly support log redirection. Your process manager should have a way to redirect log output or you can use redirection via shell to redirect Sidekiq's output to the logger UNIX command to send it to syslog with a 'sidekiq' tag (ideally this should be done via systemd instead).

bundle exec sidekiq 2>&1 | logger -t sidekiq

This will not work correctly with Upstart. If using Upstart, take a look at this issue.

Default logger and verboseness

Sidekiq defaults to using Ruby's standard library Logger. Log levels thus follow the stdlib documentation.

In production environments, a log level of INFO may be too verbose for your needs. For quieter logs that use less disk space, you can change the log level to only show WARN and higher:

Sidekiq.configure_server do |config|
  config.logger.level = Logger::WARN
end

Per worker log level

If you need to adjust the log level for a specific worker:

class YourJob
  include Sidekiq::Job

  sidekiq_options log_level: :warn
end

Output Format

Sidekiq's logger has configurable formatters; you can enable the optional JSON format if, for example, you are sending log output to Elasticache for indexing:

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

Results:

$ bundle exec sidekiq
{"ts":"2019-09-01T22:34:59.778Z","pid":90069,"tid":"104v8ph","lvl":"INFO","msg":"Running in ruby 2.5.1p57 (2018-03-29 revision 63029) [x86_64-darwin17]"}
{"ts":"2019-09-01T22:34:59.778Z","pid":90069,"tid":"104v8ph","lvl":"INFO","msg":"See LICENSE and the LGPL-3.0 for licensing details."}
{"ts":"2019-09-01T22:34:59.778Z","pid":90069,"tid":"104v8ph","lvl":"INFO","msg":"Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org"}
{"ts":"2019-09-01T22:34:59.778Z","pid":90069,"tid":"104v8ph","lvl":"INFO","msg":"Booting Sidekiq 6.0.0 with redis options {:id=>\"Sidekiq-server-PID-90069\", :url=>nil}"}
{"ts":"2019-09-01T22:34:59.807Z","pid":90069,"tid":"104v8ph","lvl":"INFO","msg":"Starting processing, hit Ctrl-C to stop"}

See sidekiq/logger for implementation details. To define a custom log format, for example one that changes the JSON keys, add the following to your Sidekiq configuration file:

module Sidekiq
  class Logger < ::Logger
    module Formatters
      class CustomJson < Base
        def call(severity, time, program_name, message)
          hash = {
            '@timestamp': time.utc.iso8601(3),
            pid: ::Process.pid,
            tid: tid,
            level: severity,
            message: message,
            origin: "sidekiq",
          }
          c = ctx
          hash["ctx"] = c unless c.empty?
          Sidekiq.dump_json(hash) << "\n"
        end
      end
    end
  end
end

# ...

Sidekiq.configure_server do |config|
  config.logger = Logger.new(STDOUT)
  config.logger.formatter = Sidekiq::Logger::Formatters::CustomJson.new
  # other config here
end

Skipping default job logging

As of v7.3.0, you can skip Sidekiq's default start/finish job logging.

Sidekiq.configure_server do |config|
  config[:skip_default_job_logging] = true
end

Backtrace Cleaning

You can provide a backtrace cleaner for any backtraces which go through Sidekiq's global exception handlers like this:

Sidekiq.configure_server do |config|
  config[:backtrace_cleaner] = ->(bt) { bt[0..5] }
end

API Changes

The old Sidekiq::Logging class was removed in Sidekiq 6.0. You should not be accessing any Sidekiq internal classes to use the logger. Use logger directly in your jobs or use Sidekiq.logger elsewhere.

Previous: Middleware Next: Signals