Sidekiq logging is missing context information

[prikha]

Following the readme I`ve added semantic logger to Sidekiq.

Sidekiq::Logging.logger = SemanticLogger[Sidekiq] if defined?(Sidekiq)

And it occurred that i`ve lost the most valuable data - worker class name.

The log before:

2017-02-12T19:18:43.908Z 22548 TID-osbolpr4g SomeWorker JID- INFO: start 2017-02-12T19:18:43.912Z 22548 TID-osbolpr4g SomeWorker JID- INFO: done: 0.003 sec

The log after:

{"name":"Sidekiq","pid":19857,"thread":"47328718486600","level":"info","level_index":2,"host":"web01","application":"Semantic Logger","message":"start","timestamp":"2017-02-12T19:32:00.599277Z"} {"name":"Sidekiq","pid":19857,"thread":"47328718486600","level":"info","level_index":2,"host":"web01","application":"Semantic Logger","message":"done: 0.002 sec","timestamp":"2017-02-12T19:32:00.601137Z"}

Is there a known way to capture the name of the calling worker class. Or maybe we should provider some facilities for such a broad use-case?

[reidmorrison]

It looks like Sidekiq tries to add context information in its own way and does not use builtin features such as tags to add context to log entries.

Recommend patching the Sidekiq logging class using an initializer and make it use tags instead of a custom tags mechanism.

Then you can also get rid of the string output, and log the individual elements as json attributes that do not have to be parsed by the centralized log system.

Have you looked at RocketJob ? It has complete support for Semantic Logger built-in from the ground up. It logs each classes name along with the duration of each task, etc..

[prikha]

Thanks for support!

Got it, RocketJob looks very promising. To be fair you should include Sidekiq Pro feature in the comparision table.

Went with a sample like this

# config/initializers/sidekiq.rb
module Sidekiq
  module Middleware
    module Server
      class Logging
        SPACE = ' '.freeze

        def call(worker, item, queue)
          Sidekiq::Logging.with_context(log_context(worker, item)) do
            # Apply payload to semantic logger
            # * we are loosing formatter capabilities
            logger.with_payload(log_payload(worker, item)) do
              begin
                start = Time.now
                logger.info("start".freeze)
                yield
                logger.info("done: #{elapsed(start)} sec")
              rescue Exception
                logger.info("fail: #{elapsed(start)} sec")
                raise
              end
            end
          end
        end

        private

        # If we're using a wrapper class, like ActiveJob, use the "wrapped"
        # attribute to expose the underlying thing.
        def log_context(worker, item)
          klass = item['wrapped'.freeze] || worker.class.to_s
          "#{klass} JID-#{item['jid'.freeze]}#{" BID-#{item['bid'.freeze]}" if item['bid'.freeze]}"
        end

        # This additional method formats context as payload
        def log_payload(worker, item)
          {
            class_name: item['wrapped'.freeze] || worker.class.to_s,
            jid: item['jid'.freeze],
            tid: Thread.current.object_id.to_s(36),
            context: context
          }
        end

        def context
          c = Thread.current[:sidekiq_context]
          " #{c.join(SPACE)}" if c && c.any?
        end

        def elapsed(start)
          (Time.now - start).round(3)
        end

        def logger
          Sidekiq.logger
        end
      end
    end
  end
end

[reidmorrison]

Thanks for the code extract, happy to hear it works now.

By supporting RocketJob Pro you will also be supporting the development efforts on Semantic Logger and Symmetric Encryption.

[gingerlime]

@prikha thanks for the snippet. Is this something that can be contributed to Sidekiq? so it generically works with "plain" logs as well more sophisticated ones, like SemanticLogger or maybe others?

(are tags something common to all loggers? or something specific to SemanticLogger)?

[gingerlime]

p.s. I hope that any rivalry between Sidekiq and RocketJob can be put aside for the purpose of better logging, irrespective of which product / logger is used ;-)

[prikha]

@gingerlime Hi, I had a quick run over sidekiq logging code - it seems very specific to what they are doing. Generalizing it for better logging solutions(better than plain ruby logger) should be a right direction imho.

However tagged logging is being introduced by ActiveSupport which is required by rails. Sidekiq itself has nothing to do with rails.

For me it seems there are plenty of options like message formatting which is done right. It would be great to have an opportunity to define not a custom formatter, but a block of code which consumes all message events and actually calls logger(in all its variety).

Anyway - there is not a right place for that discussion. We may open an issue at relevant repo.

[gingerlime]

Thanks @prikha ... I'm not sure I completely understand what's the best way forward here.

Regardless if Sidekiq isn't super-flexible with custom loggers, I still wonder why, if I just want a plain-text file log output, I would somehow lose some of the context info that Sidekiq outputs. And with any other logger, it just works out-of-the-box (right?)

[gingerlime]

@prikha @reidmorrison sorry to bother you guys, but I'm looking at some examples, but can't quite wrap my head around it fully.

If I look at the JSON formatter, then the usage section says I should assign the formatter to the sidekiq logger. The formatter itself inherits from Sidekiq's Pretty formatter, which outputs everything as a string.

However, when I try to use the standard pretty formatter by assigning it, SemanticLogger either doesn't use it, or ignores it? I don't see all the info I'd expect in my logs

# config/initializers/sidekiq.rb
Sidekiq.logger.formatter = Sidekiq::Logging::Pretty.new

log output:

2017-04-05 11:51:54.650201 I [4391:47191573070460] Sidekiq -- start
2017-04-05 11:51:55.381212 I [4391:47191573070460] Sidekiq -- done: 0.731 sec

Without SemanticLogger

2017-04-05T09:16:01.343Z 18637 TID-1f5h70 ClassName JID-936bd16c703db2ffbc9b2b5a INFO: start
2017-04-05T09:16:05.392Z 18637 TID-1f5h70 ClassName JID-936bd16c703db2ffbc9b2b5a INFO: done: 4.049 sec

I can create a middleware like @prikha suggested, or using Rails tags similar to this?

But I just wonder where's the conflict, or why the full log record isn't logged correctly by default? when I'm using the logging-rails gem, and lograge, it "just works" with those. So why can't this happen with Semantic Logger?

... sorry if it's a silly question, but I'm genuinely confused about how this all fits together, or doesn't as the case might be ;-)

[reidmorrison]

Sidekiq creates its own custom logger that is not compatible with standard loggers. The only way around it is to "monkey-patch" sidekiq as per the example above to use semantic logger instead of using its own custom logger.

If Sidekiq followed either Semantic Logger or the built-in Rails logger approach of using logger.tagged for tagged logging then this would not be an issue.

[gingerlime]

@reidmorrison regarding tagged, as far as I understand from @prikha, then this is a rails feature, and therefore I can see why it wouldn't use it by default.

Correct me if I'm wrong, but the sidekiq logger is compatible with the Ruby Logger (at least according to the wiki page), and it does work with other logging libraries, doesn't it?

Is there a change to the sidekiq logger that would make it compatible with standard loggers? then maybe it's worth submitting a PR to sidekiq to bring this compatibility?

I'm really just trying to understand why or what's not compatible and hopefully find a way for SemanticLogger and Sidekiq logger to work together "out of the box" if possible.

[gingerlime]

This is what I'm using now (similar to the snippet above, but slightly different), and it seems to work with rails using logger.tagged, but I still hope there's some reasonable change somewhere that would make it work out-of-the-box...

module Sidekiq
  module Middleware
    module Server
      class TaggedLogging
        SPACE = ' '.freeze

        def call(worker, item, _queue)
          logger.tagged(log_context(worker, item)) do
            begin
              start = Time.zone.now
              logger.info('start'.freeze)
              yield
              logger.info("done: #{elapsed(start)} sec")
            rescue Exception
              logger.info("fail: #{elapsed(start)} sec")
              raise
            end
          end
        end

        private

        # If we're using a wrapper class, like ActiveJob, use the "wrapped"
        # attribute to expose the underlying thing.
        def log_context(worker, item)
          klass = item['wrapped'.freeze] || worker.class.to_s
          "#{klass} JID-#{item['jid'.freeze]}#{" BID-#{item['bid'.freeze]}" if item['bid'.freeze]}"
        end

        def context
          c = Thread.current[:sidekiq_context]
          " #{c.join(SPACE)}" if c && c.any?
        end

        def elapsed(start)
          (Time.zone.now - start).round(3)
        end

        def logger
          Sidekiq.logger
        end
      end
    end
  end
end

Sidekiq.configure_server do |config|
  config.server_middleware do |chain|
    chain.add Sidekiq::Middleware::Server::TaggedLogging
  end
end

[Silex]

Ok, I confirm the Sidekiq logger is weird. If you replace it by Logger.new('testfile.log'), this is what gets logged:

I, [2017-07-20T16:46:27.359965 #14]  INFO -- : Running in ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-linux]
I, [2017-07-20T16:46:27.360022 #14]  INFO -- : See LICENSE and the LGPL-3.0 for licensing details.
I, [2017-07-20T16:46:27.360037 #14]  INFO -- : Upgrade to Sidekiq Pro for more features and support: http://sidekiq.org
I, [2017-07-20T16:46:27.361560 #14]  INFO -- : Starting processing, hit Ctrl-C to stop
I, [2017-07-20T16:46:27.307104 #15]  INFO -- : start
I, [2017-07-20T16:46:27.732218 #15]  INFO -- : done: 0.425 sec

So, all information is lost with regular Logger as well. Recently there was a way to customize the job logger class, investiguating atm.

EDIT: okay basically with Sidekiq you are supposed to use a custom format in order to get things logged:

"#{time.utc.iso8601} #{Process.pid} TID-#{Thread.current.object_id.to_s(36)}#{context} #{severity}: #{message}\n"

[lacco]

Based on @gingerlime 's idea, I was able to customize the logging via overwriting Sidekiq::JobLogger:

class CustomSidekiqJobLogger < Sidekiq::JobLogger
  def call(item, queue, &block)
    logger.tagged(*context_tags(item)) do
      super(item, queue, &block)
    end
  end

  private

  def context_tags(item)
    [
      item['jid'],
      item['class']
    ]
  end

  def logger
    Rails.logger
  end
end

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

[prdanelli]

For anyone else finding this thread, none of the solutions offered here or https://github.com/rocketjob/semantic_logger/issues/80 worked for me.

Semantic logger was preventing Sidekiq from outputting anything at all.

I added Sidekiq.logger = Logger.new(STDOUT) in initializers/sidekiq.rb to force Sidekiq to use the default logger to fix the issue.

[gingerlime]

I'm still playing around with this, but with Sidekiq 6.0.1 @lacco example can be boiled down to

class TaggedJobLogger < Sidekiq::JobLogger
  def call(item, queue)
    @logger.tagged(Sidekiq::Context.current) do
      super(item, queue)
    end
  end
end

...

Sidekiq.configure_server do |config|
  ...

  config.options[:job_logger] = TaggedJobLogger

  ...
end

@bobvanderlinden is this more or less what you had in mind ?

[bobvanderlinden]

Yes, indeed. I was thinking it might be nice to use such a tagged logger for Sidekiq by default.

[ixti]

Notice, that Sidekiq.logger = SemanticLogger[Sidekiq] extends given logger with Sidekiq::LoggingUtils. That module provides #log_at (similar to SemanticLogger#silence, and that is used by JobLogger if job payload includes log_level) and #add method that relies on @logdev instance variable...