Fork me on GitHub

April 9, 2011

Rails.logger is not threadsafe!

Post moved to http://log2.kares.org/post/59891244469/rails-logger-is-not-threadsafe

At least not completely, one might experience strange logging issues especially in JRuby threadsafe! environments: logs show up fine in the beginning but after a while it seems as if logging stopped working and only errors show up.

Blame ActiveSupport::BufferedLogger for not being (completely) thread-safe, let's take a closer look at it's silencing implementation :


Consider there are 2 threads running logger.silence(&block) concurrently. Thread 1 enters the silence blocks and changed the (temporary) level to ERROR. Then thread 2 comes in and changes the level for the block duration but the old_logger_level is now ERROR, as thread 1 changed the level already (and haven't finished executing the block yet). Now suppose thread 1 is done and restores the correct level, next thread 2 finishes and it also restores the "old" level leaving logger.level different then it was before both threads invoked silence !

Now that we understand what's happening, there seem to be 3 options how to fix this :
  1. No silencing: ActiveSupport::BufferedLogger.silencer = false
  2. Setup a new logger instance for every request (thread)
  3. Use a thread-safe "silencable" logger, such as the following:

This actually does more then promised. Would be great if we haven't had to pollute Thread.current, unfortunately there are places where silence is reinvented instead of being delegated to the logger, thus the "crazy" level= writer. In a perfect world a silence tweak would do the job.

Even if one does not use logger.silence and it's siblings such as ActiveRecord::Base.silence explicitly, it might get called by the framework e.g. when a session is being loaded using ActiveRecord::SessionStore. It's best to make sure logging works correctly in a concurrent environment as tracking down production issues when one can not rely on logs is not that simple.

No comments:

Post a Comment