Dd-trace-rb: Log injection patching occurs before Lograge is configured

[Supy]

The ddtrace gem supports automatic injection of the active correlation into logs through both Rails' ActiveSupport::TaggedLogging and Lograge.

Documentation here, here and here suggest the Datadog be configured in initializers/datadog.rb and Lograge, through their default convention, be configured in initializers/lograge.rb.

Assuming one has configured both gems according to those guides, the expected behaviour is that one will see env, service, trace, span, version attributes appended to their application's logs.

This flow did not work for me, however, and I suspect this is the problem:

1. Rails executes files in initializers in alphabetical order. datadog.rb appears before lograge.rb and as such, the Datadog patching scripts execute first.
2. At this stage, Lograge has not been configured or enabled.
3. Based on the patching logic in Datadog::Contrib::Rails::Patcher#add_logger, unless app.config.respond_to?(:lograge), it will try to inject the metadata using Rails' TaggerLogging instead.

To test the theory, I have the setup suggest in the guides first:

• initializers/lograge.rb configured as per normal
• initializers/datadog.rb configured as per normal, c.use :rails, log_injection: true
• environment/development.rb has Rails.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)).

After accessing /, the following is logged:

{"method":"GET","path":"/","format":"html","controller":"Rails::WelcomeController","action":"index","status":200,"duration":17.02,"view":15.73,"db":0.0,"timestamp":"2020-10-15T09:30:59.985Z","level":"INFO","params":{}}

Next test: initialize lograge first:

• initializers/01_lograge.rb configured as per normal
• initializers/datadog.rb configured as per normal, c.use :rails, log_injection: true
• environment/development.rb has Rails.logger = ActiveSupport::TaggedLogging.new(Logger.new(STDOUT)).

After accessing /, the following is logged:

{"method":"GET","path":"/","format":"html","controller":"Rails::WelcomeController","action":"index","status":200,"duration":17.15,"view":16.02,"db":0.0,"timestamp":"2020-10-15T09:32:55.907Z","level":"INFO","params":{},"dd":{"trace_id":"4290670721401171988","span_id":"3831417033168415356","env":"","service":"xxx","version":""},"ddsource":["ruby"]}

By renaming initializers/lograge.rb to initializers/01_lograge.rb, the Datadog patcher correctly injects the metadata.

Gem versions:

rails => 4.2.11
ddtrace => 0.41.0
lograge => 0.11.2

[ericmustin]

@Supy thanks for the report. I'm scheduling some time to investigate this, but from a quick glance I would agree and say that your findings are likely correct. I'm going to investigate whether there's any remedies here as we'd really like to be able to offer lograge injection support that doesn't require modifying your lograge config.

In the meantime I'd recommend the old/more manual approach of lograge custom_options https://docs.datadoghq.com/tracing/setup/ruby/#manual-lograge

config.lograge.custom_options = lambda do |event|
  # Retrieves trace information for current thread
  correlation = Datadog.tracer.active_correlation

  {
    # Adds IDs as tags to log output
    :dd => {
      # To preserve precision during JSON serialization, use strings for large numbers
      :trace_id => correlation.trace_id.to_s,
      :span_id => correlation.span_id.to_s,
      :env => correlation.env.to_s,
      :service => correlation.service.to_s,
      :version => correlation.version.to_s
    },
    :ddsource => ["ruby"],
    :params => event.payload[:params].reject { |k| %w(controller action).include? k }
  }
end

[Supy]

@ericmustin one solution could be to patch Lograge in the current manner, but do so even when Lograge is not enabled. If it is not enabled, patching it makes no difference and results in no performance cost.

At Datadog patching time, Lograge has been "initialized" but not yet enabled - it is only enabled after Rails initialization is complete (see lograge-0.11.2/lib/lograge/railtie.rb:11).

In ddtrace/contrib/rails/patcher.rb:57: if app.config.respond_to?(:lograge) && app.config.lograge.enabled could be changed to if app.config.respond_to?(:lograge). The if-else block would need to be reworked slightly to not patch Lograge or TaggerLogging, but rather, both.

[ericmustin]

@Supy yup, I think that makes a lot of sense, I will try to prioritise this before the next release. Needless to say I personally really appreciate the thoughtfulness here.

[ericmustin]

@Supy we've released 0.42.0 that may help here https://github.com/DataDog/dd-trace-rb/releases/tag/v0.42.0 . If you're using custom_options in your initializers/lograge.rb file i believe you may still have to use the manual approach for now. Long term I think we'd like to patch the lograge gem itself

[Supy]

@ericmustin thanks for looking into this. Agree with your comments in the PR that addresses this issue. Left one small comment on it, but it is minor.

[delner]

@Supy Looks like this one is addressed? Going to close this; please feel free to comment if you think there's more to do here!

[Supy]

@delner I am unfortunately no longer working on the project that brought about this PR to offer some validation, but appreciate the resolution nonetheless. 👍🏻