Attempting to wrap a Logging::Logger in a ActiveSupport::TaggedLogging raises an error

[yboulkaid]

Hi,

ActiveSupport::TaggedLogging is supposed to be able to wrap "any standard Logger object". However, when wrapping an instance of Logging::Logger, this does not work:

ActiveSupport::TaggedLogging.new(Logging::Logger.new(STDOUT))
=> NoMethodError: undefined method `formatter=' for #<Logging::Logger:0x007fa3f98c14d8>

This is because ActiveSupport::TaggedLogging tries to set a formatter in case it doesn't exist.

Since code that tries to wrap the Rails.logger object in a ActiveSupport::TaggedLogging instance is becoming more and more common in the rails ecosystem (cf. here in webpacker), this can be deter many users from using this otherwise good framework.

There is a formatter method already defined in Logging so maybe it could be possible to map formatter= to the MDC feature of Logging?

Also, not sure if this should be part of the logging or the logging-rails repo, it has to do with rails but the RailsCompat module is in the logging repo..

[craigtsmith]

+1

[sshaw]

This is also a problem with Webpacker:

NoMethodError: undefined method `formatter=' for #<Logging::Logger:0x00007fc129d4e4e0>
Did you mean?  formatter
/Users/sshaw/.rvm/gems/ruby-2.3.5-railsexpress/gems/activesupport-4.2.10/lib/active_support/tagged_logging.rb:60:in `new'
/Users/sshaw/.rvm/gems/ruby-2.3.5-railsexpress/gems/webpacker-3.5.5/lib/webpacker/railtie.rb:72:in `block (2 levels) in <class:Engine>'
/Users/sshaw/.rvm/gems/ruby-2.3.5-railsexpress/gems/activesupport-4.2.10/lib/active_support/lazy_load_hooks.rb:36:in `execute
...

Also see #20.

[rauhryan]

As a workaround:

add the following to config/environment.rb

# Load the rails application
require File.expand_path('../application', __FILE__)

module Logging
  module RailsCompat
       def formatter
        self
      end
 
      def tagged(*_args)
         yield self
      end
 
     def current_tags
       []
     end
  end
end

# Initialize the rails application
Rails.application.initialize!

Works with Rails 4.2, I can now run bundle exec rake webpacker:install without errors and the apps seems to be working fine.

[tdeschamps]

Hey all,

When fixing the gem in order to webpack, it raises an error in ActiveJob which wants to add tags to the formatter which is unfortunately nil.

Would you have any idea regarding this issue?

Many thanks in advance!!

Thomas

You can find the error below

worker    | 2019-04-14T20:26:12.361Z 82070 TID-ouu3ugtp2 WARN: NoMethodError: undefined method `current_tags' for nil:NilClass
worker    | 2019-04-14T20:26:12.362Z 82070 TID-ouu3ugtp2 WARN: /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:53:in `logger_tagged_by_active_job?'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:45:in `tag_logger'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activejob-5.2.2.1/lib/active_job/logging.rb:16:in `block (2 levels) in <module:Logging>'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `instance_exec'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:118:in `block in run_callbacks'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activesupport-5.2.2.1/lib/active_support/callbacks.rb:136:in `run_callbacks'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activejob-5.2.2.1/lib/active_job/enqueuing.rb:49:in `enqueue'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/activejob-5.2.2.1/lib/active_job/configured_job.rb:15:in `perform_later'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionmailer-5.2.2.1/lib/action_mailer/message_delivery.rb:140:in `enqueue_delivery'
worker    | /Users/thomasdeschamps/.rbenv/versions/2.6.1/lib/ruby/gems/2.6.0/gems/actionmailer-5.2.2.1/lib/action_mailer/message_delivery.rb:94:in `deliver_later'

This raises due to this: https://github.com/rails/rails/blob/b9ca94caea2ca6a6cc09abaffaad67b447134079/activejob/lib/active_job/logging.rb#L53

[katiekeel]

@rauhryan Thanks for the workaround - it fixed the immediate issue.

However, I'm now experiencing NoMethodError: undefined method 'current_tags' for nil:NilClass when calling ActiveJob, just the same as @tdeschamps. Also using Rails 4.

NB @TwP: This library is recommended for Rails users by Datadog in order to log to a file and let them tail it, so as long as Datadog is popular and this bug exists, there will be frustrations, although I'm sure this could be a Rails problem and not necessarily a logging-rails problem.

[rauhryan]

thanks @katiekeel

Try adding this additional stuff I ran into

module Logging
    module RailsCompat
      def formatter
        self
      end
 
      def tagged(*_args)
       yield self
      end
 
     def current_tags
       []
     end
   end
 end

It will get you going, it's possible you could try managing the tags array, but I decided to just return an empty array

[tdeschamps]

Hello @katiekeel ,

on rails 5, I ended up 🐵 patching both logging_rails and active_job

module Logging
  module RailsCompat
    def tagged(*args); yield; end
  end
end

module ActiveJob
  module Logging
    private

    def tag_logger(*tags)
      yield
    end
  end
end

You can obviously set this in two separate files. Also, the gem is working fine if you stick to sidekiq and do not use ActiveJob. After adding these patches, the logger worked as expected. Unfortunately, this is nowhere to be found in the Datadog documentation. I hope it will help you on your project!

[katiekeel]

Thanks @rauhryan and @tdeschamps - @rauhryan's solution worked perfectly. 👍