Ruby JSON Logging

json_logger.rb

class JsonLogger
  class Instance
    extend Forwardable

    attr_reader :identifier

    # @param [String] identifier Custom identifier string for this logger. Required property of every structured log.
    # @param [Array<String>] groups Optional list of additional properties to include with every log message.
    # @param [Boolean] audit Defaults to false.
    # @param [String, Symbol, Integer] level Defaults to DEBUG.
    # @param [Logger] logger Defaults to copy of Rails.logger
    def initialize(identifier,
                   groups: [],
                   level: :debug,
                   logger: nil)
      @identifier = identifier
      @logger = logger || build_logger

      @logger.formatter = LoggerJsonFormatter.new(groups: groups)

      @logger.level = level
    end

    def_delegator :@logger, :formatter

    [:debug, :info, :warn, :error, :fatal].each do |method_name|
      define_method(method_name) do |log_data|
        full_log_data = log_data.merge(identifier: identifier)
        logger.send(method_name, full_log_data)
      end
    end

    private

    attr_reader :logger

    def build_logger
      # Duplicate the Rails logger to start. This ensures we use the same log
      # device (file descriptor) as the one configured for the environment.
      # In development, that is a log file. In production, that is stdout.
      Rails.logger.dup
    end
  end

  # TODO: Cache these in a thread-safe way. Only if we start to care about
  # allocations (which we probably won't, it's Ruby lol). identifier would
  # be the perfect key to cache on.
  #
  # @see JsonLogger::Instance
  def self.for(*args, **kwargs)
    Instance.new(*args, **kwargs)
  end
end

logger_json_formatter.rb

class LoggerJsonFormatter < ::Logger::Formatter
  def initialize(groups: [])
    @groups = groups
    super()
  end

  def call(severity, _timestamp, _progname, msg)
    return unless msg.is_a?(Hash)
    return unless msg[:identifier].present?

    # This happens so often it needs to be addressed globally.
    # Convert ActionController::Parameters to hash.
    msg.transform_values! do |value|
      if value.is_a?(ActionController::Parameters)
        value.as_json
      else
        value
      end
    end

    log_data = {}.tap do |data|
      correlation = Datadog::Tracing.correlation
      if correlation
        data[:dd] = {
          trace_id: correlation.trace_id.to_s,
          span_id: correlation.span_id.to_s,
        }
      end

      data.merge!(
        ddsource: ['ruby'],
        lvl: severity,
        ts: Time.now.to_f,
        rails_console: rails_console?,
        custom_event: msg.merge(groups: @groups)
      )
    end

    # Stolen from Sidekiq.dump_json
    # https://github.com/mperham/sidekiq/blob/v6.4.2/lib/sidekiq.rb#L189-L191
    "#{JSON.generate(log_data)}\n"
  end

  private

  def rails_console?
    !!defined?(Rails::Console)
  end
end

usage.rb

# Instantiate logger
logger = JsonLogger.for("feature")

logger.debug(
  message: "Precise values for debugging",
  count: 123,
  did_the_thing: true,
  response_headers: { "Content-Type": "application/json" },
)

# Common pattern for "default log attributes"
log_data = {
  class: self.class.name,
  always_here: true,
}

logger.info(message: "Thing 1", **log_data)
logger.info(message: "Thing 2", **log_data)