Stack Level too deep (SystemStackError)

[ManevilleF]

Hello,

I installed the gem ddtrace on my rails application and created the config file as the documentation says:

config/initializers/datadog-tracer.rb:

Datadog.configure do |c|
  c.use :rails
end

Gemfile.lock extract:

ddtrace (0.18.0)
      msgpack
      opentracing (>= 0.4.1)

If I attempt to access my active record models, event something like MyObject.count I receive the following error:

SystemStackError: stack level too deep
from /.rbenv/versions/2.4.3/lib/ruby/gems/2.4.0/gems/activesupport-5.0.7/lib/active_support/core_ext/object/json.rb:161:in `dup'

If I remove the config file or remove the line in the do-end block everything works again.

[tjgrathwell]

I'm getting this too, as of ddtrace 0.18. We rolled back to 0.17.3 because all sorts of commands crash, though possibly only in development or test envs because we had it deployed in production for some time.

Here's the relevant part of the stack trace

/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:56:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `each'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `map'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:56:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `each'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `map'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:56:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `block in as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `each'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `map'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:171:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:56:in `as_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/json/encoding.rb:35:in `encode'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/json/encoding.rb:22:in `encode'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/core_ext/object/json.rb:41:in `to_json'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:42:in `block in json_encodable'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:62:in `block in transform_hash'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:56:in `each'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:56:in `inject'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:56:in `transform_hash'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:36:in `json_encodable'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/event.rb:13:in `initialize'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/app_notifications.rb:51:in `new'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/app_notifications.rb:51:in `block in <class:AppNotifications>'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/meta_request-0.6.0/lib/meta_request/app_notifications.rb:78:in `block in subscribe'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:129:in `finish'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `block in finish'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `each'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/fanout.rb:48:in `finish'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:44:in `finish_with_state'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/activesupport-5.2.2/lib/active_support/notifications/instrumenter.rb:29:in `instrument'
/Users/travis/.rbenv/versions/2.5.1/lib/ruby/gems/2.5.0/gems/ddtrace-0.18.0/lib/ddtrace/contrib/active_record/patches/abstract_adapter.rb:63:in `block (2 levels) in insert_shim!'

I traced it as far as the insert_shim! code which is new in ddtrace 0.18. I think the :connection object it adds to the args is getting jsonified but maybe has circular references that cause it to spin forever.

If I comment out the part that adds :connection to the args on

dd-trace-rb/lib/ddtrace/contrib/active_record/patches/abstract_adapter.rb

Line 59 in 6c3554c

args[1][:connection] ||= connection

it doesn't crash

[delner]

Ahhh okay, thanks for reporting this one. We're going to take a look at this ASAP, likely related to #649. I would recommend a downgrade to 0.17.3 in the mean time.

[delner]

@EpiFouloux or @tjgrathwell , do you have a snippet of code or a test we can run to reproduce the problem in a test environment? Want to make sure we're fixing this properly.

[tjgrathwell]

@delner I tried making a minimum viable rails app right now (ruby 2.5.1, rails 5.2, postgres, just adding the ddtrace gem) but it didn't seem to exhibit the problem our real app does

Since the meta_request gem was also present in the stack trace I posted, I tried that too and it caused the crash. So I guess the issue only shows when using both ddtrace and meta_request, though it's possible @EpiFouloux is seeing the issue with a different gem.

(I don't think our project actually uses meta_request anymore, so we could remove it, but it's possible other gems also do whatever meta_request is doing)

So the minimum viable case I can reduce it to is:

rails new my_cool_datadog_project

add this to the gemfile:

gem 'ddtrace'
gem 'meta_request'

add this to config/initializers/datadog.rb

Datadog.configure do |c|
  c.tracer enabled: false
  c.use :rails
end

then do anything that accesses ActiveRecord in development, like rake db:migrate

[delner]

Okay, maybe he's using the same gem, but maybe instead there's some common thread that's causing incompatibility with other gems as well. I'll give that a shot, thanks @tjgrathwell . Let me know if you find anything else.

[delner]

@tjgrathwell Have another question for you... can you try rails/rails#34602 without ddtrace but with meta_request and see if this replicates things?

Part of me suspects that in trying to replicate a future Rails feature, passing an object in the event args instead of a simple serializable value might be causing this. Possibly because meta_request or other gems are trying to serialize the event args, and the connection object doesn't serialize well.

This is just a hypothesis though, still need to do more fact finding.

[delner]

Okay, this is definitely because we're putting a non-serializable object into the event args. I can confirm this error also occurs with rails/rails#34602 and without ddtrace, so my thinking is this is a version incompatibility of serialization gems like meta_request with Rails 6+.

Because ddtrace definitely should support Rails < v6, we will implement an alternative that doesn't create this kind of incompatibility with existing serialization gems. Likely #647 from @guizmaii.

[delner]

@tjgrathwell and @EpiFouloux , I opened #662, which I've tested against a Rails app in which I recreated this error; the PR appears to fix it. Would you like to give it a shot to confirm it solves your issue?

I'll probably put this in a 0.18.1 release for either tonight or tomorrow.

[ManevilleF]

Thank you very much @delner and @tjgrathwell for the quick responses and help, I'm sorry I didn't react soon enough to help.

I'm trying the 0.18.1 right away, I will come back soon with the answer. If it doesn't work I will try the downgrade to 0.17.3

[ManevilleF]

@delner I upgraded to 0.18.1 and it works, I have a new error after the first attempt to access the database:

[2018-12-21T09:30:52.045674 #7686] ERROR -- ddtrace: [ddtrace] (/home/felixdemaneville/.rbenv/versions/2.4.3/lib/ruby/gems/2.4.0/gems/ddtrace-0.18.1/lib/ddtrace/transport.rb:215:in `log_error_once') Failed to open TCP connection to 127.0.0.1:8126 (Connection refused - connect(2) for "127.0.0.1" port 8126)
Which is probably because I did not set up the DD_TRACE_HOST and DD_TRACE_PORT

But issue is fixed for me, I suggest we wait for @tjgrathwell answer before closing the issue

[delner]

Okay, glad to hear that the original issue is fixed.

Regarding the connections, it will default to 127.0.0.1:8126 without any env vars or configuration supplied. If your agent is running at a different location, you can configure it in Datadog.configure or use those DD_TRACE_HOST and DD_TRACE_PORT env vars. This was a new thing for 0.18.0 to make it easier for our users with containerized deployments.

[tjgrathwell]

@delner Seems to work for me, thanks for the fix!

[delner]

Awesome, thanks guys, closing this issue.

[amundra2016]

Hi @delner , I am facing a similar issue what has been described above.

[ddtrace] (/usr/local/bundle/gems/ddtrace-0.18.2/lib/ddtrace/transport.rb:215:in `log_error_once') execution expired

However I dont understand the entire solution that you have provided. I have configured my ruby application like this

Datadog.configure do |c|
  c.tracer hostname: 'dd-agent', port: 8126
  c.use :rack
  c.use :mongo
  c.use :sidekiq
  c.use :http
  c.use :puma
end

Here dd-agent is the datadog/agent container present on the same docker network, so this also reachable.Where and how should I use these env vars DD_TRACE_HOST and DD_TRACE_PORT (I am not finding relevant docs for it). Would be very nice if you give a little description also.
Thanks!!

[delner]

@amundra2016 The error you're seeing is likely unrelated. It appears, from what we can tell right now, to come from Net/HTTP throwing timeout errors upon failing to establish a TCP connection to the agent. This could happen for a number of reasons, however, according to https://stackoverflow.com/questions/42036133/ruby-netopentimeout-execution-expired it might be caused by DNS resolution failure (possibly your dd-agent hostname). I would check to make sure the agent is accessible from the container/host in question, using the same parameters as the tracer is configured with.

If you have further questions about this connectivity issue, I would suggest opening a ticket with our support team, as they might be able to help you, and since this problem appears unrelated to this Github issue.

[amundra2016]

Hi @delner , thanks for the response, yes that was the problem with it, Using IP or gem suggested in link worked quite nicely.
Thanks again 🙇

[ndbroadbent]

Hello, I think I might have suddenly started experiencing a similar issue.

• ddtrace (0.24.0)
• rails (5.2.3)

SystemStackError: stack level too deep
  from active_support/core_ext/object/json.rb:171:in `dup'
  from active_support/core_ext/object/json.rb:171:in `block in as_json'
  from active_support/core_ext/object/json.rb:171:in `each'
  from active_support/core_ext/object/json.rb:171:in `map'
  from active_support/core_ext/object/json.rb:171:in `as_json'
  from active_support/core_ext/object/json.rb:171:in `block in as_json'
  from active_support/core_ext/object/json.rb:171:in `each'
  from active_support/core_ext/object/json.rb:171:in `map'
  from active_support/core_ext/object/json.rb:171:in `as_json'
  from active_support/core_ext/object/json.rb:56:in `as_json'
  from active_support/core_ext/object/json.rb:171:in `block in as_json'
  from active_support/core_ext/object/json.rb:171:in `each'
  from active_support/core_ext/object/json.rb:171:in `map'
  from active_support/core_ext/object/json.rb:171:in `as_json'
  from active_support/core_ext/object/json.rb:171:in `block in as_json'
...
  from active_support/core_ext/object/json.rb:171:in `each'
  from active_support/core_ext/object/json.rb:171:in `map'
  from active_support/core_ext/object/json.rb:171:in `as_json'
  from active_support/core_ext/object/json.rb:171:in `block in as_json'
  from active_support/core_ext/object/json.rb:171:in `each'
  from active_support/core_ext/object/json.rb:171:in `map'
  from active_support/core_ext/object/json.rb:171:in `as_json'
  from active_support/json/encoding.rb:35:in `encode'
  from active_support/json/encoding.rb:22:in `encode'
  from active_record/type/json.rb:18:in `serialize'
  from active_model/type/helpers/mutable.rb:8:in `cast'
  from active_model/attribute.rb:175:in `type_cast'
  from active_model/attribute.rb:42:in `value'
  from active_model/attribute_set.rb:48:in `fetch_value'
  from active_record/attribute_methods/read.rb:77:in `_read_attribute'
  from active_record/attribute_methods/read.rb:40:in `__temp__46f63657d656e647f546164716'

I searched from active_support/core_ext/object/json.rb:171:in dup on Google and found this issue, and I think it might be related since I'm also using the ddtrace gem in my app (although it doesn't appear anywhere in my stack trace.)

I also have:

  Datadog.configure do |c|
    # This will activate auto-instrumentation for Rails
    c.use :rails
    # ...
  end

This issue just started happening today for one random Sidekiq job, and I haven't really changed anything in my Gemfile recently. Maybe it just hit the one code path that caused this infinite loop.

[ndbroadbent]

Hello, this wasn't related to ddtrace! I updated to ddtrace (0.28.0) and the infinite loop was still happening. It turns out that it was something else that was causing the circular references in my own code. Sorry to bother you!