Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
EvNomad opened this issue Jan 12, 2021 · 7 comments · Fixed by #1354
Closed

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

EvNomad opened this issue Jan 12, 2021 · 7 comments · Fixed by #1354
Labels
community Was opened by a community member

Comments

@EvNomad
Copy link

EvNomad commented Jan 12, 2021

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:

@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
Copy link
Member

marcotc commented Jan 18, 2021

👋 @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?

@marcotc marcotc added the community Was opened by a community member label Jan 18, 2021
@EvNomad
Copy link
Author

EvNomad commented Jan 19, 2021

@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.

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

Screen Shot 2021-01-19 at 10 33 10

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
Copy link
Member

marcotc commented Jan 19, 2021

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:

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
Copy link
Author

EvNomad commented Jan 19, 2021

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
Copy link
Member

marcotc commented Jan 26, 2021

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.

ivoanjo added a commit that referenced this issue Feb 5, 2021
If for some reason multiple tracers are initializing concurrently
(see customer issue in #1306 or the flaky test in
`tracer_integration_spec.rb` in the previous commit), multiple threads
can try to run `default_statsd_client` concurrently.

Because Ruby `require`s are not atomic (e.g. you can observe classes
that are half-loaded), our conditional

```ruby
require 'datadog/statsd' unless defined?(::Datadog::Statsd)
Datadog::Statsd.new(default_hostname, default_port)
```

could try to create a `Statsd` instance BEFORE the class was fully
defined, leading to
`ArgumentError: wrong number of arguments (given 2, expected 0)` when
calling `initialize`. This error stems from the custom `#initialize`
method not being available yet, so Ruby falls back to
`Object#initialize`, which does not take any argument.

See also:
* <https://slides.com/ianjo/spotting-unsafe-concurrent-ruby-patterns-fullstack-lx#/0/42/0>
* <https://gitlab.com/ivoanjo/unsafe-concurrent-ruby-patterns/-/blob/master/background_require.rb>

The fix in this case is to always call `require`. Calling `require`
repeatedly has little impact -- a given file is only loaded by
`require` the first time AND concurrent `require`s are protected --
only one thread will get to execute the require, will all others wait
until it finishes.

The follow example demonstrates this:

* `lazy-require.rb`:

```ruby
def try_require
  puts "#{Thread.current} Going to require"
  require_relative './lazy-require-sleep-1'
  puts "#{Thread.current} After require"
end

2.times.map { Thread.new { try_require } }.map(&:join)

try_require
```

* `lazy-require-sleep-1.rb`:

```ruby
puts "#{Thread.current} Running require"
sleep 1
puts "#{Thread.current} Require finished"
```

* Output:

```
$ ruby lazy-require.rb
```

Notice how two threads tried to require, but only one actually ran the
code on the other file, while the other was blocked and only woke
up after the `require` finished.

Fixes #1306
ivoanjo added a commit that referenced this issue Feb 5, 2021
If for some reason multiple tracers are initializing concurrently
(see customer issue in #1306 or the flaky test in
`tracer_integration_spec.rb` in the previous commit), multiple threads
can try to run `default_statsd_client` concurrently.

Because Ruby `require`s are not atomic (e.g. you can observe classes
that are half-loaded), our conditional

```ruby
require 'datadog/statsd' unless defined?(::Datadog::Statsd)
Datadog::Statsd.new(default_hostname, default_port)
```

could try to create a `Statsd` instance BEFORE the class was fully
defined, leading to
`ArgumentError: wrong number of arguments (given 2, expected 0)` when
calling `initialize`. This error stems from the custom `#initialize`
method not being available yet, so Ruby falls back to
`Object#initialize`, which does not take any argument.

See also:
* <https://slides.com/ianjo/spotting-unsafe-concurrent-ruby-patterns-fullstack-lx#/0/42/0>
* <https://gitlab.com/ivoanjo/unsafe-concurrent-ruby-patterns/-/blob/master/background_require.rb>

The fix in this case is to always call `require`. Calling `require`
repeatedly has little impact -- a given file is only loaded by
`require` the first time AND concurrent `require`s are protected --
only one thread will get to execute the require, will all others wait
until it finishes.

The follow example demonstrates this:

* `lazy-require.rb`:

```ruby
def try_require
  puts "#{Thread.current} Going to require"
  require_relative './lazy-require-sleep-1'
  puts "#{Thread.current} After require"
end

2.times.map { Thread.new { try_require } }.map(&:join)

try_require
```

* `lazy-require-sleep-1.rb`:

```ruby
puts "#{Thread.current} Running require"
sleep 1
puts "#{Thread.current} Require finished"
```

* Output:

```
$ ruby lazy-require.rb
 #<Thread:0x00007fc08b9081e0 lazy-require.rb:7 run> Going to require
 #<Thread:0x00007fc08b90be80 lazy-require.rb:7 run> Going to require
 #<Thread:0x00007fc08b9081e0 lazy-require.rb:7 run> Running require
 #<Thread:0x00007fc08b9081e0 lazy-require.rb:7 run> Require finished
 #<Thread:0x00007fc08b9081e0 lazy-require.rb:7 run> After require
 #<Thread:0x00007fc08b90be80 lazy-require.rb:7 run> After require
 #<Thread:0x00007fc08b85fa90 run> Going to require
 #<Thread:0x00007fc08b85fa90 run> After require
```

Notice how two threads tried to require, but only one actually ran the
code on the other file, while the other was blocked and only woke
up after the `require` finished.

Fixes #1306
@marcotc
Copy link
Member

marcotc commented Mar 3, 2021

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

@EvNomad
Copy link
Author

EvNomad commented Mar 4, 2021

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

@marcotc Thank you!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
community Was opened by a community member
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants