Only affects request logs. Probably expected, but not immediately clear

[bf4]

that is, Rails.logger.info "some logger" isn't formatted or otherwise touched by Lograge or any of its settings.

I wanted to log everything as JSON what I see it that lograge appears to take a given active support notification, format it, and then pass it along to the Rails logger. This surprised me, but explains why Lograge doesn't affect the Rails logger. I did try setting a separate Lograge.logger, but that didn't end up helping.

[pxlpnk]

Yes, this is true. lograge only tames the bits of the controller based routing. Might be worth noting this. However, it is not difficult to make a custom format and supply it to the Rails logger. Happy to accept a PR that makes this clear. 😄

[bf4]

It's well past my bedtime now. If I made a PR now, it would say:

Note: Lograge does not change the behavior of the Rails.logger. Lograge replaces various framework-level request logging with a nicely formatted message which is then sent to the Rails.logger.

[mediafinger]

🤦‍♂️ ouch. I was wondering why lograge is not working as expected. Only now I realize it is, but I expected differently.

What is the usual fix to tame ActiveRecord's multi-line log outputs when using lograge? E.g.:

  Admin Load (1.4ms)  SELECT  "admins".* FROM "admins" WHERE "admins"."id" = $1 ORDER BY "admins"."id" ASC LIMIT $2  [["id", "6a00e6cc-fdfa-46d4-b799-ad07a2e8a47b"], ["LIMIT", 1]]
  ↳ app/views/layouts/application.html.haml:13

[silva96]

Hi, I want my Rails.logger.info/warn/etc logs to be json with some metadata like you do with lograge, particulary the request_id: controller.request.request_id like this

  config.lograge.custom_payload do |controller|
    {
      request_id: controller.request.request_id
    }
  end

I then created a Formatter for my rails Logger,

# frozen_string_literal: true

class JsonLogFormatter < Logger::Formatter
  def call(severity, _time, _progname, msg)
    log = {
      "@timestamp": Time.zone.now,
      level: severity
    }

    if msg.include?('[->]')
      parts = msg.split('[->]')
      msg = parts[1]
      meta = parts[0].split(' ')
      request_id = meta[0].tr('[]', '')
      remote_ip = meta[1].tr('[]', '')
      log[:request_id] = request_id,
      log[:remote_ip] = remote_ip
    end

    log[:message] = msg
    log.to_json + "\n"
  end
end

and use it in production.rb like this

config.log_formatter = JsonLogFormatter.new
config.log_tags = [:uuid, :remote_ip, '->']

This way messages bring tagged metadata and a -> separator which I use to split the message and log it properly.

this feels so hacky, do you have any better approach?

[minamijoyo]

I found that we can get current_tags in Logger::Formatter#call when using ActiveSupport::TaggedLogging. Thus, we don't need the magic keyword -> as mentioned above, and we can put request_id to entry logged by Rails.logger as the followings. Note that an entry logged by lograge is already encoded as JSON in the msg field, so we need decode and merge it.

Environments: Rails 5.2 + lograge v0.11.2

class JsonLogFormatter < Logger::Formatter
  def call(severity, _time, _progname, msg)
    log = {
      time: _time.iso8601(6),
      level: severity,
      progname: _progname,
      type: "default",
    }

    unless current_tags.empty?
      tagged = Rails.application.config.log_tags.zip(current_tags).to_h
      log.merge!(tagged)
      msg = msg&.split(' ', current_tags.size + 1)&.last
    end
    begin
      parsed = JSON.parse(msg).symbolize_keys
      log.merge!(parsed)
    rescue JSON::ParserError
      log.merge!({message: msg})
    end
    log.to_json + "\n"
  end
end

Rails.application.configure do
  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Json.new

  config.lograge.custom_options = lambda do |event|
    data = {
      level: 'INFO',
      type: 'access',
    }

    # customize other fields
    # (snip.)

    data
  end
end

and use it in production.rb like this

logger = ActiveSupport::Logger.new(STDOUT)
logger.formatter = ::JsonLogFormatter.new
config.log_tags = [:request_id]
config.logger = ActiveSupport::TaggedLogging.new(logger)

Rails.logger.info("foo")

{"time":"2020-07-13T09:57:47.558838+09:00","level":"INFO","progname":null,"type":"default","request_id":"5a48d951-a04b-43fe-b462-f57277b55291","message":"foo"}

controller access log logged by lograge

{"time":"2020-07-13T09:57:48.744866+09:00","level":"INFO","progname":null,"type":"access","request_id":"5a48d951-a04b-43fe-b462-f57277b55291","method":"GET","path":"/","format":"html","controller":"RootPagesController","action":"index","status":200,"duration":1675.8,"view":1150.5,"db":15.37,"user_id":null,"params":"{}"}

Rails.logger cannot log all fields logged by lograge, but I think the request_id is enough to join with other entries. Thanks!

[santry]

ActiveSupport::TaggedLogging::Formatter#tags_text gives you the rendered list of tags from the log message. Using this method can make removing the square-bracketed tags from the message a little easier.

Instead of

msg = msg&.split(' ', current_tags.size + 1)&.last

you can do

# Get a substring of `msg` that starts at the end of the tag list and goes to the end of `msg`
msg = msg[tags_text.size..].strip

That is, if msg is "[tag1] [tag2] [tag3] foo bar baz", tags_text will be "[tag1] [tag2] [tag3] ".

This has the advantage of allowing spaces in the tag names, since space is no longer a special character used for splitting the string.

[santry]

For anyone who's interested, I built the JsonTaggedLogger gem (source) to address these needs in a more structured and hopefully easier to implement way. For example,

Given the following configuration,

# Gemfile
gem 'json_tagged_logger'
gem 'lograge'

# config/environments/production.rb
Rails.application.configure do
  # …
  config.log_tags = JsonTaggedLogger::LogTagsConfig.generate(
    :request_id,
    :host,
    ->(request) { { my_param: request.query_parameters["my_param"] }.to_json },
    JsonTaggedLogger::TagFromSession.get(:user_id),
    JsonTaggedLogger::TagFromHeaders.get(:my_custom_header, "X-Custom-Header"),
  )

  logger = ActiveSupport::Logger.new(STDOUT)
  config.logger = JsonTaggedLogger::Logger.new(logger)

  config.lograge.enabled = true
  config.lograge.formatter = Lograge::Formatters::Json.new
  # …
end

A request like

curl -H "X-Custom-Header: some header value" 'http://127.0.0.1:3000/?my_param=param%20value'

will get you something like

{
  "level": "INFO",
  "request_id": "914f6104-538d-4ddc-beef-37bfe06ca1c7",
  "host": "127.0.0.1",
  "my_param": "param value",
  "user_id": "99",
  "my_custom_header": "some header value",
  "method": "GET",
  "path": "/",
  "format": "*/*",
  "controller": "SessionsController",
  "action": "new",
  "status": 302,
  "duration": 0.51,
  "view": 0,
  "db": 0,
  "location": "http://127.0.0.1:3000/profile"
}