Deadlock error since version 1.14.0

[joeosburn]

I've been using DataDog for several years without issue on a ruby project. Since version 1.14.0, up to the most recent version, 1.19.0, I've run into a deadlocking issue related to the logger configuration I use.

I now get this error:

2024-01-16T22:19:21.767Z pid=249 tid=5qt WARN: ThreadError: deadlock; recursive locking
2024-01-16T22:19:21.768Z pid=249 tid=5qt WARN: /Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/core/configuration.rb:228:in `synchronize'
/Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/core/configuration.rb:228:in `safely_synchronize'
/Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/core/configuration.rb:195:in `components'
/Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/tracing.rb:134:in `components'
/Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/tracing.rb:138:in `tracer'
/Users/joe/.rvm/gems/ruby-3.2.2/gems/ddtrace-1.19.0/lib/datadog/tracing.rb:76:in `correlation'
/Users/joe/projects/api/config/api.rb:67:in `block (2 levels) in logger'
...

It appears to be related to the interaction of DataDog within my logger code.

Here is what my DataDog configuration looks like:

Datadog.configure do |c|
  ...
  c.logger.instance = Api.logger
  ...
end

If I comment out the c.logger.instance = line, the error goes away.

In my Api.logger code, I have this code:

correlation = Datadog::Tracing.correlation
data[:dd] = {
  trace_id: correlation.trace_id,
  span_id: correlation.span_id
}

This is because my logger instance needs tracing data from DataDog. Again, if I comment this code out, the error goes away.

This was working fine until version 1.14.0 and then something changed. I am currently on Ruby 3.2.2

[benhutton]

to add some details here,

We maintain a ruby app that uses Ougai for structured logging. We have followed your instructions for adding trace correlation to our structured logging.

So we are adding Datadog trace correlation data to the Ougai logger, and we are configuring Datadog to use the Ougai logger as its logger.

It seems that something changed in 1.14.0 to make that no longer supported.

Is this a bug in this gem, or is there something we need to change about our usage of it?

[ivoanjo]

Hey! This is definitely an interesting one. The ddtrace logger can get called during initialization, and by chaining it back to ddtrace, it hits this issue. 😅

I'm guessing even if we didn't have locking, we might've had some recursion on our hands... 🤔

What may be happening here is that something is trying to log information in 1.19 that didn't before in 1.14.

To investigate this further, do you mind sharing the full backtrace from the deadlock? The backtrace you shared unfortunately doesn't show what thread deadlocked and in what part of the code it was when it tried to log.

[benhutton]

@ivoanjo take a look at this: https://gist.github.com/benhutton/c28099f46d6a582c3c9e567dc481d32e

That's a backtrace I got when trying to book up a console on heroku. I think the "real" error is the bottom one, then it triggered the ones above it.

Also, to be clear, 1.13.1 is the last version that work. Whatever broke it broke it in 1.14.0.

[ivoanjo]

Ahh, it's the environment logger... that would fit with the change in #3020 that we merged for 1.14.0. That information used to be logged later in the gem life cycle, and we moved it to earlier.

It's possible to disable this behavior by setting the DD_TRACE_STARTUP_LOGS env variable to false and/or via code in your configure block:

Datadog.configure { |c| c.diagnostics.startup_logs.enabled = false }

[joeosburn]

That solution gets us going. What's the long term fix for this scenario?

[ivoanjo]

Great! Let me bring this back to the team and see what we can do to avoid this sharp edge.

[ivoanjo]

PR to fix this #3426 :)

[joeosburn]

Thank you.

[TonyCTHsu]

👋 @joeosburn , 1.20.0 has been released! Give it a try 👍

[joeosburn]

Success! Works great.