reidmorrison / semantic_logger

Semantic Logger is a feature rich logging framework, and replacement for existing Ruby & Rails loggers.
https://logger.rocketjob.io/
Apache License 2.0
873 stars 124 forks source link

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

Closed eagletmt closed 5 months ago

eagletmt commented 5 months ago

Environment

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 commented 5 months ago

Thank you for the pull request, merged.