Rails.logger log level is not thread safe

[rdubya]

We discovered while trying to silence certain of our requests that changing the Rails.logger level is not thread safe. The main issue appears to be that Rails.logger is a singleton. As I started digging through the ActiveSupport::Logger code, I realized that Rails.logger.silence suffers from the same issue we discovered in our codebase.

I have created executable tests displaying the issue here: https://gist.github.com/rdubya/5c3ffb3e49d0c2bd42e9 We discovered the issue in JRuby, but I have gotten the tests in the gist to fail in both JRuby and MRI 2.2.

If you look at the second test case, the worst case scenario is that your log level is permanently changed to whatever level is passed to the call to #silence or ::Logger::ERROR if nothing is passed.

A couple of thoughts that I had for possible solutions:

• Update ActiveSupport::Logger to use thread variables to store the level (could possibly make this an option when the logger is created)
• Create a new class (such as ActiveSupport::ThreadsafeLogger or ActiveSupport::Logger::Threadsafe) which extends ActiveSupport::Logger and uses thread variables to store the level
• Update Rails.logger to optionally maintain separate loggers or log levels for each thread

I'm willing to take a shot at creating a patch for this, but wanted to get an idea of the right direction to head down.

[rafaelfranca]

Yes, it is not thread safe and you should not expect it to be. This is a dup of #16885

[rafaelfranca]

Forget to say, thank you for the report. Also could you test the solution proposed in the linked issue so we can verify it is working?

[rabbitt]

@rafaelfranca: uhmm.. what? why would you not expect your logger to be thread safe? why would you expect anything about rails to not be threadsafe when it's specifically said to be threadsafe. Either don't use a singleton method for logging, or use Thread Locals in your logging class. It's a dead simple fix.

[rafaelfranca]

Is the Ruby logger threadsafe? I don't think so. Is Ruby not threadsafe so? I don't think so.

If you are changing a global state of a class that is shared across threads it is expected to it be not threadsafe and this is exactly this case.

It's a dead simple fix.

Right, it may be, so please, PDI and send a patch, but I'd say that the correct fix is to change Ruby Logger class since Rails just use it.

[rabbitt]

You are correct - the standard Ruby Logger class is not threadsafe, and there's certainly an argument that could be made that it shouldn't care about threadsafety at that low level as it adds unnecessary overhead to something that is used in non-threaded situations as well.

However, that point is made moot by the fact that Rails doesn't use Logger directly - it uses ActiveSupport::Logger which /derives/ from Logger. More to the point, an instance of ::Logger isn't used as a singleton method - ActiveSupport::Logger is. Anyone working with ::Logger knows (or should anyway) that it isn't threadsafe on it's own. If want threadsafety, you need to ensure that in your own use of ::Logger - which is exactly what ActiveSupport::Logger should do.

You can't have it both ways, telling people that rails is threadsafe and then complain about it not being threadsafe because a ruby class (that rails derives from and augments in the derivative class) isn't threadsafe.

In short, I fully disagree with you on where the fix should be applied but, yes, a patch will be forthcoming.

[rafaelfranca]

Had you find any logger that you could change the level in a threadsafe way?

I particularly don't see why you would have to change the log level in runtime, maybe I'm missing some use case here. Could you explain?

[rabbitt]

Had you find any logger that you could change the level in a threadsafe way?

Not sure I understand the question here - are you asking if I've ever found a logger that could change the level in a threadsafe way? If so, yes - I've written a derivative class (of ::Logger) that uses Thread Locals to ensure threadsafety.

I particularly don't see why you would have to change the log level in runtime, maybe I'm missing some use case here. Could you explain?

There's a simple use case where you want to provide DEBUG level output for specific URIs, but maintain ERROR level logging for everything else. Or, maybe you want to disable verbose output of a certain URI and only output at ERROR level. This type of use case isn't new and happens more frequently than you expect in production environments.

[rafaelfranca]

👍

[rafaelfranca]

Thank you for explaining the reason

[rabbitt]

Absolutely - thanks for listening :-)

[rafaelfranca]

I'd go with a subclass instead of using the default Logger as threadsafe

[rabbitt]

I'd go with a subclass instead of using the default Logger as threadsafe

Not sure I grok you - care to elaborate?