`log_tags` breaking LogStash parser?

[cabello]

Hi,

I have a Rails 5 app configured like the following config/environments/production.rb:

Rails.application.configure do
  config.lograge.formatter = Lograge::Formatters::Logstash.new
  config.log_tags = [:request_id]
end

This is a sample message that I am seeing in logz.io a ELK as a service provider:

[c069aa8b-b42b-4683-bfc2-c89f716c5c18] {"method":"GET","path":"/","format":"html","controller":"HealthcheckController","action":"index","status":200,"duration":2.17,"view":0.2,"db":0.67,"@timestamp":"2017-11-17T20:45:57.415Z","@version":"1","message":"[200] GET / (HealthcheckController#index)"}

I just did a test and removed the log_tags settings and everything was parsed into searchable fields.

Is that the expected behaviour? How do I log the request id otherwise? Using config.customize_event maybe?

[radoAngelov]

Hi,

I have experienced the same issue. In order to use the custom_options method I added this to my application_controller.rb file:

def append_info_to_payload(payload)
  super
  payload[:uuid] = request.uuid
end

After that you can customize lograge like:

config.lograge.custom_options = lambda do |event|
  # use the `event.payload` from application_controller
  {
    uuid: event.payload[:uuid],
  }
end

This worked for me. Probably it will work for you too 😄

[jeremywadsack]

Unless I'm missing something @radoAngelov, your solution is to work around the tags. That is, you are incorporating the :uuid data in the lograge logs fields, but that requires disabling the tags.

As I'd really like to use lograge (and the logstash formatter) for structured logs, it seems that lograge should not allow adding data to the log line after it has rendered it and should capture tags as fields in the data.

In particular Rails really, really likes tags (in 5.0 and 5.1). We're finding that not just Rails, but ActiveJob and other internal logging are tagging logs, even if we provide JSON as the original content.

[ActiveJob] [ImportJob] [dc6c4a1c-d9dd-4dca-bafa-aafd314d2163] {"message":"Logging test"}

While I haven't dug into how it works, I'd like any tags to be added as new attributes on the JSON output. Does that seem reasonable?

[jeremywadsack]

Hmm... this appears to just be a problem with the design of ActiveSupport::TaggedLogging that assumes that the logging data is string base and prepends tags to it.

So the solution is to not use ActiveSupport::TaggedLogging in my Rails app logging configuration.

As we want to log to STDOUT in production (for our log aggregator) we did this in config/environments/production.rb:

  # Log to STDOUT without additional formatting
  config.logger = ActiveSupport::Logger.new(STDOUT)

  # Log to STDOUT without additional formatting from ActiveJob
  config.active_job.logger = ActiveSupport::Logger.new(STDOUT)

[ianlet]

With Rails 5, you can also get the request id directly from the controller request without having to append info from the ApplicationController as suggested by @radoAngelov.

You can add it to the log with the following configuration:

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