message key in payload overwrites logging message

[chrisbloom7]

Environment

Provide at least:

• Ruby Version.
  • 2.7.1
• Semantic Logger Version.
  • semantic_logger (~> 4.8)
• Application/framework names and versions (e.g. Rails, Sinatra, Puma, etc.).
  • rails (6.1.4.4)
• Rails Semantic Logger Version, if applicable.
  • rails_semantic_logger (4.6.1)
• Rails configuration. Only need the settings related to Rails Semantic Logger and Semantic Logger.

  if ENV["RAILS_LOG_TO_STDOUT"].present?
  $stdout.sync = true
  config.rails_semantic_logger.add_file_appender = false
  config.rails_semantic_logger.format = :json
  config.semantic_logger.add_appender(
    io: $stdout,
    formatter: config.rails_semantic_logger.format
  )
  
  # Hide Rack started messages in production
  config.rails_semantic_logger.started = false
  
  # Hide ActionController processing messages in production
  config.rails_semantic_logger.processing = false
  
  # Hide ActionView rendering messages in production
  config.rails_semantic_logger.rendered = false
  end
  

• Full Stack Trace, if an exception is being raised.
  • N/A

Note:

• If the issue is with extensions to Rails to make it use Semantic Logger, please report the issue at Rails Semantic Logger.
• All appender issues should be reported here.

Expected Behavior

When logging something like

logger = SemanticLogger["Test"]
message = { foo: :bar }
logger.debug "Message received", message: message

I expect it to output

"name":"Test", "message":"Message received", "payload":{"message":{"foo":"bar"}}, ...

Actual Behavior

Instead, the message in the payload overwrites the first message argument, such that it is logged like this instead:

"name":"Test", "message":"{:foo=\u003e:bar}"

It does not matter if the second argument is passed as an implicit or explicit hash. For instance, this has the same result

logger.debug "Message received", { message: message }

The only way to work around it is to not use a key of message or to use the longer form of the logger API, i.e.

logger.debug message: "Message received", payload: { message: message }

as documented in https://logger.rocketjob.io/api.html#standard-logging-methods

Pull Request

• Consider submitting a Pull Request with a fix for the issue.
  • This is particularly helpful for appender changes/fixes since we don't have access to all appenders.
• Or, even a Pull request that only includes a test that reproduces the problem.

[reidmorrison]

The use of this older backward compatible API is not recommended, since it has to automagically guess what you are trying to do. The result is what you are seeing above.

logger.debug "Message received", message: message

The correct api to use when supplying a payload is to supply the payload tag:

logger.debug "Message received", payload: { message: "message" }

[chrisbloom7]

That's different than the API the docs describe

log.info(message, payload_or_exception = nil, exception = nil, &block)

# And then later, describing an alternative:

logger.debug(message: "Calling Supplier", payload: {request: "update", user: "Jack"})

You've just described a 3rd way of using it (ordinal message argument, keyword payload arg) which actually leads to the same issue as the one I reported. Based on the docs, I should be able to provide a string message and a hash-like payload, so I would expect

logger.debug "Message received", { payload: { message: "message" } }

to output

"name":"Test", "message":"Message received", "payload":{"payload":{"message":{"foo":"bar"}}}, ...

But the as with the message key in my example, the payload key inside the hash argument gets extracted out into the payload kwarg. I believe this has to do with this line

semantic_logger/lib/semantic_logger/base.rb

Line 335 in 6b28a6f

log.assign(message: message, **log.extract_arguments(payload))

The resulting call is essentially this:

log.assign(message: "Ordinal message", message: "Extracted message")

This will generate a warning about key :message is duplicated and overwritten but will still allow the assignment, and the result is that the second message kwarg overwrites the first.

log.message
=> "Extracted message"

[reidmorrison]

Wish I could re-do the logging api. The api evolved based on what was available at the time, and unfortunately I chose to allow any arbitrary data in the method call to be "automagically" converted into the payload, instead of rejecting such calls and forcing that data to be supplied as a separate payload tag.
Additionally, the previous loggers allowed variable numbers of arguments, where sometimes it was just the message, or just the exception. Trying to be backward compatible and still add new features is a fine rope walking exercise.
I am still surprised by some of the unexpected behavior of existing loggers that Semantic Logger has to support, even though it does not add value to Semantic Logger or its API.

For the specific use-case above, we could add code to detect if the message is already present, to leave the additional message in the payload alone? I bet it would break someones code somewhere though.

[chrisbloom7]

Hmm, it does sound complicated trying to support all the older formats. Maybe we would need to go so far as to add a flag to the root SemanticLogger class that enables an incompatible mode where log.assign(message: message, **log.extract_arguments(payload)) works differently? In the meantime I'm working around it with copious comments about why some logger calls look different than others when I want to include a payload in the payload

[reidmorrison]

Going to give something a try in Semantic Logger v4.11. Give it a try and let me know if it works? Will publish the new gem shortly.