Skip to content

Threading exception with Resque/Redis in exit #2054

Closed

Description

@jason-o-matic

Issue Description

In our tests we have a background thread that processes Resque jobs. We don't always care if the jobs finish during a given test. Occasionally we're getting this stack trace at the end of a test run:


Traceback (most recent call last):
	1: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/minitest-5.17.0/lib/minitest.rb:80:in `block (2 levels) in autorun'
~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/minitest-5.17.0/lib/minitest.rb:80:in `exit': exit (SystemExit)
	27: from ~/path/to/project/test/test_worker.rb:38:in `block in start_thread'
	26: from ~/path/to/project/test/test_worker.rb:43:in `run_process_loop'
	25: from ~/path/to/project/test/test_worker.rb:43:in `loop'
	24: from ~/path/to/project/test/test_worker.rb:45:in `block in run_process_loop'
	23: from ~/path/to/project/test/test_worker.rb:52:in `run_all_jobs'
	22: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-1.27.4/lib/resque.rb:317:in `queues'
	21: from ~/.rbenv/versions/2.7.8/lib/ruby/2.7.0/forwardable.rb:235:in `queue_names'
	20: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/resque-1.27.4/lib/resque/data_store.rb:144:in `queue_names'
	19: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.5.3/lib/redis/namespace.rb:321:in `method_missing'
	18: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-namespace-1.5.3/lib/redis/namespace.rb:435:in `call_with_namespace'
	17: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis.rb:1397:in `smembers'
	16: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis.rb:58:in `synchronize'
	15: from ~/.rbenv/versions/2.7.8/lib/ruby/2.7.0/monitor.rb:202:in `mon_synchronize'
	14: from ~/.rbenv/versions/2.7.8/lib/ruby/2.7.0/monitor.rb:202:in `synchronize'
	13: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis.rb:58:in `block in synchronize'
	12: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis.rb:1398:in `block in smembers'
	11: from ~/path/to/project/lib/project_instrumentation/redis.rb:6:in `call'
	10: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/bundler/gems/metrician-ruby-8841bad30386/lib/metrician/reporters/redis.rb:22:in `call'
	 9: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis/client.rb:120:in `call'
	 8: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/redis-3.3.3/lib/redis/client.rb:220:in `process'
	 7: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:76:in `logging'
	 6: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:16:in `instrument'
	 5: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry-ruby.rb:456:in `with_child_span'
	 4: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/hub.rb:102:in `with_child_span'
	 3: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:17:in `block in instrument'
	 2: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:17:in `tap'
	 1: from ~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:18:in `block (2 levels) in instrument'
~/.rbenv/versions/2.7.8/lib/ruby/gems/2.7.0/gems/sentry-ruby-5.9.0/lib/sentry/redis.rb:33:in `record_breadcrumb': undefined method `breadcrumbs_logger' for nil:NilClass (NoMethodError)

The tests pass, it seems like the issue is when the process is exiting. It's not clear to me why https://github.com/getsentry/sentry-ruby/blob/5.9.0/sentry-ruby/lib/sentry/redis.rb#LL33C28-L33C41 would have Sentry.configuration return nil, which seems like it shouldn't happen.

Reproduction Steps

  1. Write a test that processes Resque jobs in a background thread
  2. Run the test a bunch

Expected Behavior

No exception is produced.

Actual Behavior

The above exception is printed.

Ruby Version

2.7.8

SDK Version

5.9.0

Integration and Its Version

Redis/Resque/Rails

Sentry Config

logger = ::Logger.new(STDOUT)
logger.level = ::Logger::WARN
logger.formatter = Logger::Formatter.new

class CustomHTTPTransport < Sentry::HTTPTransport
  def handle_transport_failure(*args, **kwargs)
    puts ["transport_failure_callback", Time.now.to_f, args, kwargs].inspect
    I.increment("sentry.transport_failure_callback")
  end

  private

  def send_data(*args, **kwargs, &block)
    super
  rescue => e
    handle_transport_failure(e)
  end
end

SENTRY_FILTER = if Rails.application
  ActiveSupport::ParameterFilter.new(Rails.application.config.filter_parameters)
end

Sentry.init do |config|
  config.dsn = "[REDACTED]"
  config.send_default_pii = false
  config.enabled_environments = ["staging", "production"]
  config.logger = logger
  config.breadcrumbs_logger = [logger]
  config.before_send = lambda do |event, *args|
    I.increment("sentry.before_send")
    SENTRY_FILTER ? SENTRY_FILTER.filter(event.to_hash) : event
  end
  config.transport.transport_class = CustomHTTPTransport
end

Activity

  1. moved this to Waiting for: Product Owner in GitHub Issues with 👀on Jun 7, 2023
  2. sl0thentr0py commented on Jun 19, 2023

    @sl0thentr0py
    Member

    hmm interesting, seems there's a Sentry.close being called on the main thread between

    return yield unless Sentry.initialized?

    and

    which runs after the redis db call is done.

    I can add a protective guard to record_breadcrumb as well.

  3. jason-o-matic commented on Jun 28, 2023

    @jason-o-matic
    ContributorAuthor

    Thanks for the quick fix! Any idea when this change will be be included in a release?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

Projects

Milestone

No milestone

Relationships

None yet

Development

No branches or pull requests

Issue actions