rails_semantic_logger icon indicating copy to clipboard operation
rails_semantic_logger copied to clipboard

log_tags configuration is not working for all logs

Open mikesnare opened this issue 3 years ago • 1 comments
trafficstars

Environment

  • Ruby Version. 2.6.3
  • Rails Version. 6.1.3
  • Semantic Logger Version. 4.10.0
  • Rails Semantic Logger Version. 4.9.0
  • Other Application/framework names and versions (e.g. Puma, etc.). Unicorn 5.8.0

Config:

config.log_tags = { request_id: :request_id }
config.semantic_logger.backtrace_level  = :info
config.rails_semantic_logger.ap_options = { multiline: false }
config.rails_semantic_logger.started    = false
config.rails_semantic_logger.processing = false
config.rails_semantic_logger.rendered   = false
config.rails_semantic_logger.semantic   = true
Rails.application
      .config
      .semantic_logger.add_appender({ io: $stdout, formatter: :json})

Expected Behavior

The log_tags config should result in the tags being output as a hash, containing the :request_id key and the value of the current request's ID. That is not happening

Actual Behavior

Instead, the tags entry in the log contains ["request_id", "request_id"]. This is the expected output for the default Rails::Rack::Logger

What appears to be happening is that the RailsSemanticLogger::Rack::Logger is not being used for all logging. I have added debug output in several places in both the default rails logger and the RSL logger, and I can see that the the RSL rack logger is being used in some cases -- but those cases do not have a request and so they don't output any thing for the tags -- but it is not used in others. In other places, the original Rails::Rack::Logger is being used. The result is the output you see above.

Please advise.

mikesnare avatar Feb 16 '22 23:02 mikesnare

These are the log tags we are running with Rails 6.1 and the correct hash log tags appear everywhere we see them:

    config.log_tags = {
      request_id:    :request_id,
      ip:            :remote_ip,
      amzn_trace_id: ->(request) { request.headers["X-Amzn-Trace-ID"] },
      incap_req_id:  ->(request) { request.headers["INCAP-Req-ID"] }
    }

I will keep an eye out and see if I notice any invalid log entries. Our primary logging goes to Splunk in JSON format, so we seldom look at the text log outputs in Cloudwatch now. If you can find a place in Rails that is not being monkey-patched, consider submitting a pull request so that it can be replaced with the correct logger.

reidmorrison avatar Mar 24 '22 14:03 reidmorrison