fix: write log text that isn't valid UTF-8 instead of raising

[rpearce]

Description

Formatter#call ends with to_json, which raises JSON::GeneratorError on text that isn't valid UTF-8. Since json 3.0 it also raises on binary text with any non-ASCII byte. Logger doesn't rescue a formatter's error, so the log call itself raises.

In a Rails 8.1 app with logs_monitor: true, a crafted request becomes a 500:

• GET /?%FF=1: Rails refuses the parameter key with ActionController::BadRequest, meaning to answer 400. Then ActionDispatch::DebugExceptions logs the error, and its message holds the raw key. The formatter raises, the raise escapes the app past ShowExceptions, and Puma answers its own 500. Nothing about the request reaches the log.
• A request path with a raw byte does the same, since Rails logs the path as binary.

A parameter value that isn't UTF-8 is unaffected, because Rails scrubs the value in its message.

Easy Repro

In this repo:

BUNDLE_GEMFILE=gems/rails.gemfile bundle exec ruby -Ilib -e '
require "scout_apm_logging"
formatter = ScoutApm::Logging::Loggers::Formatter.new
def formatter.emit_log(*); end
puts formatter.call("INFO", Time.now, nil, "bad \xFF byte")'

# => JSON::GeneratorError: source sequence is illegal/malformed utf-8

With this change, it prints the line with "msg":"bad � byte".

The fix

• msg2str: it now reads binary text, and text that's invalid in its encoding, as UTF-8, with bytes that aren't valid UTF-8 replaced by U+FFFD. Valid text in other encodings is left for to_json to convert, so ISO-8859-1 or UTF-16 text is written as before. Overriding msg2str covers String messages, Exception messages and inspect output alike.
• The OpenTelemetry body: a String message's body is now that same text. With the raw bytes, the OTLP encoder raised, and the exporter dropped the whole batch.
• The specs: spec/unit/loggers/formatter_spec.rb has one example per rule:
  • invalid UTF-8
  • binary text
  • valid UTF-16 kept as it is
  • an Exception's message
  • the OpenTelemetry body
• logger_spec.rb's top-level class_exec replaced Formatter#emit_log for every spec loaded with it. It's now scoped to its own examples, so the body example also passes when the unit specs run in one process.

Related

• Remove severity-number exporter patch; map severity at emit time #119 fixes the RSpec failures here on Ruby 3.3+. They're log_record_patch_spec.rb under opentelemetry-exporter-otlp-logs 0.7.0, which Remove severity-number exporter patch; map severity at emit time #119 removes; that's the break Log severity numbers will be wrong once opentelemetry-exporter-otlp-logs ships opentelemetry-ruby#2434 #116 describes.
• The overlap: Remove severity-number exporter patch; map severity at emit time #119 also adds spec/unit/loggers/formatter_spec.rb, and edits the same on_emit call, so whichever merges second needs a rebase. I'm happy to rebase this onto Remove severity-number exporter patch; map severity at emit time #119, and to move these examples onto its in-memory exporter.
• This PR's logger_spec.rb change helps Remove severity-number exporter patch; map severity at emit time #119 too. Without it, Remove severity-number exporter patch; map severity at emit time #119's formatter examples fail when the unit specs run in one process (BUNDLE_GEMFILE=gems/rails.gemfile bundle exec rspec spec/unit). The cause is logger_spec's top-level class_exec, which replaces emit_log for every spec loaded with it.

🤖 Generated with Claude Code

[rpearce]

In the mean time, I'm doing this in my project:

# frozen_string_literal: true

# scout_apm_logging's formatter writes each line as JSON, which raises on text that isn't valid UTF-8,
# and the raise escapes the log call: logging Rails' 400 for a param key that isn't UTF-8, or a request
# path with a raw byte, made it a 500. Binary or invalid text is read as UTF-8; to_json converts the rest.
module ScrubInvalidLogText
  def call(severity, time, progname, msg)
    if msg.is_a?(String) && !(msg.valid_encoding? && msg.encoding != Encoding::BINARY)
      msg = msg.dup.force_encoding(Encoding::UTF_8).scrub
    end
    super
  end
end

ScoutApm::Logging::Loggers::Formatter.prepend(ScrubInvalidLogText)

[jrothrock]

Ran this together with #118/#119 in a Rails 8.1.4 app on exporter 0.7.0: /?%FF=1 now gets its 400 instead of a Puma 500, all 33 batches exported, and the U+FFFD lines show up in the logs UI. 👍