Message formatting not threadsafe

[mperham]

My testing under heavy concurrency shows that mono_logger has an annoying thread safety issue, likely due to the lock removal.

You can see the output interleaved between two different messages:

2013-04-26T23:31:02Z 19528 TID-ouxe236p8 EmptyWorker JID-6313d8187514753593817627 INFO: done: 0.0 sec
2013-04-26T23:31:02Z 19528 TID-ouxdwfy2w EmptyWorker JID-656eacd91bb014c22cdd851e INFO: start
2013-04-26T23:31:02Z 19528 TID2013-04-26T23:31:02Z 19528 TID-ouxe04kiw EmptyWorker JID-5edfbfb6b6adf427ca29249e INFO: start
-ouxdwfy2w EmptyWorker JID-656eacd91bb014c22cdd851e INFO: done: 0.0 sec
2013-04-26T23:31:02Z 19528 TID-ouxdjc0ig EmptyWorker JID-ac651c5666e575e3c745d367 INFO: start
2013-04-26T23:31:02Z 19528 TID-ouxe00fcc EmptyWorker JID-c7634ee9be49514834f63943 INFO: start

Here's the log formatter that's active:

module Sidekiq
  module Logging
    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

I need to look into the underlying Logger class and see how it is handling the message and formatting.

[mperham]

I can't reproduce this at all when logging to a logfile (either explicitly or by redirecting stdout on the cmd line). Only logging directly to stdout shows the issue. Setting STDOUT.sync = true does not help.

[mperham]

I can't see this being a bug in mono_logger, closing.

[steveklabnik]

Bummer, didn't see this one either.

[steveklabnik]

I'd like to keep this one open until we figure out exactly what's causing it. Even if it's not my fault, I'd like to 1) have an open issue showing there's some sort of issue and 2) figure out who it is so we can fix it.