[Bug] ScopedLogger fails attempting to compare symbol to integer for libraries like semantic_logger

[schoblaska]

What are you really trying to do?

I'm running Temporal alongside a Rails application, starting the Temporal worker with a Rails runner script like in the example.

Describe the bug

Workflows are failing on exceptions bubbling up from ScopedLogger on this line:

sdk-ruby/temporalio/lib/temporalio/scoped_logger.rb

Line 20 in 21a3f31

return true if (severity || Logger::Unknown) < level

When I inspect those values, severity is 2, Logger::Unknown is undefined (should be Logger::UNKNOWN?), and level is :debug.

comparison of Integer with :debug failed

/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/scoped_logger.rb:20:in 'Integer#<'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/scoped_logger.rb:20:in 'Temporalio::ScopedLogger#add'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/replay_safe_logger.rb:31:in 'block in Temporalio::Internal::Worker::WorkflowInstance::ReplaySafeLogger#add'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/illegal_call_tracer.rb:134:in 'block in Temporalio::Internal::Worker::WorkflowInstance::IllegalCallTracer#disable'
<internal:trace_point>:297:in 'TracePoint#disable'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/illegal_call_tracer.rb:133:in 'Temporalio::Internal::Worker::WorkflowInstance::IllegalCallTracer#disable'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:197:in 'Temporalio::Internal::Worker::WorkflowInstance#illegal_call_tracing_disabled'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/replay_safe_logger.rb:31:in 'Temporalio::Internal::Worker::WorkflowInstance::ReplaySafeLogger#add'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/scoped_logger.rb:57:in 'Temporalio::ScopedLogger#warn'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:289:in 'block in Temporalio::Internal::Worker::WorkflowInstance#activate_internal'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/replay_safe_logger.rb:20:in 'Temporalio::Internal::Worker::WorkflowInstance::ReplaySafeLogger#replay_safety_disabled'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:288:in 'Temporalio::Internal::Worker::WorkflowInstance#activate_internal'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:166:in 'block in Temporalio::Internal::Worker::WorkflowInstance#activate'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/illegal_call_tracer.rb:125:in 'block in Temporalio::Internal::Worker::WorkflowInstance::IllegalCallTracer#enable'
<internal:trace_point>:261:in 'TracePoint#enable'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance/illegal_call_tracer.rb:124:in 'Temporalio::Internal::Worker::WorkflowInstance::IllegalCallTracer#enable'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:236:in 'Temporalio::Internal::Worker::WorkflowInstance#run_in_scheduler'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/internal/worker/workflow_instance.rb:166:in 'Temporalio::Internal::Worker::WorkflowInstance#activate'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/workflow_executor/thread_pool.rb:163:in 'block in Temporalio::Worker::WorkflowExecutor::ThreadPool::Worker#activate'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/timeout-0.4.3/lib/timeout.rb:185:in 'block in Timeout.timeout'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/timeout-0.4.3/lib/timeout.rb:192:in 'Timeout.timeout'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/workflow_executor/thread_pool.rb:149:in 'Temporalio::Worker::WorkflowExecutor::ThreadPool::Worker#activate'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/workflow_executor/thread_pool.rb:124:in 'block in Temporalio::Worker::WorkflowExecutor::ThreadPool::Worker#run'
<internal:kernel>:168:in 'Kernel#loop'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/workflow_executor/thread_pool.rb:115:in 'Temporalio::Worker::WorkflowExecutor::ThreadPool::Worker#run'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/workflow_executor/thread_pool.rb:99:in 'block in Temporalio::Worker::WorkflowExecutor::ThreadPool::Worker#initialize'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/thread_pool.rb:200:in 'block (3 levels) in Temporalio::Worker::ThreadPool::Worker#initialize'
<internal:kernel>:168:in 'Kernel#loop'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/thread_pool.rb:193:in 'block (2 levels) in Temporalio::Worker::ThreadPool::Worker#initialize'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/thread_pool.rb:192:in 'Kernel#catch'
/Users/joseph/.rvm/gems/ruby-3.4.2/gems/temporalio-0.5.0-arm64-darwin/lib/temporalio/worker/thread_pool.rb:192:in 'block in Temporalio::Worker::ThreadPool::Worker#initialize'

Environment/Versions

• OS and processor: M1 Mac
• Using the temporalio/auto-setup:latest Docker image

[cretz]

Interesting. Per https://github.com/ruby/rbs/blob/607dc0573276048ba41f07fe160df102898fe717/stdlib/logger/0/logger.rbs#L609, level is supposed to be an integer not a symbol. Even Ruby itself does integer comparison operators against level e.g. https://github.com/ruby/logger/blob/9239e197f39df4cb11652808bdfd1624f824a3a3/lib/logger.rb#L482.

So I wonder if Rails.logger.level is a symbol. Rails.logger is an ActiveSupport::Logger which extends ::Logger which means it should only have level returning an integer. So does Rails.logger.level > 2 fail? Does Rails.logger.debug? fail? We will have to investigate (and/or feel free to do some deep diving here yourself).

[schoblaska]

I did a little digging and realized that I'm using rails_semantic_logger in this project, which uses symbols for log levels, which can result in compatibility issues.

3.4.2 :001 > Rails.logger
 => #<SemanticLogger::Logger:0x000000011611bf90 @filter=nil, @level=nil, @level_index=nil, @name="Rails">

3.4.2 :002 > Rails.logger.level
 => :debug

On a Rails project using the default logger:

3.3.5 :001 > Rails.logger
 =>
#<ActiveSupport::BroadcastLogger:0x00000001683e64f8
 @broadcasts=
  [#<ActiveSupport::Logger:0x000000016ea37b30
    @default_formatter=#<Logger::Formatter:0x00000001683ee108 @datetime_format=nil>,
    @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x00000001683e6d18 @datetime_format=nil>,
    @level=0,
    @level_override={},
    @local_level_key=:logger_thread_safe_level_41180,
    @logdev=
     #<Logger::LogDevice:0x000000016f6db9b8
      @binmode=false,
      @dev=#<File:/Users/joseph/projects/web_app/log/development.log>,
      @filename="/Users/joseph/projects/web_app/log/development.log",
      @mon_data=#<Monitor:0x00000001683ee040>,
      @mon_data_owner_object_id=21640,
      @reraise_write_errors=[],
      @shift_age=1,
      @shift_period_suffix="%Y%m%d",
      @shift_size=104857600,
      @skip_header=false>,
    @progname=nil>,
   #<ActiveSupport::Logger:0x000000010f470d78
    @default_formatter=#<Logger::Formatter:0x000000016e8571d0 @datetime_format=nil>,
    @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x000000016e856c58 @datetime_format=nil>,
    @level=0,
    @level_override={},
    @logdev=#<Logger::LogDevice:0x000000031063b740 @binmode=false, @dev=#<IO:<STDERR>>, @filename=nil, @mon_data=#<Monitor:0x000000016e856d70>, @mon_data_owner_object_id=41160, @reraise_write_errors=[], @shift_age=nil, @shift_period_suffix=nil, @shift_size=nil, @skip_header=false>,
    @progname=nil>],
 @formatter=#<ActiveSupport::Logger::SimpleFormatter:0x00000001683e6d18 @datetime_format=nil>,
 @progname="Broadcast">

3.3.5 :002 > Rails.logger.level
 => 0

Personally, I don't need the semantic logger anymore (I believe I initially switched to it because of a telemetry library I was using) so I'll probably just switch back to the default.

[cretz]

👍 FWIW, I personally disagree with the first sentence of rails/rails#49563 that states

Numeric values for Logger#level is an implementation detail

And reidmorrison/semantic_logger#28 and others here. The integer is set in RBS, in Sorbet, and is clearly referred to as an integer in the base Logger class multiple times, which any extension/wrapper/delegator relies on.

However, I'll update the title of this issue and if other users complain about semantic_logger issues here, we can try to adjust our wrapper to be semantic_logger friendly.

[schoblaska]

Sounds good! Thanks for looking into this. I opened a PR for the Logger::Unknown issue: #316