[Proposal, Patch] Allow Loggers with Keyword Arguments

TL;DR

I propose a minor change to both ServerCommand and ActiveSupport::Logger to allow users to set up loggers that take keyword arguments, e.g. logger.debug('message', user_id: 1, some_argument: 'argument') in Rails.

Background

Logging benefits from additional context. Rather than just logging some message it is generally recommended to add additional data that makes the logs more useful when you have to look at them.

For example, you might want to add method arguments, the current user’s ID, or similar information to your log message. The standard Ruby logger, which ActiveSupport::Logger inherits from, takes only a string argument (message), so the only way to accomplish the above would be to use string interpolation:

logger.info("User logged in, user_id=#{user_id} some_argument=#{some_argument}")

This does not allow you to easily change the log formatting for all log messages. If one is so inclined, one may decide to create a logger that inherits from Logger, but also takes keyword arguments:

logger.info("User logged in", user_id: user_id, some_argument: some_argument})

Presuming a keyword argument enabled Logger to be added by the user (with a formatter that can also handle keyword arguments), e.g.

# application.rb
config.logger = MyKwargsLogger.new("log/#{Rails.env}.log", formatter: MyKwargsFormatter.new)

you will hit several small issues:

  1. ActiveSupport::Logger.broadcast modifies the add method of Rails.logger in such a way that prohibits keyword arguments on loggers:

    def self.broadcast(logger) # :nodoc:
      Module.new do
        define_method(:add) do |*args, &block|
          logger.add(*args, &block)
          super(*args, &block)
        end
        
        # ...
      end
    end
    

When calling the logger with keyword arguments (logger.info(some_argument: 'argument')) the above patch will cause an error.

  1. ServerCommand will use the above broadcast method to forward log messages to an instance of ActiveSupport::Logger

    def log_to_stdout
      wrapped_app # touch the app so the logger is set up
    
      console = ActiveSupport::Logger.new(STDOUT)
      console.formatter = Rails.logger.formatter
      console.level = Rails.logger.level
    
      unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDOUT)
        Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
      end
    end
    

So while the loggers formatter is used, the actual logger is not, which may result in a mismatch of log formatting, and errors if the add signature of the user-configured logger and ActiveSupport::Logger differ.

Proposed Solution

By modifying both the broadcast method as well as the server command, Rails can support loggers with a non-standard interface. Modifying ServerCommand to use the Logger the user has set up:

def log_to_stdout
  wrapped_app # touch the app so the logger is set up

  console = Rails.logger.class.new(STDOUT) # << Instead of ActiveSupport::Logger
  console.formatter = Rails.logger.formatter
  console.level = Rails.logger.level

  unless ActiveSupport::Logger.logger_outputs_to?(Rails.logger, STDOUT)
    Rails.logger.extend(ActiveSupport::Logger.broadcast(console))
  end
end

Modifying broadcast to allow logger add signatures with keyword arguments:

define_method(:add) do |*args, **kwargs, &block| # Add kwargs
  logger.add(*args, **kwargs, &block)
  super(*args, **kwargs, &block)
end

Changing the signature of add with keyword arguments has no impact if the logger is not called with any. Only in the case where the logger supports it and the user uses calls like logger.debug(some_argument: 1) this change has any impact.

While these kinds of loggers are definitely ‘non-standard’, the changes to Rails to support these use cases seem minimal. I believe that supporting users who want to use such loggers will be ultimately beneficial to Rails.

Alternatives Considered

Using Application Code to Format Messages

One may write some helper method to format log messages globally:

def my_kwargs_formatter(message, **kwargs)
  return "#{message}, #{kwargs.values.join(' ')}" # just an example
end

logger.debug(my_kwargs_formatter('message', some_argument: 'argument'))

This solves the issue of modifying the log formatting globally without needing to make changes to the logger signature. However, this still treats contextual data as part of the message. Whether or not that is bad is debatable.

This solution is suboptimal when it comes to formatting still. By modifying the message formatter and adding a JSON log formatter, the best you can get is something like below, which is not easily parsable:

{
   "severity":"INFO",
   "message":"{ \"message\": \"my message\", \"some_argument\": \"argument\" }"
}

The only way to get a proper JSON structure would be by creating a JSON formatter that first parses the message and then chucks it back into the message, which seems woefully inefficient:

class JsonFormatter < Logger::Formatter
  def call(severity, time, progname, raw_msg)
    msg = normalize_message(raw_msg)
    content = { severity: severity, time: time.iso8601(3), progname: progname, **msg }

    "#{JSON.dump(content)}\n"
  end

  private

  def normalize_message(raw_msg)
    raw_msg = raw_msg.strip
    return { message: raw_msg } unless raw_msg.is_a?(String) && raw_msg.json?

    JSON.parse(raw_msg)
  end
end

Maybe using Keyword Arguments for logging is not a great idea?

Maybe there is some good reason why we shouldn’t have loggers take keyword arguments that I haven’t thought of. I’m relatively new to Ruby/Rails.