Webpacker modifies the Rails.logger instance

[sveinn]

This change to Webpacker inadvertently modifies Rails.logger and Rails.logger.formatter; methods are added to their singleton classes. (This happens because of this line in ActiveSupport::TaggedLogging).

In particular, a call method is added, which results in it being executed ahead of the Rails.logger.formatter's call method. The added call method makes the assumption that msg is a string (by interpolating it passes a string to super), which msg need not be.

This is a problem because it's possible that Rails.logger.formatter expects to receive an exception class and not a strings for msg, which happened in my case, which is why I am filing this issue.

[sveinn]

Here is a test case that reproduces this issue, and should pass once the issue is resolved.

def test_rails_logger_should_not_be_modified
    # Set up a rails logger
    rails_logger = Logger.new(StringIO.new)
    rails_logger.formatter = rails_logger.instance_variable_get(:@default_formatter)
    assert_false rails_logger.formatter.respond_to?(:tagged)

    # Do what the 'webpacker.logger' initializer does
    webpacker_logger = ActiveSupport::TaggedLogging.new(rails_logger)
    
    # Webpacker logger is a tagged logger
    assert webpacker_logger.respond_to?(:tagged)
    assert webpacker_logger.formatter.respond_to?(:tagged)

    # Assert that the Rails logger is not modified by Webpacker's initializer
    test_object = Object.new
    def test_object.to_s
      raise "to_s called on msg. this means 'call' method has been added by ActiveSupport::TaggedLogging"
    end
    assert_nothing_raised { rails_logger.formatter.call('',Date.new,'',test_object) }

    assert_false rails_logger.respond_to?(:tagged)
    assert_false rails_logger.formatter.respond_to?(:tagged)
  end

[sveinn]

Here is one idea for a fix:

    ...
    # Proposed fix to the 'webpacker.logger' initializer
    temp_logger = rails_logger.dup
    temp_logger.formatter = rails_logger.formatter.dup
    webpacker_logger = ActiveSupport::TaggedLogging.new(temp_logger)
    ...

@curvo, @javan and @gauravtiwari I see that you guys were involved in the original change to the initializer. Would love to get your thoughts if you have the time. Thanks!

[jonleighton]

I've had trouble with this too. We have a custom logger where msg is a hash (it outputs JSON log messages). Due to Webpacker wrapping it in ActiveSupport::TaggedLogging, our hashes end up getting turned into strings.

IMO, Webpacker shouldn't require Rails.logger to be a ActiveSupport::TaggedLogging. If the logger doesn't respond to tagged then Webpacker should just not call tagged on it.

[andrewpage]

Having the same issue as @jonleighton. My structured logging isn't working! Would love to see a fix for this.

[andrewpage]

Looks like a fix for this has been included in the Rails 6 version of ActiveSupport. The ActiveSupport::TaggedLogger initializer duplicates the logger that is passed in before extending it, therefore removing this undesired behavior.

Here is a snippet of Ruby code that you can use to import this into your application without needing to fully upgrade. Include this after ActiveSupport has been loaded, and before Webpacker has. Probably makes sense to stick this between require 'rails/all' and Bundler.require(*Rails.groups).

# Monkeypatch in Rails 6 ActiveSupport::TaggedLogging initializer.
# Solves problem in which the TaggedLogging initializer modifies an existing logger
# by injecting its own functionality in.
if ActiveSupport::VERSION::MAJOR < 6
  module ActiveSupport
    module TaggedLogging
      def self.new(logger)
        logger = logger.dup

        if logger.formatter
          logger.formatter = logger.formatter.dup
        else
          # Ensure we set a default formatter so we aren't extending nil!
          logger.formatter = ActiveSupport::Logger::SimpleFormatter.new
        end

        logger.formatter.extend Formatter
        logger.extend(self)
      end
    end
  end
else
  ActiveSupport::Deprecation.warn('No longer need to monkeypatch ActiveSupport::TaggedLogging!')
end

This has solved the problem on my end. Hope this helps.

[guillaumebriday]

Is this issue still relevant ?

Or can it be closed ?