Logs passed as non-String and formatted into a String are ignored

[andreaswachowski]

trafficstars

If your bug is about how AppSignal works in your app specifically we recommend you contact us at [email protected] with your bug report instead.

---

Describe the bug

Appsignal does not accept log messages that arrive as a non-String and are formatted into a String. Instead, it triggers the "Logger message was ignored, because it was not a String" in the appsignal internal logger.

Specific example: Sidekiq::LogstashJobLogger (from sidekiq-logstash) feeds a Hash into the logger, and Sidekiq::Logging::LogstashFormatter converts that to a string. However, since cd2f9fbfe31, the check whether the message is a String happens before the message is formatted, not after (see lib/appsignal/logger lines 76-83).

If the two lines were reversed, the JSON would be accepted by Appsignal, and it would show the various key-value pairs as attributes.

To Reproduce

(Please see https://github.com/andreaswachowski/appsignal_reproduction/blob/main for a working reproduction.)

In brief: Create a Rails application with the Gems

• appsignal
• sidekiq
• sidekiq-logstash

And a config/initializer/sidekiq.rb including

Sidekiq::Logstash.setup

Sidekiq.configure_server do |config|
  appsignal_logger = Appsignal::Logger.new('sidekiq', format: Appsignal::Logger::JSON)
  appsignal_logger.formatter = Sidekiq::Logging::LogstashFormatter.new
  appsignal_logger.broadcast_to(config.logger)
  config.logger = appsignal_logger

  # ... (more configuration)
end

Create a trivial Sidekiq job

class HelloWorldJob < ApplicationJob
  queue_as :default

  def perform(*args)
    nil
  end
end

and, while Sidekiq is running on a different terminal, execute it from the Rails console with HelloWorldJob.perform_later. The Sidekiq terminal shows the log message

{"severity":"INFO","retry":true,"queue":"default","wrapped":"HelloWorldJob","args":[{"job_class":...

log/appsignal.log includes

[2025-06-04T14:21:16 (process) #74631][WARN] Logger message was ignored, because it was not a String: {"retry" => true, "queue" => "default", "wrapped" => "HelloWorldJob", "args" => [{"job_ ...

Edit: Initialize the formatter directly on the appsignal_logger. Otherwise, the formatter is nil, and hence the formatting wouldn't happen even if the suggested fix is applied. This simply fixes the reproduction, it doesn't change the core problem.

[andreaswachowski]

~~Actually, my configuration might be wrong. It seems to work when I assign the formatter directly to the appsignal_logger:~~ Nope, sorry I temporarily patched the Gem and got confused. It is as described above.

On a side note, I still don't understand why the attributes receive a type suffix, as seen below (I do however read in the documentation that an Array as a JSON-value cannot be parsed, so I understand the related message):

[unflxw]

Thank you for reporting this.

It might make sense if our logger called .to_s in objects that implement it, instead of rejecting non-String values outright.

[andreaswachowski]

@unflxw Thank you for following up on this. While I can confirm that the proposed fix in 5f1a049 leads to the message being passed to the extension, unfortunately, the original Hash (which also included a message-key) is now simply output as a String, with no filterable attributes (except @version_string):

Note that the JSON includes a message-key. Following https://docs.appsignal.com/logging/formatting.html and https://docs.appsignal.com/logging/integrations/ruby.html#logfmt-and-json, I would have expected it to be possible to pass a Hash and extract the filterable attributes automatically, like so:

(By the way, I also don't see how we could do something like this, where we extract Sidekiq execution data, by calling logger.info("message", { key: value, key2: value2, ...} ourselves, it feels to me that this enrichment must happen in the formatter, whose API does not know about attributes, only a message with an unspecified type.)

Should it perhaps be possible to pass a String or a Hash into the extension (and if the Hash contains a message or msg key, then its value must be a String or representable as a String)?

Edit: Perhaps the issue is that we always use to_s, but for a Hash, to_json might be required (haven't tried that yet, but that's what https://github.com/iMacTia/sidekiq-logstash/blob/master/lib/sidekiq/logging/logstash_formatter.rb#L26 is doing)?

Edit2: Actually, I could adjust the formatter to first attempt to JSON-parse the message it receives. So nevermind I suppose.

Edit3: The default logger formatter does make few assumptions on the message object (see https://github.com/ruby/logger/blob/v1.7.0/lib/logger.rb#L172-L177 ). In particular, it does not assume that the message is necessarily a String (which Appsignal currently enforces). I suppose ideally, Appsignal would be 1) add the message to the loggers (to avoid duplicate formatting 2) pass the message as-is to the formatter, and 3) test the Stringiness on the formatted result:

@loggers.each do |logger|
  logger.add(severity, message, group)
rescue
  nil
end

message = formatter.call(severity, Time.now, group, message) if formatter

unless message.is_a?(String)
  Appsignal.internal_logger.warn(
    "Logger message was ignored, because it was not a String: #{message.inspect}"
  )
  return
end

That's what I had initially in mind, but at the time I wasn't sure whether that violates the intention of cd2f9fb. I think it works though?

[unflxw]

Thank you so much for trying out the fix @andreaswachowski! This is extremely useful feedback. I'll attempt to address this issue and ping you back.

[andreaswachowski]

Sounds good. Note I did not try the entirety of changes on #1423, just the part

message = message.to_s if message.respond_to?(:to_s)

But, as you already clarified in https://github.com/appsignal/appsignal-ruby/pull/1423/files#r2155308686, indeed I believe the actual issue (here, anyway) is converting the message type (to String) inside the logger, instead of delegating that to the formatter. Thank you for the follow up!