unable to disable log_injection

[Kallin]

Current behaviour
logs include dd_trace details, like

[dd.service=finance_it dd.trace_id=470572845010387719 dd.span_id=2086160090212041436]   Rendered layouts/_some_page.html.haml (333.6ms)

even though Datadog.configuration.tracing.log_injection is set to false.

Expected behaviour
Datadog.configuration.tracing.log_injection should be respected

Steps to reproduce
set Datadog.configuration.tracing.log_injection to true, observe logs still contain the trace details.

Environment

• ddtrace version: 1.8.0
• Configuration block (Datadog.configure ...):
• Ruby version: 2.5.7
• Operating system: OSX Ventura, 13.1

** further **

This seems to be due to this code, https://github.com/DataDog/dd-trace-rb/blob/master/lib/datadog/tracing/contrib/rails/patcher.rb#L45 , which runs before any of the configuration values can be set.

All I'm trying to do here is keep the logs less cluttered for development. Is there a recommended way to disable datadog for development? Should I just do it at the gemfile level?

[TonyCTHsu]

👋 @Kallin , thanks for reporting!

I have taken sometime looking into this. Unfortunately, I was not able to reproduce your case(with the Ruby 2.7 and Rails 6).

Datadog.configure do |c|
  c.env = 'integration'
  c.service = 'MyService'
  c.tracing.log_injection = false
  c.tracing.instrument :rails
end

I am able to control the behaviour by toggling c.tracing.log_injection. It is worth noticing that it is default enabled and the environment variable DD_LOGS_INJECTION is used to configure c.tracing.log_injection when not explicitly set.

However, I understand the logger's behaviour is highly configurable in Rails (config.log_formatter, config.logger, config.log_tags) even based on your environment (config/environments/development.rb, config/environments/production.rb). It is not surprising that I won't be able to reproduce your issue without having a clear understanding about your Rails environment setup.

Our tracer leverage the config.log_tags as you pointed out. You could verified it by

logger.formatter.current_tags

I wonder what is the result of yours?

[thomasdziedzic-calmwave]

I am also seeing this:

  c.tracing.log_injection = false

does not disable the log tags for me as well in the development rails environment.

I verified that the following tag exists during a controller action in development:

(ruby) Rails.logger.formatter.current_tags
["dd.env=development dd.service=REDACTED dd.trace_id=REDACTED dd.span_id=0"]

Using ddtrace 1.8.0

To fix this, I added:

# remove once https://github.com/DataDog/dd-trace-rb/issues/2542 is fixed
Datadog.configuration.tracing.log_injection = false

to the top of my config/environments/development.rb and config/environments/test.rb files.

[TonyCTHsu]

👋 @thomasdziedzic-calmwave Could you provide me your version for ruby and rails ?

I could try to reproduce with such your description

[thomasdziedzic-calmwave]

I'm using ruby 3.1.3 and rails 7.0.4

I created a repo that reproduces the issue at https://github.com/thomasdziedzic-calmwave/ddtrace_issue_2542

thomasdziedzic-calmwave/ddtrace_issue_2542@e01b85f reproduces the issue

for example:

[dd.service=ddtrace_issue2542 dd.trace_id=1776694316476370328 dd.span_id=369807288675348954] Started GET "/home/index" for 127.0.0.1 at 2023-01-17 08:13:07 -0600

thomasdziedzic-calmwave/ddtrace_issue_2542@c45537c is my current workaround to disable these log tags

to repro, remove the workaround, and run bin/rails s, visit localhost:3000/home/index and see that the tags are attached from ddtrace even when the initializer has log_injection turned off.

to see the workaround in action, run the same commands, but with the workaround left in place in development.rb

[TonyCTHsu]

👋 @thomasdziedzic-calmwave, Thanks for your awesome repository for reproducing this issue.

I am able to reproduce with the example and I believe it is related to the way we provide auto instrumentation.

gem 'ddtrace', require: 'ddtrace/auto_instrument'

Our auto instrumentation leverage railtie to hook into initialization process, even before loading initializers (where log injection being overwritten to false.). This mechanism is skipped by removing require: 'ddtrace/auto_instrument' from the Gemfile.

With auto instrumentation, I would recommend providing an environment variable DD_LOGS_INJECTION=false in your development environment to disable log injection(since overwriting with initializer is too late). It could depends on the tool you use for handling environment variable(such as dotenv or Figaro), but with your repo as an example, you can simply run rails s command with the environment variable, like:

DD_LOGS_INJECTION=false bundle exec rails s

Let me know if it helps 😄

[thomasdziedzic-calmwave]

Our auto instrumentation leverage railtie to hook into initialization process, even before loading initializers (where log injection being overwritten to false.). This mechanism is skipped by removing require: 'ddtrace/auto_instrument' from the Gemfile.

Is there a reason that the auto instrumentation injects the log tags so early?
Couldn't it inject log tags after initialization and it would fix this issue?
Since no requests are being served before initialization, I don't see why it needs to inject so early.

[Kallin]

Any reason https://github.com/DataDog/dd-trace-rb/blob/master/lib/datadog/tracing/contrib/rails/patcher.rb#L45 can't be pulled out of the before_initialize? I think it's a bit much to ask everyone to always add DD_LOGS_INJECTION=false whenever running their app.

@thomasdziedzic-calmwave, thanks for the suggestion, I'll try that workaround in the interim. And thanks everyone for looking into this!

[TonyCTHsu]

👋 @Kallin @thomasdziedzic-calmwave , I think the assumption for configuring the behaviour in the initializer make sense. We will be working on to improve this, in the meanwhile, adding DD_LOGS_INJECTION=false would be the mitigation for now.

[simi]

ℹ️ I tried to address this by removing tags based on proc source location since there is no easy way to provide ENV vars in related project. Looking for proper solution as well. 🙏

original_tags = Array.wrap(Rails.application.config.log_tags).reject! { |tag| tag&.source_location&.include?('datadog') }
Rails.application.config.log_tags = original_tags