ActiveSupport::TaggedLogging no longer works (no tags are logged)

[TylerRick]

After upgrading from Rails 3.2 to Rails 5.1 recently, I noticed that my log files no longer included the tags specified in config.log_tags, even though my logger configuration hasn't changed (I'm still wrapping Lumberjack with ActiveSupport::TaggedLogging.new like I showed in #8).

Rails::Rack::Logger is the middleware that is supposed to take your log_tags and add them to all log messages. But you can reproduce the same issue even more easily directly in a console...

What I would expect (this used to work):

main > Rails.logger = ActiveSupport::TaggedLogging.new(Lumberjack::Logger.new(STDOUT, level: :debug))

main > Rails.logger.tagged('My Tag') { Rails.logger.debug 'Message' }
[My Tag] Message

What happens instead:

No tags:

main > Rails.logger.tagged('My Tag') { Rails.logger.debug 'Message' }
Message

How it used to work (Rails 3.2):

Using byebug, I was able to step through my old Rails 3.2 app (same version of lumberjack, 1.0.12) to see the path it used to take:

main > Rails.logger = ActiveSupport::TaggedLogging.new(Lumberjack::Logger.new(STDOUT, level: :debug))
=> #<ActiveSupport::TaggedLogging:0x000000089cc7e8
 @logger=
  #<Lumberjack::Logger:0x00000008a40490
   @_formatter=
    #<Lumberjack::Formatter:0x000000089f21f0
     @_default_formatter=
      #<Lumberjack::Formatter::InspectFormatter:0x000000089f1ca0>,
...

(Note that this used to return an instance of ActiveSupport::TaggedLogging. Now it returns an instance of Lumberjack::Logger. Kind of strange, but possibly unrelated to the issue at hand.)

main > byebug; Rails.logger.tagged('My Tag') { Rails.logger.debug 'Message' }
...
[17, 26] in /usr/local/bundle/gems/activesupport-3.2.21/lib/active_support/tagged_logging.rb
   20:     def tagged(*tags)
   21:       new_tags = push_tags(*tags)
=> 22:       yield self
   23:     ensure
   24:       pop_tags(new_tags.size)
   25:     end
(byebug) s
*** No sourcefile available for (pry)
(byebug) s
...
[56, 65] in /usr/local/bundle/gems/activesupport-3.2.21/lib/active_support/tagged_logging.rb
   56:     end
   57: 
   58:     %w( fatal error warn info debug unknown ).each do |severity|
   59:       eval <<-EOM, nil, __FILE__, __LINE__ + 1
   60:         def #{severity}(progname = nil, &block)
=> 61:           add(Logger::#{severity.upcase}, nil, progname, &block)
   62:         end
   63:       EOM
   64:     end
...
[46, 56] in /usr/local/bundle/gems/activesupport-3.2.21/lib/active_support/tagged_logging.rb
   46:     def add(severity, message = nil, progname = nil, &block)
   47:       if message.nil?
   48:         if block_given?
   49:           message = block.call
   50:         else
   51:           message = progname
   52:           progname = nil #No instance variable for this like Logger
   53:         end
   54:       end
=> 55:       @logger.add(severity, "#{tags_text}#{message}", progname)
   56:     end
(byebug) tags_text
"[My Tag] "

As you can see, ActiveSupport::TaggedLogging#add used to be the method that added tags_text. This has changed in later version of ActiveSupport, as you can see in the next section:

How it works in Rails 5 (without Lumberjack):

main > Rails.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT, level: :debug))
=> #<ActiveSupport::Logger:0x000000000ab8ab78
 @default_formatter=#<Logger::Formatter:0x000000000ab899d0 @datetime_format=nil>,
 @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x000000000ab7f638 @datetime_format=nil>,
 @level=0,

main > byebug; Rails.logger.tagged('My Tag') { Rails.logger.debug 'Message' }

[64, 73] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   68:     def tagged(*tags)
=> 69:       formatter.tagged(*tags) { yield self }
   70:     end
(byebug) self
#<ActiveSupport::Logger...
(byebug) s

[21, 30] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   24:       def tagged(*tags)
   25:         new_tags = push_tags(*tags)
=> 26:         yield self
   27:       ensure
   28:         pop_tags(new_tags.size)
   29:       end
(byebug) self
#<ActiveSupport::Logger::SimpleFormatter...

[64, 73] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   68:     def tagged(*tags)
=> 69:       formatter.tagged(*tags) { yield self }
   70:     end
(byebug) self
#<ActiveSupport::Logger...
(byebug) s
*** No sourcefile available for (pry)
(byebug) s

[486, 495] in /usr/lib/ruby/2.4.0/logger.rb
   490:   def debug(progname = nil, &block)
=> 491:     add(DEBUG, nil, progname, &block)
   492:   end

[82, 91] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/logger.rb
   85:     def add(severity, message = nil, progname = nil, &block)
   86:       return true if @logdev.nil? || (severity || UNKNOWN) < level
=> 87:       super
   88:     end

# Notice how it goes to the add in Logger instead of in active_support/tagged_logging.rb like it used to:
[455, 472] in /usr/lib/ruby/2.4.0/logger.rb
   455:   def add(severity, message = nil, progname = nil)
   456:     severity ||= UNKNOWN
   457:     if @logdev.nil? or severity < @level
   458:       return true
   459:     end
   460:     progname ||= @progname
   461:     if message.nil?
   462:       if block_given?
   463:         message = yield
   464:       else
   465:         message = progname
   466:         progname = @progname
   467:       end
   468:     end
=> 469:     @logdev.write(
   470:       format_message(format_severity(severity), Time.now, progname, message))
   471:     true
   472:   end

[577, 586] in /usr/lib/ruby/2.4.0/logger.rb
   581:   def format_message(severity, datetime, progname, msg)
=> 582:     (@formatter || @default_formatter).call(severity, datetime, progname, msg)
   583:   end
(byebug) s

[16, 25] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   16:   # to aid debugging of multi-user production applications.
   17:   module TaggedLogging
   18:     module Formatter # :nodoc:
   19:       # This method is invoked when a log event occurs.
   20:       def call(severity, timestamp, progname, msg)
=> 21:         super(severity, timestamp, progname, "#{tags_text}#{msg}")
   22:       end
(byebug) self
#<ActiveSupport::Logger::SimpleFormatter:0x000000000ab7f638 @datetime_format=nil, @thread_key="activesupport_tagged_logging_tags:89914140">
(byebug) tags_text
"[My Tag] "

[97, 106] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/logger.rb
    99:     class SimpleFormatter < ::Logger::Formatter
   100:       # This method is invoked when a log event occurs
   101:       def call(severity, timestamp, progname, msg)
=> 102:         "#{String === msg ? msg : msg.inspect}\n"
   103:       end

(byebug) c
[My Tag] Message

As you can see, the responsibility for adding tags_text has moved from ActiveSupport::TaggedLogging#add in Rails 3 to ActiveSupport::TaggedLogging::Formatter#call in Rails 5. The problem is, that call never gets called if we use Lumberjack...

How it doesn't work in Rails 5 with Lumberjack

If I change this line:

main > Rails.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT, level: :debug))

to this:

main > Rails.logger = ActiveSupport::TaggedLogging.new(Lumberjack::Logger.new(STDOUT, level: :debug))
=> #<Lumberjack::Logger:0x000000000a8f0d90
 @_formatter=
  #<Lumberjack::Formatter:0x000000000a8f0688
   @_default_formatter=#<Lumberjack::Formatter::InspectFormatter:0x000000000a8f0638>,

Then:
You can see that it starts out identically...

main > byebug; Rails.logger.tagged('My Tag') { Rails.logger.debug 'Message' }

[68, 70] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   68:     def tagged(*tags)
=> 69:       formatter.tagged(*tags) { yield self }
   70:     end
(byebug) self
#<Lumberjack::Logger:...

[21, 30] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   24:       def tagged(*tags)
   25:         new_tags = push_tags(*tags)
=> 26:         yield self
   27:       ensure
   28:         pop_tags(new_tags.size)
   29:       end
(byebug) self
#<Lumberjack::Formatter:...

[68, 70] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   68:     def tagged(*tags)
=> 69:       formatter.tagged(*tags) { yield self }
   70:     end
(byebug) self
#<Lumberjack::Logger:...

(byebug) s
*** No sourcefile available for (pry)
(byebug) s

[180, 189] in /usr/local/bundle/gems/lumberjack-1.0.12/lib/lumberjack/logger.rb
   184:     def debug(message = nil, progname = nil, &block)
=> 185:       add(DEBUG, message, progname, &block)
   186:     end

That method is pretty much the same as Logger's, but here is where it really starts to diverge:

[100, 126] in /usr/local/bundle/gems/lumberjack-1.0.12/lib/lumberjack/logger.rb
   100:     def add(severity, message = nil, progname = nil)
   101:       severity = Severity.label_to_level(severity) if severity.is_a?(String) || severity.is_a?(Symbol)
   102: 
   103:       return unless severity && severity >= level
   104: 
   105:       time = Time.now
   106:       if message.nil?
   107:         if block_given?
   108:           message = yield
   109:         else
   110:           message = progname
   111:           progname = nil
   112:         end
   113:       end
   114: 
   115:       message = @_formatter.format(message)
   116:       progname ||= self.progname
   117:       entry = LogEntry.new(time, severity, message, progname, $$, Lumberjack.unit_of_work_id)
   118:       begin
=> 119:         device.write(entry)
   120:       rescue => e
   121:         $stderr.puts("#{e.class.name}: #{e.message}#{' at ' + e.backtrace.first if e.backtrace}")
   122:         $stderr.puts(entry.to_s)
   123:       end
   124: 
   125:       nil
   126:     end
(byebug) @_formatter
#<Lumberjack::Formatter:0x000000000a8f0688 ...
(byebug) @_formatter.format(message)
"Message"
(byebug) message
"Message"
(byebug) entry
[2018-05-08T10:28:24.335 DEBUG (12846)] Message

As you can see, @formatter is a Lumberjack::Formatter and ActiveSupport::TaggedLogging::Formatter#call never gets called, so the log tags never get added.

Have also tested in a simple, bare-bones Rails 5.2 app and observe the same behavior.

Summary

So I'm wondering, is ActiveSupport::TaggedLogging's formatter fundamentally incompatible with Lumberjack's formatter system? Or are we expected to register that formatter with Lumberjack somehow?

Was it just coincidence that ActiveSupport::TaggedLogging worked with Lumberjack before without any special configuration, or is it supposed to still work now? If so, how do we fix it?

One or both sides seem to be breaking a promise here. ActiveSupport::TaggedLogging claims:

Wraps any standard Logger object to provide tagging capabilities.

while Lumberjack claims:

can be a drop in replacement for Logger or ActiveSupport::BufferedLogger

Could someone who understands the logger situation better please explain why they don't seem to play nicely together and what the recommended solution would be?

[TylerRick]

Workaround I'm using for now, for what it's worth:

Monkeypatch Lumberjack::Logger to call formatter.call(severity, time, progname, message) instead of formatter.format(message):

module Lumberjack
  Logger.class_eval do

    def add(severity, message = nil, progname = nil)
      severity = Severity.label_to_level(severity) if severity.is_a?(String) || severity.is_a?(Symbol)

      return unless severity && severity >= level

      time = Time.now
      if message.nil?
        if block_given?
          message = yield
        else
          message = progname
          progname = nil
        end
      end

      #message = @_formatter.format(message)
      message = formatter.call(severity, time, progname, message)
      progname ||= self.progname
      entry = LogEntry.new(time, severity, message, progname, $$, Lumberjack.unit_of_work_id)
      begin
        device.write(entry)
      rescue => e
        $stderr.puts("#{e.class.name}: #{e.message}#{' at ' + e.backtrace.first if e.backtrace}")
        $stderr.puts(entry.to_s)
      end

      true
    end

  end
end

Looks like Lumberjack::Formatter itself doesn't have a call method, but this change causes it to call
ActiveSupport::TaggedLogging::Formatter#call because the ActiveSupport::TaggedLogging::Formatter module was apparently mixed into Lumberjack::Formatter somehow, somewhere.

[15, 24] in /app/lib/lumberjack/logger_extensions.rb
   18: 
   19:       #message = @_formatter.format(message)
=> 20:       message = formatter.call(severity, time, progname, message)
   21:       progname ||= self.progname
   22:       entry = LogEntry.new(time, severity, message, progname, $$, Lumberjack.unit_of_work_id)

[16, 25] in /usr/local/bundle/gems/activesupport-5.1.4/lib/active_support/tagged_logging.rb
   16:   # to aid debugging of multi-user production applications.
   17:   module TaggedLogging
   18:     module Formatter # :nodoc:
   19:       # This method is invoked when a log event occurs.
   20:       def call(severity, timestamp, progname, msg)
=> 21:         super(severity, timestamp, progname, "#{tags_text}#{msg}")
   22:       end

[TylerRick]

After upgrading to Rails 5.2, I noticed that the last line of Lumberjack::Logger#add above needs to return true instead of nil so that it actually gets to the ActiveRecord::Base.verbose_query_logs check here:

      # activerecord-5.2.3/lib/active_record/log_subscriber.rb
          def debug(progname = nil, &block)
            return unless super
    
            if ActiveRecord::Base.verbose_query_logs
              log_query_source
            end
          end