ThreadError: deadlock; recursive locking in Airbrake::PerformanceNotifier

[matiasmelendi]

I enabled performance monitoring in my production rails app and I'm getting a bunch of ThreadError.

I'm using airbrake ~> 9.3.0 which depends on airbrake-ruby -> 4.5.0.
Rails version is (~> 5.1.0) running on ruby 2.5.5...
Below is part of the stacktrace of the error:

/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/performance_notifier.rb:36 in synchronize
/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby/performance_notifier.rb:36 in notify
/gems/airbrake-ruby-4.5.0/lib/airbrake-ruby.rb:358 in notify_request
/gems/airbrake-9.3.0/lib/airbrake/rails/action_controller_notify_subscriber.rb:17 in block in call
/gems/airbrake-9.3.0/lib/airbrake/rails/action_controller_notify_subscriber.rb:16 in each
/gems/airbrake-9.3.0/lib/airbrake/rails/action_controller_notify_subscriber.rb:16 in call
/gems/activesupport-5.1.6.2/lib/active_support/notifications/fanout.rb:127 in finish

Any clue on what could be causing the issue? None of the changes on newer versions seem to be related to thread management so I don't think that upgrading would solve it.

Thanks in advance!

[kyrylo]

What kind of routes trigger that? Just a standard controller action?
Is the code that you run async or sync?

Right now I'm short of ideas but it's probably an issue with multithreading support in our code, since it's a deadlock.

[kyrylo]

Gentle ping @matiasmelendi.

[karoskibinska]

Hi, we've encountered similar issue on production environment - after update to airbrake 10.0.1 with airbrake-ruby 4.13.0 we started getting bunch of ThreadErrors. Temporary solution was to downgrade and lock dependencies on 10.0.0 and 4.12.0 respectively.

# config: 
# Airbrake 10.0.1  
# Airbrake-ruby 4.13.0
# Ruby 2.6.5
# Rails 6.0.2.1 

Error backtrace:

# /GEM_ROOT/gems/airbrake-ruby-4.13.0/lib/airbrake-ruby/performance_notifier.rb:131→ synchronize
# /GEM_ROOT/gems/airbrake-ruby-4.13.0/lib/airbrake-ruby/performance_notifier.rb:131→ send_resource
# /GEM_ROOT/gems/airbrake-ruby-4.13.0/lib/airbrake-ruby/performance_notifier.rb:28→ notify
# /GEM_ROOT/gems/airbrake-ruby-4.13.0/lib/airbrake-ruby.rb:419→ notify_query
# /GEM_ROOT/gems/airbrake-10.0.1/lib/airbrake/rails/active_record_subscriber.rb:20→ block in call
# /GEM_ROOT/gems/airbrake-10.0.1/lib/airbrake/rails/active_record_subscriber.rb:19→ each
# /GEM_ROOT/gems/airbrake-10.0.1/lib/airbrake/rails/active_record_subscriber.rb:19→ call
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/fanout.rb:189→ finish
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/fanout.rb:62→ block in finish
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/fanout.rb:62→ each
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/fanout.rb:62→ finish
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/instrumenter.rb:45→ finish_with_state
# /GEM_ROOT/gems/activesupport-6.0.2.1/lib/active_support/notifications/instrumenter.rb:30→ instrument
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract_adapter.rb:708→ log
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:684→ exec_cache
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/postgresql_adapter.rb:655→ execute_and_clear
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/postgresql/database_statements.rb:98→ exec_query
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:491→ select_prepared
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:68→ select_all
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:105→ block in select_all
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:123→ block in cache_sql
# /usr/local/lib/ruby/2.6.0/monitor.rb:235→ mon_synchronize
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:114→ cache_sql
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/connection_adapters/abstract/query_cache.rb:105→ select_all
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/querying.rb:46→ find_by_sql
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:810→ block in exec_queries
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:828→ skip_query_cache_if_necessary
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:797→ exec_queries
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:615→ load
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation.rb:250→ records
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation/finder_methods.rb:500→ find_take
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation/finder_methods.rb:98→ take
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/relation/finder_methods.rb:81→ find_by
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/querying.rb:21→ find_by
# /GEM_ROOT/gems/activerecord-6.0.2.1/lib/active_record/core.rb:188→ find_by

It runs as regular api controller create action.

[kyrylo]

Thanks for the report @karoskibinska-ah. I am not sure why downgrading to v10.0.0 helps. My hunch is that it's a coincidence. We haven't made any drastic changes in PerformanceNotifier between v10.0.0 and v10.0.1.

Your bug report is related to the same class but the method that fails is different. The reason why this error occurs is because we enter into the same lock a 2nd time. Why? I currently struggle to answer but it could be because the code that we wrap in synchronize calls itself again.

While debugging this I found one more issue, which may be related to this one. Because I have a clear reproducible case, I will work on that issue first.

In the meantime, there's a side clue, which I am not sure is related but it's very easy to try. Since you report that v10.0.0 doesn't have problems but v10.0.1 does, one thing you could try is to upgrade to v10.0.1 but lock your rbtree3 dependency to v0.5.0. This is our dependency that we bumped in v10.0.1. There's another bug report which is related to threading, so it may be connected to this issue as well. I would appreciate if you could test this.

[karoskibinska]

@kyrylo Hi, unfortunately locking rbtree3 to v0.5.0 did not work, as soon as the change was deployed to integration, we got another deadlock; recursive locking errors

[kyrylo]

Thanks for checking, that is helpful. I have fixed the issue that I mentioned before (in airbrake-ruby): it appears to be irrelevant to this bug report. I am still looking into this issue - no obvious solution so far.

[kyrylo]

Fixed by #554.