ArgumentError: wrong number of arguments (given 2, expected 0)

[EvNomad]

Hi guys, please help me to understand the issue we are having.
Lately we upgraded to rails 6 and ruby 2.7 and currently we are trying to resolve all deprecation messages and move to Zeitwerk.
The problem: On every deploy to Heroku some of our dynos crash with:

2021-01-12T09:10:15.201313+00:00 app[rpush.1]: bundler: failed to load command: rpush (/app/vendor/bundle/ruby/2.7.0/bin/rpush)
2021-01-12T09:10:15.208499+00:00 app[rpush.1]: ArgumentError: wrong number of arguments (given 2, expected 0)
2021-01-12T09:10:15.208502+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:47:in `initialize'
2021-01-12T09:10:15.208502+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:47:in `new'
2021-01-12T09:10:15.208503+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:47:in `default_statsd_client'
2021-01-12T09:10:15.208503+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `block in initialize'
2021-01-12T09:10:15.208504+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `fetch'
2021-01-12T09:10:15.208504+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `initialize'
2021-01-12T09:10:15.208505+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/runtime/metrics.rb:15:in `initialize'
2021-01-12T09:10:15.208505+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:33:in `new'
2021-01-12T09:10:15.208507+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:33:in `build_runtime_metrics'
2021-01-12T09:10:15.208511+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:40:in `build_runtime_metrics_worker'
2021-01-12T09:10:15.208511+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:109:in `initialize'
2021-01-12T09:10:15.208512+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:90:in `new'
2021-01-12T09:10:15.208512+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:90:in `build_components'
2021-01-12T09:10:15.208513+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:27:in `configure'
2021-01-12T09:10:15.208513+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/contrib/extensions.rb:26:in `configure'
2021-01-12T09:10:15.208514+00:00 app[rpush.1]: /app/config/initializers/datadog_tracer.rb:5:in `<main>'
2021-01-12T09:10:15.208514+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2021-01-12T09:10:15.208515+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/bootsnap-1.5.1/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:59:in `load'
2021-01-12T09:10:15.208515+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/dependencies.rb:318:in `block in load'
2021-01-12T09:10:15.208516+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/dependencies.rb:291:in `load_dependency'
2021-01-12T09:10:15.208524+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/dependencies.rb:318:in `load'
2021-01-12T09:10:15.208525+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:666:in `block in load_config_initializer'
2021-01-12T09:10:15.208525+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/notifications.rb:182:in `instrument'
2021-01-12T09:10:15.208525+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:665:in `load_config_initializer'
2021-01-12T09:10:15.208526+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:625:in `block (2 levels) in <class:Engine>'
2021-01-12T09:10:15.208526+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:624:in `each'
2021-01-12T09:10:15.208527+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/engine.rb:624:in `block in <class:Engine>'
2021-01-12T09:10:15.208527+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:32:in `instance_exec'
2021-01-12T09:10:15.208528+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:32:in `run'
2021-01-12T09:10:15.208528+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:61:in `block in run_initializers'
2021-01-12T09:10:15.208529+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:228:in `block in tsort_each'
2021-01-12T09:10:15.208529+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
2021-01-12T09:10:15.208530+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
2021-01-12T09:10:15.208530+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:431:in `each_strongly_connected_component_from'
2021-01-12T09:10:15.208530+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
2021-01-12T09:10:15.208531+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:50:in `each'
2021-01-12T09:10:15.208531+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:50:in `tsort_each_child'
2021-01-12T09:10:15.208532+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:415:in `call'
2021-01-12T09:10:15.208532+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:415:in `each_strongly_connected_component_from'
2021-01-12T09:10:15.208540+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:349:in `block in each_strongly_connected_component'
2021-01-12T09:10:15.208540+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `each'
2021-01-12T09:10:15.208541+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `call'
2021-01-12T09:10:15.208541+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:347:in `each_strongly_connected_component'
2021-01-12T09:10:15.208542+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:226:in `tsort_each'
2021-01-12T09:10:15.208542+00:00 app[rpush.1]: /app/vendor/ruby-2.7.2/lib/ruby/2.7.0/tsort.rb:205:in `tsort_each'
2021-01-12T09:10:15.208543+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/initializable.rb:60:in `run_initializers'
2021-01-12T09:10:15.208543+00:00 app[rpush.1]: /app/vendor/bundle/ruby/2.7.0/gems/railties-6.0.3.4/lib/rails/application.rb:363:in `initialize!'
2021-01-12T09:10:15.208544+00:00 app[rpush.1]: config/environment.rb:3:in `<top (required)>'

It could be Sidekiq and Sneakers but not a web dyno.

It seems like here:

dd-trace-rb/lib/ddtrace/metrics.rb

Line 16 in a770176

@statsd = options.fetch(:statsd) { default_statsd_client if supported? }

the problem is with initialising default_statsd_client

After adding Statsd client with default values to the initialiser the dynos stopped crashing

c.tracer.enabled = true
c.runtime_metrics.enabled = true
c.runtime_metrics.statsd = Datadog::Statsd.new('127.0.0.1', 8125)

But... We also upgraded the Airbrake gem and it added a mechanism that polls for remote configurations every x seconds. Once I disabled it, the crashes also stopped (without the mentioned fix).

Can you please elaborate on that error?

[marcotc]

👋 @EvNomad, thanks for reaching out.

I'm also not sure where a zero argument initializer for dogstatsd would come from.
Would you be able to record the result of Datadog::Statsd.instance_method(:initialize).source right before you get this error?

I see your application last has control of the stack frame at /app/config/initializers/datadog_tracer.rb:5, so I'd suggest capturing it at line 4 of this file.

One thing I can think of: are you requiring require 'datadog/statsd' before your Datadog.configure?

[EvNomad]

@marcotc Thank you for your response!

We never had the require 'datadog/statsd' in the initialiser. I see that it is required inside the default_statsd_client method.

dd-trace-rb/lib/ddtrace/metrics.rb

Line 44 in dba4c21

require 'datadog/statsd' unless defined?(::Datadog::Statsd)

So, in order to print out the source I had to add the require and it helped (also with the weird airbrake config turned back on)

Here is the output of Datadog::Statsd.instance_method(:initialize).source

This is our initialiser:

require 'ddtrace'

Datadog.configure do |c|
  c.tracer.enabled = true
  c.runtime_metrics.enabled = true
  c.use(:rails, analytics_enabled: true)
  c.use(:redis, analytics_enabled: true)
  c.use(:sidekiq, analytics_enabled: true)
  c.use(:dalli, analytics_enabled: true)
end

BTW the only place I found the same stack trace is here: #1163

Any ideas what should be investigated further?

Thank you!

[marcotc]

Thank you for pointing out #1163, @EvNomad, I think it helps understand the issue you are seeing.

#1163 was caused by concurrent threads racing to call:

dd-trace-rb/lib/ddtrace/metrics.rb

Lines 44 to 47 in dba4c21

	require 'datadog/statsd' unless defined?(::Datadog::Statsd)
	# Create a StatsD client that points to the agent.
	Datadog::Statsd.new(default_hostname, default_port)

When I reproduced the same error you are having locally, I caught the application half-way through requiring dogstatsd in another thread, for example running line 5 here https://github.com/DataDog/dogstatsd-ruby/blob/e665cfb11793cee07215c3d8a2132d561edd0ea6/lib/datadog/statsd.rb#L5 on a separate thread.

This causes defined?(::Datadog::Statsd) to return true, as the path class Datadog::Statsd has already been partially defined, but not all methods (including the initializer) have not been defined yet.

With this in mind: I suspect your environment has multiple threads initializing or Datadog.configure ddtrace, is that the case? If you are not sure, I advise recording the result of all threads stack tracek to your logs, close to your Datadog.configure block: Thread.list.map{|x|[x, x.backtrace]}. This is how I found the concurrent access when I was able to reproduce the issue.

We advise against concurrent initialization of the tracer, as ddtrace not fully concurrency-safe during the configuration process. After initialized, it works fine in a concurrent environment.

If concurrent initialization is a requirement for you, I'd like to understand your setup, as this would be a new requirement for the library.

[EvNomad]

Thank you for this idea Thread.list.map{|x|[x, x.backtrace]}
We use Lograge for web dynos. For non web processes like rpush for example I've added json formatter and injected Datadog.tracer.active_correlation.
Here is a part of remote settings thread backtrace:

"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:44:in `default_statsd_client'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `block in initialize'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `fetch'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/metrics.rb:16:in `initialize'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/runtime/metrics.rb:15:in `initialize'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:33:in `new'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:33:in `build_runtime_metrics'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:40:in `build_runtime_metrics_worker'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration/components.rb:109:in `initialize'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:90:in `new'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:90:in `build_components'",
"/app/vendor/bundle/ruby/2.7.0/gems/ddtrace-0.43.0/lib/ddtrace/configuration.rb:84:in `components'",
"/app/vendor/ruby-2.7.2/lib/ruby/2.7.0/forwardable.rb:229:in `tracer'",
"/app/lib/cheetah/logger/json_formatter.rb:22:in `default_data'",
"/app/lib/cheetah/logger/json_formatter.rb:8:in `call'",
"/app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/tagged_logging.rb:23:in `call'",
"/app/vendor/ruby-2.7.2/lib/ruby/2.7.0/logger.rb:585:in `format_message'",
"/app/vendor/ruby-2.7.2/lib/ruby/2.7.0/logger.rb:475:in `add'",
"/app/vendor/bundle/ruby/2.7.0/gems/activesupport-6.0.3.4/lib/active_support/logger_thread_safe_level.rb:53:in `add'",
"/app/vendor/ruby-2.7.2/lib/ruby/2.7.0/logger.rb:494:in `debug'",
"/app/vendor/bundle/ruby/2.7.0/gems/airbrake-ruby-5.2.0/lib/airbrake-ruby/remote_settings/callback.rb:18:in `call'",
"/app/vendor/bundle/ruby/2.7.0/gems/airbrake-ruby-5.2.0/lib/airbrake-ruby/config/processor.rb:49:in `block in process_remote_configuration'",
"/app/vendor/bundle/ruby/2.7.0/gems/airbrake-ruby-5.2.0/lib/airbrake-ruby/remote_settings.rb:54:in `block in poll'"]]]

It seems like the Airbrake thread produces debug level log which call the tracer and races with the main thread.
I'll disable this feature in airbrake for now and will think about more elegant solution.

[marcotc]

As we are moving towards addressing this issue, with safe concurrent initialization of the tracer, I'll record here steps to reproduce this issue that when I dug into this issue:

With Ruby 2.6, revision feb2047 of ddtrace:

bundle exec rspec --seed=28572 ./spec/ddtrace/tracer_integration_spec.rb

This will result in ArgumentError: wrong number of arguments (given 2, expected 0) due to concurrent require 'datadog/statsd' calls.

It might take a few tries, given the concurrent nature of the failure.

[marcotc]

👋 @EvNomad, we've just released 0.46.0, which includes a fix for the root cause of this issue.

[EvNomad]

👋 @EvNomad, we've just released 0.46.0, which includes a fix for the root cause of this issue.

@marcotc Thank you!