"write" methods (#add, #info, #debug, etc.) are inconsistent with Ruby Logger (and Log4r), and trigger nasty ripple effects

[javmorin]

I've just started porting an existing app from log4r to logging.

An issue I discovered very quickly was that logging was breaking a fair number of my Rails model callbacks. Model callbacks require a non-false result in order to complete successfully. The result was that I had debug logging methods which record the end of a callbacks execution that where effectively disabling the callback chain.

I checked other logging tools to see what they chose to use:

• Rails Logger always returns true
• Log4r always returns nilHere is a pull request which resolves Issue "write" methods (#add, #info, #debug, etc.) are inconsistent with Ruby Logger (and Log4r), and trigger nasty ripple effects #71

I picked the Rails Logger implementation as the more approach (also means only 1 changed line vs 2).

Note: This pull request applies cleanly to both master(3ce0721) and two-point-oh(5c06041)

[TwP]

The return values from these methods conform to the ruby Logger class. The methods for logging at a specific level all delegate to the add method. This method returns true if the message was logged and false if it was not.

So changing these methods to always return true regardless of whether or not the message was logged does not make much sense.

[javmorin]

Apologies, however your interpretation of what the ruby Logger class does is incorrect.

If you look at https://github.com/ruby/ruby/blob/trunk/lib/logger.rb#L371 you will note that in the case where the device is nil, or the level would prevent a log item being recorded, it calls return true. This appears to be unchanged from 1.8.7 era (https://github.com/ruby/ruby/blob/v1_8_7/lib/logger.rb#L315).

Barring an exception being raised, there is, in fact, no way for the ruby Logger#add method to return anything but true.

[TwP]

The more you know ...

Apparently it is impossible for the add method to return false. It will only ever return true or raise an exception. So either the code is wrong or the documentation is wrong.

Unfortunately that code has been in there since the file was first created: https://github.com/ruby/ruby/blame/trunk/lib/logger.rb#L370-L372

And the documentation was updated by Eric back only a year ago: https://github.com/ruby/ruby/blame/trunk/lib/logger.rb#L346-L347

This smells more like a bug in the ruby code more than anything else.

[TwP]

I'm curious, though. What "ripple effects" are you seeing?

[javmorin]

To the "bug in the ruby code" comment:
The Logger#add method should not responsible for returning log level/state, in any way. If anything, it's just reporting that it handled the message. It could be argued that it should return nil, rather than true - which is what Log4r does. That said, the Logger class does return true, so you need to decide if you want to stick with ruby Logger compliance or not. Ruby methods always have to return something, it would just be nice if the something wasn't the one thing that broke my app 😀

On the "ripple effect":
We use a lot of model callbacks in our rails app. For a number of these callbacks we have .debug log calls at the start and the end so we can track progress through the callback chain. When I switched from Log4r to logging, the callback chains started breaking as model callback chains only continue if the callback does not return false. It took a fair bit to work out that the fact that logging returns false was breaking the our callbacks.

My initial response to all this was Why is this method returning anything?, though in the end, I have to say, my Rails app works fine with the ruby Logger and with Log4r, but logging breaks it. I would like to use logging, but I need it to not break my app 😄.

[TwP]

Yes, I can see how terminating a callback chain would be bad mojo in your app.

The quickest way to solve the issue is to explicitly return true in your model callbacks. If the code really does not care about the success or failure of the debug statement, then that should be explicit in the callback. Relying on the implicit return value from some other library will lead to these kinds of problems.

I'm very hesitant to change the behavior here. You have convinced me that the current return values from Logging disagree with the ruby Logger. However, I'm not fully convinced that the current behavior here is wrong - it's just different from what the ruby stdlib is doing.

I've opened a ruby-lang issue #8567 to see what the powers that be think about this.

[javmorin]

I am using my pull-request branch in my app, so that was my quick resolution to the issue. I would be interested to see what comes from the ruby-lang issue.

[javmorin]

So it's been a few weeks and I was looking through my Gemspec and was reminded that I was running my patched version of logging (it works soo much better than log4r ever did). I decided I would check on the status. It seems the ruby-lang people feel the conflicting documentation was wrong, and have removed it. (See changeset 41901)

So I guess the ball is back in your court @TwP for what you want to do in your library.

[keithrbennett]

I think there's a lot of wisdom in what @TwP said:

"The quickest way to solve the issue is to explicitly return true in your model callbacks. If the code really does not care about the success or failure of the debug statement, then that should be explicit in the callback. Relying on the implicit return value from some other library will lead to these kinds of problems."

Although it may have been fortunate that other libraries returned the desired value, relying on that strikes me as relying on coincidence. The meaning of the value returned by the log library is different from the meaning of the value returned by the callback. Since the latter is a really important value, I think it warrants something more intentional than the log call's return value, even if it's a literal true.

[javmorin]

If anyone is interested, here is the monkeypatch we wound up using to "resolve" this issue and avoid maintaining a fork for just this one fix.

  module LoggingLoggerCodePatch
    def _meta_eval(code, file = nil, line = nil)
      # patch the generated recording code to return true even when level is disabled
      super(code.gsub(/def (.*)\( data = nil \) false end/, "def \\1( data = nil ) true end"), file, line)
    end
  end
  Logging::Logger.send(:prepend, LoggingLoggerCodePatch)