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.
ActiveSupport::BufferedLoggerfor 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
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.leveldifferent then it was before both threads invoked
Now that we understand what's happening, there seem to be 3 options how to fix this :
ActiveSupport::BufferedLogger.silencer = false
- Setup a new logger instance for every request (thread)
- 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
silenceis reinvented instead of being delegated to the logger, thus the "crazy"
level=writer. In a perfect world a
silencetweak would do the job.
Even if one does not use
logger.silenceand it's siblings such as
ActiveRecord::Base.silenceexplicitly, 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.