Support message and payload (v5 feature request)

[bethesque]

Expected behaviour

When calling logger.info("this message is not printed", payload: { foo: "bar" }) the message is printed.

Actual behaviour

When calling logger.info("this message is not printed", payload: { foo: "bar" }) the message is not printed.

Steps to reproduce

With 4.10.0

require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "semantic_logger", "4.10.0"
end

require "semantic_logger"

SemanticLogger.add_appender(io: $stdout, formatter: :json)

logger = SemanticLogger['logger']
logger.info("this message is printed", { foo: "bar" })
logger.info("this message is printed too", payload: { foo: "bar" })

With 4.11.0

require "bundler/inline"

gemfile do
  source "https://rubygems.org"
  gem "semantic_logger", "4.11.0"
end

require "semantic_logger"

SemanticLogger.add_appender(io: $stdout, formatter: :json)

logger = SemanticLogger['logger']
logger.info("this message is printed", { foo: "bar" })
logger.info("this message is not printed", payload: { foo: "bar" })

I have read #194 and I am a bit confused. I was sure at one stage, there was an upgrade to semantic logger that documented, as Reid Morrison states, that the correct format to use was logger.debug "Message received", payload: { message: "message" } because I remember having to go through every log line in my application and add the payload key. I now see that the recommended formats are logger.debug("Calling Supplier", request: "update", user: "Jack") and logger.debug(message: "Calling Supplier", payload: {request: "update", user: "Jack"}) (with no payload key). Am I (and Reid) misremembering? I may have missed some later upgrade documentation that reverted the recommended syntax back to the logger.debug("Calling Supplier", request: "update", user: "Jack") format.

I understand that trying to support every format and not break anyone is a bit of a nightmare and you have my full sympathy! Thank you to everyone involved in this project.

[todd-a-jacobs]

I won't swear to this, but I think this may have something to do with the way keyword arguments are handled in Ruby 3.0+. Unless you use ruby2keywords, Ruby no longer treats a trailing Hash as an opts hash, but rather as a block. There was recently some discussion about dropping support for EOL rubies in a future release as SemanticLogger supports Ruby back to 2.5 at this time.

If you can test on an older Ruby (e.g. <= 2.7.6) and let me know if the problem persists, I'll take a closer look.

[bethesque]

The issue I described occurs on Ruby 2.7.6.

[todd-a-jacobs]

Unable to Replicate with Up-to-Date Gems on Ruby 2.7.6 or 3.1.2

This must be something environment-specific for you. I just tried your code using semantic_logger 4.11.0 on both Ruby 2.7.6 (after running gem update, because the versions of irb and other default gems that come with Ruby 2.7.6 are outdated) and Ruby 3.1.2. With a fresh install of Ruby 2.7.6 followed by gem update, irb provides the expected behavior on both Ruby versions with SemanticLogger v4.11.0:

require "semantic_logger"

SemanticLogger.add_appender(io: $stdout, formatter: :json)
logger = SemanticLogger['logger']

logger.info("this message is printed", { foo: "bar" })
#=> true
{"host":"localhost.local","application":"Semantic Logger","timestamp":"2022-07-28T01:53:53.799341Z","level":"info","level_index":2,"pid":20991,"thread":"200","name":"logger","message":"this message is printed","payload":{"foo":"bar"}}

logger.info("this message is not printed", payload: { foo: "bar" })
#=> true
{"host":"localhost.local","application":"Semantic Logger","timestamp":"2022-07-28T01:54:04.077857Z","level":"info","level_index":2,"pid":20991,"thread":"200","name":"logger","payload":{"foo":"bar"}}

Fixing Outdated Gems, Especially IRB

Notably, Ruby 2.7.6 comes with irb v1.2.6 as a default gem, while the latest version is 1.4.1. This may be the source of your problem, especially if there's an issue related to standard output in that version. If not, it's almost certainly some other outdated dependency, ~/.irbrc setting, or other aspect of your environment that's preventing the payload from printing properly to standard output. See the note below about common problems I've experienced (and worked around) with REPLs and standard output.

General Tip for Avoiding Issues with IRB and Pry

In my personal experience, using io: $stdout may conflict with your REPL. I've seen this on other systems under irb, and on most systems under Pry, where the solution is generally to use io: $stderr or file_name: "/dev/stderr" as your output stream. In either approach, using the standard error stream avoids cases where something else (such as irb or pry) is interfering with or hijacking standard output.

[bethesque]

Thank you for taking the time to respond so thoroughly Todd. Sorry for my slow response.

You say it works as expected, however, the message is not printed in your logs. Note the lack of "message": "this message is not printed" below in your output.

logger.info("this message is not printed", payload: { foo: "bar" })
#=> true
{"host":"localhost.local","application":"Semantic Logger","timestamp":"2022-07-28T01:54:04.077857Z","level":"info","level_index":2,"pid":20991,"thread":"200","name":"logger","payload":{"foo":"bar"}}

I am able to reproduce the issue using alpine ruby.

$ docker run --rm -it ruby:2.7.6-alpine3.15
irb(main):001:0> require "bundler/inline"
=> true
irb(main):002:1* gemfile do
irb(main):003:1*   source "https://rubygems.org"
irb(main):004:1*   gem "semantic_logger", "4.11.0"
irb(main):005:0> end
=> [<Bundler::Dependency type=:runtime name="semantic_logger" requirements="= 4.11.0">]
irb(main):006:0" require "semantic_logger
irb(main):006:0> require "semantic_logger"
=> false
irb(main):007:0> SemanticLogger.add_appender(io: $stdout, formatter: :json)
=> #<SemanticLogger::Appender::IO:0x0000004025624a98 @io=#<IO:<STDOUT>>, @formatter=#<SemanticLogger::Formatters::Json:0x000000402565c8d0 @time_key=:timestamp, @time_format=:iso_8601, @log_host=true, @log_application=true, @log_environment=true, @precision=6>, @application=nil, @environment=nil, @host=nil, @metrics=false, @filter=nil, @name="SemanticLogger::Appender::IO", @level_index=nil, @level=nil>
irb(main):008:0> logger = SemanticLogger['logger']
=> #<SemanticLogger::Logger:0x0000004025bf7e70 @filter=nil, @name="logger", @level_index=nil, @level=nil>
irb(main):009:0> logger.info("this message is printed", { foo: "bar" })
=> true
{"host":"2209efe96950","application":"Semantic Logger","timestamp":"2022-09-06T23:21:41.757314Z","level":"info","level_index":2,"pid":1,"thread":"1760","name":"logger","message":"this message is printed","payload":{"foo":"bar"}}
irb(main):010:0> logger.info("this message is not printed", payload: { foo: "bar" })
=> true
{"host":"2209efe96950","application":"Semantic Logger","timestamp":"2022-09-06T23:21:46.977182Z","level":"info","level_index":2,"pid":1,"thread":"1760","name":"logger","payload":{"foo":"bar"}}

If this usage is no longer supported, then I will update all our code. If this is the intended usage still, then I believe the logs show there is a bug.

[todd-a-jacobs]

@bethesque

If you're not expecting the message to be printed, I'm not sure why you think it would be? Maybe I misunderstood your example, or you might want to make it clearer. That's a side issue; the real issue is that keyword arguments and hash arguments don't work the same on newer Ruby versions.

As a work-around, you might consider passing the message and payload as explicit keyword arguments. For example:

logger.info message: "whatever you want", payload: {whatever: "you need"}

rather than relying on the first element being the message when later arguments are possibly being misinterpreted as a Hash or block. Since SemanticLogger can also take a block, and behaves differently with opt-style Hash arguments on different versions of Ruby, being explicit is your best bet.

At any rate, there's a difference in passing a Hash and passing a series of keyword arguments. Unless you pass a Hash as an option to the :payload keyword, it's probably not going to work in Ruby 3.x without significant changes. It will also likely require dropping support for older rubies or adding ruby2keyword support in various places.

More importantly, you didn't mention until your last message that you're using Alpine Linux. Alpine uses muscl rather than GCC to compile, so you aren't going to always get consistent behavior out of native extensions. In addition to the keyword arguments issue, consider using Debian Slim instead of Alpine, or installing GCC and any other build requirements into your Alpine container rather than relying on muscl for your gems.

It's probably not the answer you want, but I'm more than 80% sure that at least one of the these suggestions will solve your immediate problem.

[bethesque]

If you're not expecting the message to be printed, I'm not sure why you think it would be?

I am expecting the message to be printed. This is the format that my project has used for many years. The example I have provided demonstrates that it is not printed, and that it stopped being printed between 4.10 and 4.11.

I believe it was either this commit or this commit.

My query was - is the format logger.info "whatever you want", payload: {whatever: "you need"} meant to be supported (in which case this is a regression, as it used to work), or is it not (in which case, perhaps it only ever worked unintentionally).

[reidmorrison]

Thank you for the pull request, going to see if we can include it in the v5 major release.