GELF::Logger#add is not compatible to Ruby's Logger#add

[mrnugget]

It seems like GELF::Logger#add offers a slightly different interface than Ruby’s standard Logger. This can lead to the wrong messages being sent to server.

With a small puts statement in GELF::LoggerCompatability#add, just before the call to notify_with_level, we can see that if we use GELF::Logger.add like a Ruby Logger the message gets lost and used as facility instead, which will send an error silently in the background.

>> logger = Logger.new(STDOUT)
#=> #<Logger:0x007fc28ab06900 @progname=nil, @level=0, @default_formatter=#<Logger::Formatter:0x007fc28ab068d8 @datetime_format=nil>, @formatter=nil, @logdev=#<Logger::LogDevice:0x007fc28ab06720 @shift_size=nil, @shift_age=nil, @filename=nil, @dev=#<IO:<STDOUT>>, @mutex=#<Logger::LogDevice::LogDeviceMutex:0x007fc28ab066a8 @mon_owner=nil, @mon_count=0, @mon_mutex=#<Mutex:0x007fc28ab06608>>>>
>> logger.add(1, nil, 'foobar')
I, [2014-12-16T15:38:14.130554 #11601]  INFO -- : foobar
#=> true
>> Graylog.logger.add(1, nil, 'foobar')
DEBUG PUTS notify_with_level. level=1, hash={"short_message"=>nil, "facility"=>"foobar"}
#=> [<VERBOSE OUTPUT>]

Using GELF::Logger#info, #debug and so on works of course, as does GELF::Logger#add if we use “its” interface.

The problems arise if we try to use GELF::Logger like a standard Ruby logger with a standard #add method. Rails 4 for example, offers to extend the standard file logger with another logger by doing this:

my_logger = GELF::Logger.new("localhost", 12201, "WAN", { :facility => "appname" })
Rails.logger.extend(ActiveSupport::Logger.broadcast(my_logger))

(this seems to be the canonical way of having multiple loggers now — Rails uses this internally and in its scripts)

What Rails does here is it extends Rails.logger so whenever Rails.logger.add is called, it also calls #add on my_logger. It does not use the #info, #debug and other helper methods of my_logger. It uses #add and this leads to the problem from above:

>> Rails.logger.info("foobar")
DEBUG PUTS notify_with_level. level=1, hash={"short_message"=>nil, "facility"=>"foobar"}
=> true
>> Rails.logger.add(1, nil, 'foobar')
DEBUG PUTS notify_with_level. level=1, hash={"short_message"=>nil, "facility"=>"foobar"}
=> true

As you can see, the message foobar gets lost again. The GELF::Logger on the other hand still works (if used directly):

>> my_logger.info('foobar')
DEBUG PUTS notify_with_level. level=1, hash={"short_message"=>"foobar", "facility"=>"appname"}

But besides Rails’ this is also the way Ruby’s Logger uses the add method: https://github.com/ruby/ruby/blob/4c1666875f431105a63daf37f28734f9d1960ec2/lib/logger.rb#L433-L435

The GELF::Logger on the other hand just passes on *args, which is going to result in different outcomes.

My proposal would be to change the signature of GELF::Logger#add from this one

def add(level, *args)

to this one:

def add(level, message = nil, progname = nil, &block)

I’d also change the helper methods (#info, #warn, #error, …) to work just like Ruby’s Logger methods (see GitHub link above).

In itself GELF::Logger works fine. That’s also why it’s hard to write a failing test for this: the assertions are consistent throughout. But they are not compatibel to Ruby’s Logger.

This test for example (test/test_logger.rb:18):

      should "implement add method with level and message from parameters, facility from defaults" do
        @logger.expects(:notify_with_level!).with do |level, hash|
          level == GELF::INFO &&
          hash['short_message'] == 'Message' &&
          hash['facility'] == 'gelf-rb'
        end
        @logger.add(GELF::INFO, 'Message')
      end

It works and is fine. But: Ruby’s Logger never calls #add like this. In this case it would call #add like this:

@logger.add(GELF::INFO, nil, “Message”)

If I change the call to #add in the test to look like this it breaks.

I thought I’d open an issue here before hacking around the code and then get told that you’d want to keep the interface. So, what do you think about this?

[mrnugget]

So, I couldn't resist and whipped up a patch: https://github.com/mrnugget/gelf-rb/commit/5a2c852e97743c18221dccfae032b741b527e643

If you want me to open up a PR, just tell me! Otherwise, I'd be happy to hear what you think about this issue.

[joschi]

Nope, looks good. And there are even tests. :heart:

Feel free to open a pull-request for this.

[mrnugget]

Yes, I changed the assertions of the old tests and made the tests for the helper methods more restrictive: instead of checking what #add receives, they check that the message arrives in the correct way at the Notifier now.

[mrnugget]

Opened up the PR. I think we can move the discussion to #27 now.

[mrnugget]

I think this issue can be closed now that #27 has been merged.