opentelemetry-ruby icon indicating copy to clipboard operation
opentelemetry-ruby copied to clipboard

Published 20 hours ago • verified publisher icon open-telemetry

"stack level too deep" on redis trace

Open treyhyde opened this issue 4 years ago • 9 comments

Rails 6 / unicorn application with c.use_all

This happens with and without prometheus instrumentation enabled. So may or may not be related to open-telemetry/opentelemetry-ruby#352

/app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-api-0.12.1/lib/opentelemetry/context.rb:110:in `value': stack level too deep (SystemStackError)
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-api-0.12.1/lib/opentelemetry/trace.rb:62:in `current_span'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-sdk-0.12.1/lib/opentelemetry/sdk/trace/samplers/constant_sampler.rb:30:in `should_sample?'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-sdk-0.12.1/lib/opentelemetry/sdk/trace/samplers/parent_based.rb:56:in `should_sample?'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-sdk-0.12.1/lib/opentelemetry/sdk/trace/tracer.rb:47:in `start_span'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-api-0.12.1/lib/opentelemetry/trace/tracer.rb:28:in `in_span'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-instrumentation-redis-0.12.0/lib/opentelemetry/instrumentation/redis/patches/client.rb:18:in `call'
	from (eval):9:in `call'
	from /app/vendor/bundle/ruby/2.6.0/gems/opentelemetry-instrumentation-redis-0.12.0/lib/opentelemetry/instrumentation/redis/patches/client.rb:23:in `block in call'
	 ... 9346 levels...
	from /app/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `load'
	from /app/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `<main>'
	from /app/vendor/bundle/ruby/2.6.0/bin/ruby_executable_hooks:24:in `eval'
	from /app/vendor/bundle/ruby/2.6.0/bin/ruby_executable_hooks:24:in `<main>'
Screen Shot 2021-01-26 at 3 43 14 PM

treyhyde avatar Jan 26 '21 23:01 treyhyde

This happens with and without prometheus instrumentation enabled. So may or may not be related to #352

What other gems do you have loaded (that may contain instrumentation)?

fbogsany avatar Jan 28 '21 15:01 fbogsany

raindrops, prometheus exporter, maybe something in unicorn hooks? Certainly nothing intentional.

treyhyde avatar Jan 29 '21 03:01 treyhyde

This is the same problem as #352. Prometheus exporter uses alias_method to patch methods in Redis::Client and other classes: https://github.com/discourse/prometheus_exporter/blob/master/lib/prometheus_exporter/instrumentation/method_profiler.rb

fbogsany avatar Jan 29 '21 14:01 fbogsany

Hmm, you mentioned that the problem occurred even with Prometheus exporter instrumentation disabled. Can you remove Prometheus exporter altogether to confirm whether that's the problem?

I looked through Raindrops and couldn't find anything suspicious.

fbogsany avatar Jan 29 '21 14:01 fbogsany

Right, full on removing the prometheus_exporter gem from the bundle does the trick.

Screen Shot 2021-02-01 at 9 28 55 AM

treyhyde avatar Feb 01 '21 17:02 treyhyde

We have the same problem after updated from 0.19.3 to 0.19.4

After a downgrade to 0.19.3 it works again

Here the stack:

SystemStackError: stack level too deep
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/instance_variables.rb:15:in `map'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:175:in `block in as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:174:in `each'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:174:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:58:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:154:in `block in as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:154:in `map'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:154:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:175:in `block in as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:174:in `each'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:174:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:58:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:154:in `block in as_json'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:154:in `map'
.......
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:174:in `as_json'
  from activesupport (6.1.4.1) lib/active_support/json/encoding.rb:35:in `encode'
  from activesupport (6.1.4.1) lib/active_support/json/encoding.rb:22:in `encode'
  from activesupport (6.1.4.1) lib/active_support/core_ext/object/json.rb:43:in `to_json'
  from logstasher (2.1.5) lib/logstasher/event.rb:27:in `to_json'
  from logstasher (2.1.5) lib/logstasher/action_view/log_subscriber.rb:36:in `logstash_event'
  from logstasher (2.1.5) lib/logstasher/action_view/log_subscriber.rb:13:in `render_template'
  from activesupport (6.1.4.1) lib/active_support/subscriber.rb:150:in `finish'
......
  from actionpack (6.1.4.1) lib/abstract_controller/base.rb:228:in `process_action'
  from actionpack (6.1.4.1) lib/abstract_controller/callbacks.rb:42:in `block in process_action'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:117:in `block in run_callbacks'
  from actiontext (6.1.4.1) lib/action_text/rendering.rb:20:in `with_renderer'
  from actiontext (6.1.4.1) lib/action_text/engine.rb:59:in `block (4 levels) in <class:Engine>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:137:in `run_callbacks'
  from actionpack (6.1.4.1) lib/abstract_controller/callbacks.rb:41:in `process_action'
  from actionpack (6.1.4.1) lib/abstract_controller/base.rb:165:in `process'
  from actionmailer (6.1.4.1) lib/action_mailer/rescuable.rb:25:in `block in process'
  from actionmailer (6.1.4.1) lib/action_mailer/rescuable.rb:17:in `handle_exceptions'
  from actionmailer (6.1.4.1) lib/action_mailer/rescuable.rb:24:in `process'
  from actionview (6.1.4.1) lib/action_view/rendering.rb:39:in `process'
  from actionmailer (6.1.4.1) lib/action_mailer/base.rb:615:in `block in process'
  from activesupport (6.1.4.1) lib/active_support/notifications.rb:203:in `block in instrument'
  from activesupport (6.1.4.1) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
  from activesupport (6.1.4.1) lib/active_support/notifications.rb:203:in `instrument'
  from actionmailer (6.1.4.1) lib/action_mailer/base.rb:614:in `process'
  from actionmailer (6.1.4.1) lib/action_mailer/parameterized.rb:143:in `block in processed_mailer'
  from actionmailer (6.1.4.1) lib/action_mailer/parameterized.rb:141:in `tap'
  from actionmailer (6.1.4.1) lib/action_mailer/parameterized.rb:141:in `processed_mailer'
  from actionmailer (6.1.4.1) lib/action_mailer/message_delivery.rb:118:in `deliver_now'
  from actionmailer (6.1.4.1) lib/action_mailer/mail_delivery_job.rb:23:in `perform'
  from activejob (6.1.4.1) lib/active_job/execution.rb:48:in `block in perform_now'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:117:in `block in run_callbacks'
  from sentry-raven (3.1.2) lib/raven/integrations/rails/active_job.rb:13:in `block (2 levels) in included'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from i18n (1.8.10) lib/i18n.rb:314:in `with_locale'
  from activejob (6.1.4.1) lib/active_job/translation.rb:9:in `block (2 levels) in <module:Translation>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activesupport (6.1.4.1) lib/active_support/core_ext/time/zones.rb:66:in `use_zone'
  from activejob (6.1.4.1) lib/active_job/timezones.rb:9:in `block (2 levels) in <module:Timezones>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activejob (6.1.4.1) lib/active_job/instrumentation.rb:21:in `block in instrument'
  from activesupport (6.1.4.1) lib/active_support/notifications.rb:203:in `block in instrument'
  from activesupport (6.1.4.1) lib/active_support/notifications/instrumenter.rb:24:in `instrument'
  from activesupport (6.1.4.1) lib/active_support/notifications.rb:203:in `instrument'
  from activejob (6.1.4.1) lib/active_job/instrumentation.rb:31:in `instrument'
  from activejob (6.1.4.1) lib/active_job/instrumentation.rb:14:in `block (2 levels) in <module:Instrumentation>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activejob (6.1.4.1) lib/active_job/logging.rb:22:in `block in tag_logger'
  from activesupport (6.1.4.1) lib/active_support/tagged_logging.rb:99:in `block in tagged'
  from activesupport (6.1.4.1) lib/active_support/tagged_logging.rb:37:in `tagged'
  from activesupport (6.1.4.1) lib/active_support/tagged_logging.rb:99:in `tagged'
  from activejob (6.1.4.1) lib/active_job/logging.rb:22:in `tag_logger'
  from activejob (6.1.4.1) lib/active_job/logging.rb:15:in `block (2 levels) in <module:Logging>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:137:in `run_callbacks'
  from activejob (6.1.4.1) lib/active_job/execution.rb:47:in `perform_now'
  from activejob (6.1.4.1) lib/active_job/execution.rb:25:in `block in execute'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:117:in `block in run_callbacks'
  from activejob (6.1.4.1) lib/active_job/railtie.rb:47:in `block (4 levels) in <class:Railtie>'
  from activesupport (6.1.4.1) lib/active_support/execution_wrapper.rb:88:in `wrap'
  from activesupport (6.1.4.1) lib/active_support/reloader.rb:72:in `block in wrap'
  from activesupport (6.1.4.1) lib/active_support/execution_wrapper.rb:84:in `wrap'
  from activesupport (6.1.4.1) lib/active_support/reloader.rb:71:in `wrap'
  from activejob (6.1.4.1) lib/active_job/railtie.rb:46:in `block (3 levels) in <class:Railtie>'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `instance_exec'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:126:in `block in run_callbacks'
  from activesupport (6.1.4.1) lib/active_support/callbacks.rb:137:in `run_callbacks'
  from activejob (6.1.4.1) lib/active_job/execution.rb:23:in `execute'
  from activejob (6.1.4.1) lib/active_job/queue_adapters/sidekiq_adapter.rb:42:in `perform'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:196:in `execute_job'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:164:in `block (2 levels) in process'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:138:in `block in invoke'
  from sidekiq_prometheus (1.6.0) lib/sidekiq_prometheus/job_metrics.rb:18:in `block in call'
  from benchmark.rb:308:in `realtime'
  from sidekiq_prometheus (1.6.0) lib/sidekiq_prometheus/job_metrics.rb:18:in `call'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
  from prometheus_exporter (0.8.1) lib/prometheus_exporter/instrumentation/sidekiq.rb:36:in `call'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
  from opentelemetry-instrumentation-sidekiq (0.20.1) lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:46:in `block (2 levels) in call'
  from opentelemetry-api (1.0.0) lib/opentelemetry/trace.rb:82:in `block in with_span'
  from opentelemetry-api (1.0.0) lib/opentelemetry/context.rb:87:in `with_value'
  from opentelemetry-api (1.0.0) lib/opentelemetry/trace.rb:82:in `with_span'
  from opentelemetry-instrumentation-sidekiq (0.20.1) lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:43:in `block in call'
  from opentelemetry-api (1.0.0) lib/opentelemetry/context.rb:71:in `with_current'
  from opentelemetry-instrumentation-sidekiq (0.20.1) lib/opentelemetry/instrumentation/sidekiq/middlewares/server/tracer_middleware.rb:31:in `call'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
  from sentry-raven (3.1.2) lib/raven/integrations/sidekiq/cleanup_middleware.rb:7:in `call'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:140:in `block in invoke'
  from sidekiq (6.2.2) lib/sidekiq/middleware/chain.rb:143:in `invoke'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:163:in `block in process'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:136:in `block (6 levels) in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/job_retry.rb:112:in `local'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:135:in `block (5 levels) in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/rails.rb:14:in `block in call'
  from activesupport (6.1.4.1) lib/active_support/execution_wrapper.rb:88:in `wrap'
  from activesupport (6.1.4.1) lib/active_support/reloader.rb:72:in `block in wrap'
  from activesupport (6.1.4.1) lib/active_support/execution_wrapper.rb:88:in `wrap'
  from activesupport (6.1.4.1) lib/active_support/reloader.rb:71:in `wrap'
  from sidekiq (6.2.2) lib/sidekiq/rails.rb:13:in `call'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:131:in `block (4 levels) in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:257:in `stats'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:126:in `block (3 levels) in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/job_logger.rb:13:in `call'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:125:in `block (2 levels) in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/job_retry.rb:79:in `global'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:124:in `block in dispatch'
  from sidekiq (6.2.2) lib/sidekiq/logger.rb:11:in `with'
  from sidekiq (6.2.2) lib/sidekiq/job_logger.rb:33:in `prepare'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:123:in `dispatch'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:162:in `process'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:78:in `process_one'
  from opentelemetry-instrumentation-sidekiq (0.20.1) lib/opentelemetry/instrumentation/sidekiq/patches/processor.rb:21:in `block in process_one'
  from opentelemetry-common (0.19.2) lib/opentelemetry/common/utilities.rb:76:in `block in untraced'
  from opentelemetry-api (1.0.0) lib/opentelemetry/trace.rb:82:in `block in with_span'
  from opentelemetry-api (1.0.0) lib/opentelemetry/context.rb:87:in `with_value'
  from opentelemetry-api (1.0.0) lib/opentelemetry/trace.rb:82:in `with_span'
  from opentelemetry-common (0.19.2) lib/opentelemetry/common/utilities.rb:76:in `untraced'
  from opentelemetry-instrumentation-sidekiq (0.20.1) lib/opentelemetry/instrumentation/sidekiq/patches/processor.rb:21:in `process_one'
  from sidekiq (6.2.2) lib/sidekiq/processor.rb:68:in `run'
  from sidekiq (6.2.2) lib/sidekiq/util.rb:43:in `watchdog'
  from sidekiq (6.2.2) lib/sidekiq/util.rb:52:in `block in safe_thread'

and it seems to be an problem together with logstash

Piioo avatar Oct 18 '21 15:10 Piioo

It's unclear how this latest report relates to the Redis instrumentation. The Sidekiq instrumentation appears lower in the stack, and doesn't appear at all in the recursive portion.

fbogsany avatar Oct 22 '21 13:10 fbogsany

downgrade has not really helped....I have remove open telemetry and then all works fine.

Piioo avatar Oct 22 '21 13:10 Piioo

It would be interesting to narrow this down to specific instrumentation. Can you please try removing just the opentelemetry-instrumentation-sidekiq gem? Also, do you have the opentelemetry-instrumentation-action_view gem installed? logstasher is instrumenting ActionView::LogSubscriber, which should have nothing to do with Sidekiq, but we'd like to know if the ActionView instrumentation has problems.

fbogsany avatar Oct 22 '21 15:10 fbogsany