Lograge in JSON mode in Rails causes double addition of log correlation information and breaks log parsing

[chall8908]

The current implementation of the Rails integration causes log correlation information to be added twice to the logger when using Lograge. This breaks log parsing in Datadog if Lograge is using the JSON formatter.

I'm currently attempting to work around this by setting Rails.configuration.log_tags = [] in initializers/datadog.rb.

As far as I can tell, this is likely going to be a problem in any Rails project that doesn't override the default logger when using Lograge (which doesn't modify the default logger) and using the JSON formatter.

I'm not sure if it's possible to simply delay modifying Rails.configuration.log_tags until after_initialize and still have everything function correctly. If nothing else, a mention in the README about this potential issue would save other people the head-scratching.

[marcotc]

👋 @chall8908, thanks for this issue report.
Could you provide the relevant Rails log configuration you use (Lograge configuration, any /config\..*log.*/ related Rails configuration) and the Rails version and Lograge you are running?
One possibility is that the problem is a mix of specific versions of Rails, Lograge and ddtrace combined.

[javierjulio]

Hi @marcotc 👋🏻 I'm noticing this as well. With Datadog v1.1.0 (we upgraded recently and directly from v0.54.2) and our Lograge integration, our logs have prepended the Datadog log text before the json format which does include the Datadog tracing info.

[dd.env=production dd.service=my-app dd.version=123 dd.trace_id=123 dd.span_id=123] {"method":"POST","path":"/","format":"html","controller":"SiteController","action":"index","status":200,"duration":90.02,"view":18.85,"db":25.61,"dd":{"trace_id":"123","span_id":"123","env":"production","service":"my-app","version":"123"},"ddsource":"ruby","time":728707.869930716,"params":{},"request_id":"123"}

Before replacing the info in the log shared above, the trace and span ids were a match in both text and json formats.

We are using lograge v0.12.0 (latest), ddtrace v1.1.0 (latest) and rails v6.1.6.

[javierjulio]

@marcotc we are actually overriding the default logger whereas with what @chall8908 wrote it seems they aren't but that is still resulting in the same output issue.

For Lograge config:

Rails.application.configure do
  config.lograge.enabled = true

  # Set the default log formatter but only if we have Lograge
  # enabled since we are using the Lograge JSON formatter.
  if config.lograge.enabled
    config.log_formatter = Lograge::Formatters::Json.new
    config.lograge.formatter = config.log_formatter
  end

  # Add our own custom data and Lograge will take care of merging this with
  # a base set. Do not merge `event.payload` (only merge explicit values)
  # as that contains a large object from ActionDispatch.
  config.lograge.custom_options = ->(event) do
    {
      time: event.time,
      params: event.payload[:params].except("controller", "action", "format")
    }.merge(event.payload[:custom_payload] || {})
  end

  # A hook to access controller methods so we can log common request info.
  config.lograge.custom_payload do |controller|
    {
      request_id: controller.request.uuid,
      user_id: controller.current_user.try(:id)
    }.compact
  end
end

For Rails logging:

  # Include generic and useful information about system operation, but avoid logging too much
  # information to avoid inadvertent exposure of personally identifiable information (PII).
  config.log_level = ENVied.LOG_LEVEL

  # Prepend all log lines with the following tags.
  # config.log_tags = [ :request_id ]

  # Log disallowed deprecations.
  config.active_support.disallowed_deprecation = :log

  # Tell Active Support which deprecation messages to disallow.
  config.active_support.disallowed_deprecation_warnings = []

  # Use default logging formatter so that PID and timestamp are not suppressed.
  # config.log_formatter = ::Logger::Formatter.new

  # Use a different logger for distributed setups.
  # require "syslog/logger"
  # config.logger = ActiveSupport::TaggedLogging.new(Syslog::Logger.new 'app-name')

  if ENVied.RAILS_LOG_TO_STDOUT
    config.logger = ActiveSupport::TaggedLogging.new(ActiveSupport::Logger.new(STDOUT))
  end

  # Log CSRF failures
  config.action_controller.log_warning_on_csrf_failure = true

[chall8908]

@marcotc sorry for leaving this for so long. We ended up pivoting off Lograge entirely and I got pulled away to other projects.

@javierjulio has the right of it, though. We were using Lograge more-or-less out-of-the-box. That particular project is on Rails 6 when I was testing it. Before deciding to ditch Lograge entirely, I'd pared down our configuration to just enabling Lograge and setting the JSON formatter. No other configuration.

Since Lograge doesn't change the Rails.logger by default, it usually remains as an ActiveSupport::TaggedLogging instance which triggers dd-trace to set log_tags which causes the problem.

I think swapping the add_logger call from before_initialize to after_initialize and actually checking if Lograge is enabled should fix the problem, but I'm not sure if that would cause downstream problems.

[eduardohertz]

Hey 👋

I was getting the same error as @javierjulio in my logs using the same stack. I'm not sure about the side effects but I've got a fix by disabling the log injection before rails initialization. I've added Datadog.configuration.tracing.log_injection = false in my config/environment.rb before Rails.application.initialize!, and the datadog tracing prefix was removed from my JSON logs.

Be advised: I'm sure about the side-effects of this solution 😄

EDIT: thank you @chall8908 for pointing out a way

[elia]

I can confirm the solution used by @eduardohertz, in our case we put the configuration in the config/environment/*.rb files, which are loaded at the right time.

Before that we were tried to remove the DD tagger manually with #Rails.configuration.log_tags.reject! { _1.source_location.first.match? 'lib/datadog/tracing' } but it didn't look pretty.

[javierjulio]

@chall8908 since you mentioned Lograge was removed, may I ask what you replaced it with and is that new thing still doing JSON formatting for logs? I'd be open to changing ours but I'm not familiar with another alternative.

@marcotc we haven't been able to upgrade from 0.54.2 due to this bug where the logs include both JSON and text output because of ddtrace. Is there any chance of it being resolved?

[chall8908]

@javierjulio we switched to Semantic Logger which does still do JSON logging (among other things).

[too-gee]

+1 to this issue. I have several teams that are running into this or will hit it in the near future and the docs don't offer a workaround.

[TonyCTHsu]

👋 @too-gee Thanks for reporting, I will try to reproduce it and address it.

[javierjulio]

@TonyCTHsu thank you!

[TonyCTHsu]

@chall8908 @javierjulio 👋 I want to give you guys a quick update from my side.

I was able to reproduce with lograge, I want to try out with semantic_logger later.

Question: Are you using auto instrument? require: 'ddtrace/auto_instrument' in Gemfile ?

https://github.com/DataDog/dd-trace-rb/blob/master/docs/GettingStarted.md#rails-or-hanami-applications

[javierjulio]

@TonyCTHsu thanks! No, we are not using auto instrument.

[chall8908]

@TonyCTHsu our projects are using auto instrumentation.

I'd have to double check, but I recall that semantic_logger didn't have this issue because it overrides the Rails logger with its own logger, bypassing the problem code.

[artrybalko]

@TonyCTHsu We see the same issue with lograge, we use auto_instrument in our Rails projects.

[TonyCTHsu]

@chall8908 @artrybalko @javierjulio , I realized that auto instrumentation with a Rails app that would enable log injection for both lograge and Rails' ActiveSupport::TaggedLogging, which is causing the double insertion mentioned above.

Currently, the injection for ActiveSupport::TaggedLogging is only controlled by config.log_injection, hence it is a bit cumbersome to only activate Lograge without activate ActiveSupport::TaggedLogging injection.

Workaround: Configure your application explicitly with a logger what is not a ActiveSupport::TaggedLogging

Replace

config.logger = ActiveSupport::TaggedLogging.new(logger)

with

config.logger = logger

Noted that Rails is using ActiveSupport::TaggedLogging by default without any configuration

This is similar to the reason that semantic logger does not observed double insertion because semantic logger replaces the logger instance. In the future, we will be introducing a configuration option explicitly for ActiveSupport::TaggedLogging.

[artrybalko]

@TonyCTHsu Thanks for the feedback! We are switching to semantic logger as a trial. This issue wasn't the main consideration but it pushed it over the line.

[marcotc]

Sorry for the wait everyone.

I did some investigation on this issue this week and found out that lograge is not compatible with ActiveSupport::TaggedLogging when config.log_tags are set. This is especially problematic when JSON output format is configured for lograge.

There are a couple open issues in the lograge repository about this issue: roidrage/lograge#233 (comment), roidrage/lograge#255

There is no good immediate solution for this issue:

1. Use semantic_logger instead of lograge. Semantic Logger integrates with Rails named tags natively. There's no loss in observability for this solution.
2. Replace ActiveSupport::TaggedLogging with ActiveSupport::Logger:

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

   All lograge log lines will have the correct JSON format. The downside is that log lines that are not handled by lograge, for example simple Rails.logger.* calls, will not have trace correlation information.

Looking at internals of both semantic_logger and lograge, it looks at me that semantic_logger it's better equipped to handle modern versions of Rails. I would recommend using semantic_logger instead of lograge if the native ActiveSupport::TaggedLogging is not sufficient.

[javierjulio]

@marcotc thank you. We removed tagged logging as it's not something we use. It's actually better for us to provide our logs in JSON format for easy filtering. As you noted the Datadog trace correlation information is not included. Are we able to include that manually in a logger call in a safe manner?

[jnguyenalteris]

Hey, I also just wanted to follow up and see if this is also still occurring with the newest release of Datadog? We're on v2.2.0.

[ivoanjo]

We're looking at adding the extra needed steps to the docs in #3812, let us know if that works!

[marcotc]

We added an explicit message in code warning the user when this happens (and how to address it) in #3839 as well as in our public documentation #3812.

This comment above has the investigation write-up and alternatives, and explains why the issue happens between Lograge and Rails and cannot be addressed in dd-trace-rb.

[TonyCTHsu]

2.3.0 has been released.

[armstrjare]

I've come across this discussion since upgrading to 2.3.0 and seeing warning messages polluting our startup logs.

We've been using TaggedLogging outputting in JSON in production for quite a while now. The implementation of our extension to ActiveSupport::TaggedLogging in order to support this has been recently extracted to be public: https://github.com/armstrjare/rails-json-tagged-logging

It would be great to disable these warning messages somehow!

Here is the relevant parts of our lograge initialiser that merges tags and user info into the log output, and ensures clean log output. The majority of this is for adding additional tags etc to the JSON output and tweaking the message formatting:

Rails.application.configure do
  config.lograge.enabled = true

  # Use a fresh logger to separate to Lograge to avoid Tags, etc.
  config.lograge.logger = Rails.logger.dup.tap { |logger| logger.formatter = ActiveSupport::Logger::SimpleFormatter.new }
  config.lograge.formatter = Lograge::Formatters::Json.new
  config.lograge.keep_original_rails_log = Rails.env.development? || Rails.env.test?

  config.lograge.ignore_actions = ['Rails::HealthController#show', 'ActiveStorage::BlobsController#show']

  custom_options = config.lograge.custom_options
  # This executes on each log event to tweak the output, including 
  # adding relevant the tags and usr info to the JSON output.
  config.lograge.custom_options = -> event {
    # Get the original options before overriding
    options = if custom_options.respond_to?(:call)
      custom_options.call(event)
    else
      custom_options
    end

    # Get our standard set of request tags
    formatter = case Rails.logger
    when ActiveSupport::BroadcastLogger
      Rails.logger.broadcasts.first.formatter
    else
      Rails.logger.formatter
    end
    current_tags = formatter.respond_to?(:current_tags) ? formatter.current_tags : []

    tags = LogTagging.collapse_tags(current_tags)
    if usr_tags = event.payload[:usr]
      tags.deep_merge!(usr: usr_tags)
    end

    r = event.payload
    message = "Completed "
    message << "#{r[:method]} "
    message << "#{r[:controller]}##{r[:action]} "
    message << "#{r[:status]} #{Rack::Utils::HTTP_STATUS_CODES[r[:status]]} "
    message << "in #{event.duration.round}ms "
    message << "at #{r[:path]}"

    # Combine and include extra options
    (options || {}).merge(tags).merge(
      params: event.payload[:params].except(*%w(controller action format)),
      message: message
    )
  }

  unless Rails.env.development?
    config.log_tags = config.log_tags.to_a + [
      LogTagging::RequestId,
      LogTagging::RemoteIp,
      LogTagging::ClientUser
    ]
  end
end