Log message passed in progname, not in message parameter

[ngoral]

Description of the bug
When I am trying to run my app with a custom logger, the application fails to start with the following error:

myapp/lib/syslog/logger.rb:205:in `add': undefined method `call' for nil:NilClass (NoMethodError)

      @@syslog.log( (LEVEL_MAP[severity] | @facility), '%s', formatter.call(severity, Time.now, progname, (message || block.call)) )
                                                                                                                           ^^^^^
  from myapp/config/initializers/opentelemetry.rb:94:in `add'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-sdk-1.4.0/lib/opentelemetry/sdk/forwarding_logger.rb:49:in `info'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:79:in `install_instrumentation'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:51:in `block (2 levels) in install'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:46:in `each'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:46:in `block in install'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:45:in `synchronize'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-registry-0.3.0/lib/opentelemetry/instrumentation/registry.rb:45:in `install'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-sdk-1.4.0/lib/opentelemetry/sdk/configurator.rb:164:in `install_instrumentation'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-sdk-1.4.0/lib/opentelemetry/sdk/configurator.rb:145:in `configure'
  from myapp/shared/bundle/ruby/3.2.0/gems/opentelemetry-sdk-1.4.0/lib/opentelemetry/sdk.rb:66:in `configure'

I dug a little into it and can see that ForwardingLogger passes what should be a message into a progname parameter.
In registry/lib/opentelemetry/instrumentation/registry.rb:81 we call OpenTelemetry.logger.info 'Our message here'
Then in sdk/lib/opentelemetry/sdk/forwarding_logger.rb:48 we receive it as
def info(progname = nil, &block) thus we get our message in a progname.
Then it is passed to def add(severity, message = nil, progname = nil) in which signature me have message attribute, but when passing it, we set it to nil: add(Logger::INFO, nil, progname, &block).
And then we omit the block and pass our nil message and a message in a progname to the originally selected @logger:
@logger.add(severity, message, progname).

ActiveSupport::Logger does just fine, but my logger cannot bear both empty message and block, and I myself find it kind of weird: passing message in a progname.

Is it done supposedly for some reason or is it an error?

Share details about your runtime

Operating system details: Linux, Ubuntu 16.04 LTS
RUBY_ENGINE: "ruby"
RUBY_VERSION: "3.2.0"

[xuan-cao-swi]

Could you provide how you do the otel initialization that set the custom logger (e.g. OpenTelemetry::SDK.configure )?

Have you tried following config to set the custom logger?

OpenTelemetry::SDK.configure do |c|
  c.logger = ::Logger.new($stdout, level: <the_level_you_want>) # or any custom logger with ::Logger.new
  c.use_all()
end

[ngoral]

Opentelemetry::SDK.configure do |conf|
  conf.logger = Rails.logger
end

But I beleive that doesn't really matter since I can see that we always pass a nil as a message to a logger, and the message itself is passed in progname attribute.

So, yes, ActiveSupport::Logger manages it, and, I guess, some others do it too, and I can definitely patch my logger to be capable to manage it, but the logic in code itself seems a little odd to me.

[BrianHawley]

Looking at the Ruby logger source, it also passes a nil message from the info method to the add method, with source pretty much identical to the source in ForwardingLogger. However, the Ruby logger's add method treats a nil message as an excuse to call the block to construct the message, or reuses the progname parameter as a message if no block is passed.

So the bug is the ForwardingLogger add method not passing through the block to the logger it's forwarding to. Without that, the normal block fallback behavior doesn't work.

[xuan-cao-swi]

@BrianHawley thanks for the finding. I did little test and I believe you are correct on "ForwardingLogger add method not passing through the block to the logger it's forwarding to".

Would you mind to contribute a PR to amend this?

::Logger.add expect block

[BrianHawley]

@ngoral I fixed ForwardingLogger's add method to forward the block parameter. You should fix your custom logger's add method to use the same parameter handling tricks as Ruby's Logger class:

if progname.nil?
  progname = @progname
end
if message.nil?
  if block_given?
    message = yield
  else
    message = progname
    progname = @progname
  end
end

You might prefer to just derive your custom logger from Ruby's Logger class, then change where you're logging to or the formatter. Up to you.

[szechyjs]

This seems to also be busted when using Ougai as the logger.

Current workaround is OpenTelemetry.logger = Rails.logger