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

Sentry appender raises "ThreadError: deadlock; recursive locking" when threading features are disabled #281

Closed
eagletmt opened this issue Jun 17, 2024 · 1 comment

Comments

@eagletmt
Copy link
Contributor

Environment

  • Ruby Version.
    • 3.3.3
  • Semantic Logger Version.
    • 4.15.0
  • Application/framework names and versions (e.g. Rails, Sinatra, Puma, etc.).
    • None
  • Rails Semantic Logger Version, if applicable.
    • None
  • Rails configuration. Only need the settings related to Rails Semantic Logger and Semantic Logger.
    • None
  • Full Stack Trace, if an exception is being raised.
    • Attached below

Expected Behavior

require 'bundler/inline'

gemfile do
  source 'https://rubygems.org'

  gem 'semantic_logger', '4.15.0'
  gem 'sentry-ruby', '5.17.3'
end

# Condition 1: Enable sync mode
SemanticLogger.sync!
# Condition 2: Enable sentry_ruby appender
SemanticLogger.add_appender(appender: :sentry_ruby)

Sentry.init do |config|
  # Condition 3: Use semantic_logger as Sentry's logger
  config.logger = SemanticLogger[Sentry]
  # Condition 4: Disable non-blocking mode
  config.background_worker_threads = 0
  config.dsn = 'http://foo@localhost/bar'  # Fake value, needed to reproduce the error
end

logger = SemanticLogger['MyClass']
begin
  raise 'something went wrong'
rescue => e
  # Expected: `e` is sent to Sentry
  # Actual: `e` is not sent to Sentry; SemanticLogger::Appenders -- Failed to log to appender: SemanticLogger::Appender::SentryRuby -- Exception: ThreadError: deadlock; recursive locking
  logger.error('oops', e)
end

As I commented, the Sentry appender fails to send error logs to Sentry when these conditions are met:

  1. semantic_logger is used with sync mode
  2. Sentry appender is enabled
  3. semantic_logger is used as Sentry's logger
  4. Sentry is used in blocking mode: https://docs.sentry.io/platforms/ruby/configuration/options/

Actual Behavior

Sentry appender fails to send error logs to Sentry.

% ruby sentry-deadlock.rb
2024-06-17 16:19:52.897985 E [69200:920 sentry-deadlock.rb:29] SemanticLogger::Appenders -- Failed to log to appender: SemanticLogger::Appender::SentryRuby -- Exception: ThreadError: deadlock; recursive locking
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `error'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/utils/logging_helper.rb:9:in `log_error'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:77:in `rescue in capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:48:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:199:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:138:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:412:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:72:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:59:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:383:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:62:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:31:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `each'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `error'
sentry-deadlock.rb:29:in `rescue in <main>'
sentry-deadlock.rb:24:in `<main>'
Cause: ThreadError: deadlock; recursive locking
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `error'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/utils/logging_helper.rb:9:in `log_error'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:197:in `rescue in send_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:168:in `send_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:72:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:199:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:138:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:412:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:72:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:59:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:383:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:62:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:31:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `each'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `error'
sentry-deadlock.rb:29:in `rescue in <main>'
sentry-deadlock.rb:24:in `<main>'
Cause: ThreadError: deadlock; recursive locking
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `info'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/utils/logging_helper.rb:15:in `log_info'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/transport.rb:64:in `send_envelope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/transport.rb:51:in `send_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:192:in `send_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/client.rb:72:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:199:in `capture_event'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:138:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:412:in `capture_exception'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:72:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry/hub.rb:59:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/sentry-ruby-5.17.3/lib/sentry-ruby.rb:383:in `with_scope'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appender/sentry_ruby.rb:62:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:31:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `each'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/appenders.rb:30:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `block in log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `synchronize'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/sync_processor.rb:12:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/logger.rb:74:in `log'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:353:in `log_internal'
/usr/share/rbenv/versions/3.3.3/lib/ruby/gems/3.3.0/gems/semantic_logger-4.15.0/lib/semantic_logger/base.rb:84:in `error'
sentry-deadlock.rb:29:in `rescue in <main>'
sentry-deadlock.rb:24:in `<main>'
Cause: RuntimeError: something went wrong
sentry-deadlock.rb:25:in `<main>'

Pull Request

I'm thinking of changing @mutex from Mutex to Monitor, which allows recursive locking.
https://ruby-doc.org/3.3.3/exts/monitor/Monitor.html

@reidmorrison
Copy link
Owner

Thank you for the pull request, merged.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants