Logger Instrumentation Deadlock Due to Recursive Logging #1943
Description
Description of the bug
The OpenTelemetry Logger instrumentation (opentelemetry-instrumentation-logger v0.3.0) causes a deadlock when the OpenTelemetry SDK logs internally during log emission. This occurs when the BatchLogRecordProcessor reports dropped records, triggering recursive mutex locking.
When the batch log record queue becomes full, the BatchLogRecordProcessor logs a warning about dropped records. This internal SDK logging is intercepted by the logger instrumentation, which attempts to emit the log to OpenTelemetry again. This creates a recursive call while holding a mutex lock, resulting in a deadlock.
The logger instrumentation's format_message method doesn't prevent re-entry when OpenTelemetry's SDK itself generates log messages. The call sequence is:
Application logs → Logger#format_message (instrumentation)
→ BatchLogRecordProcessor#on_emit (acquires mutex lock)
→ Queue full → report_dropped_log_records
→ OpenTelemetry.logger.warn (internal SDK logging)
→ Logger#format_message (instrumentation again)
→ BatchLogRecordProcessor#on_emit (tries to acquire same mutex)
→ DEADLOCK (recursive locking on same thread)
Share details about your runtime
- Operating System: macOS (darwin24)
- Architecture: arm64 (Apple Silicon)
- Ruby Version: 3.2.3 (2024-01-18 revision 52bb2ac0a6) [arm64-darwin24]
- Rails version: 7.2.3
- Puma: 7.1.0
- opentelemetry-instrumentation-logger: 0.3.0
- opentelemetry-logs-sdk: 0.4.0
- opentelemetry-sdk: 1.10.0
Share a simplified reproduction if possible
# config.ru
require 'bundler/inline'
gemfile(true) do
source 'https://rubygems.org'
gem 'rails', '~> 7.2.0'
gem 'puma'
gem 'opentelemetry-sdk', '1.10.0'
gem 'opentelemetry-logs-sdk', '0.4.0'
gem 'opentelemetry-exporter-otlp', '0.31.0'
gem 'opentelemetry-exporter-otlp-logs', '0.2.2'
gem 'opentelemetry-instrumentation-logger', '0.3.0'
end
require 'action_controller/railtie'
class DummyRails < Rails::Application
config.root = __dir__
config.consider_all_requests_local = true
config.secret_key_base = 'dummy_secret_key_base'
config.load_defaults 7.2
config.eager_load = false
config.logger = Logger.new($stdout)
routes.append do
get '/test' => 'test#index'
end
end
class TestController < ActionController::Base
def index
# Generate multiple log messages quickly to fill the queue
Rails.logger.info '=== Starting deadlock test ==='
Rails.logger.info 'Log message 1'
Rails.logger.info 'Log message 2'
Rails.logger.info 'Log message 3'
Rails.logger.warn 'Log message 4'
Rails.logger.warn 'Log message 5'
Rails.logger.error 'Log message 6'
Rails.logger.info 'Log message 7'
Rails.logger.info '=== Test completed successfully ==='
render plain: "✓ Test completed! If you're reading this, the deadlock was NOT triggered."
end
end
OpenTelemetry::SDK.configure do |c|
c.add_log_record_processor(
OpenTelemetry::SDK::Logs::Export::BatchLogRecordProcessor.new(
OpenTelemetry::Exporter::OTLP::Logs::LogsExporter.new(
endpoint: 'http://localhost:4318/v1/logs',
timeout: 1
),
max_queue_size: 8,
max_export_batch_size: 2,
schedule_delay: 10_000
)
)
c.use_all
end
DummyRails.initialize!
puts ''
puts 'Visit http://localhost:3000/test to trigger the deadlock'
puts ''
run DummyRailsRun rackup -p 3000, go to http://localhost:3000/test, and observe a deadlock error
Tip: React with 👍 to help prioritize this issue. Please use comments to provide useful context, avoiding +1 or me too, to help us triage it. Learn more in our end user docs.