From 00c70f7997b3bc44f1428c749444c232a08b53d1 Mon Sep 17 00:00:00 2001 From: "Robert W. Pearce" Date: Sun, 18 Oct 2026 14:00:02 -0400 Subject: [PATCH] fix: write log text that isn't valid UTF-8 instead of raising 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 raised. In Rails, logging the 400 for a parameter key that isn't UTF-8, or a request path with a raw byte, escaped the app as a 500. msg2str 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. A String message's OpenTelemetry body is now that same text. The raw bytes made the OTLP encoder raise, and the exporter dropped the whole batch. logger_spec stubbed Formatter#emit_log for every spec loaded with it, so the new body spec failed when the unit specs ran in one process. The stub is now scoped to logger_spec's own examples. Co-Authored-By: Claude Opus 5.5 (1M context) --- lib/scout_apm/logging/loggers/formatter.rb | 10 ++- spec/unit/loggers/formatter_spec.rb | 96 ++++++++++++++++------ 2 files changed, 78 insertions(+), 28 deletions(-) diff --git a/lib/scout_apm/logging/loggers/formatter.rb b/lib/scout_apm/logging/loggers/formatter.rb index d27b415..a24f8e4 100644 --- a/lib/scout_apm/logging/loggers/formatter.rb +++ b/lib/scout_apm/logging/loggers/formatter.rb @@ -50,6 +50,14 @@ def call(severity, time, progname, msg) private + # to_json raises on binary or invalid text, and the raise escapes the log call. + def msg2str(msg) + text = super + return text if text.valid_encoding? && text.encoding != Encoding::BINARY + + text.dup.force_encoding(Encoding::UTF_8).scrub + end + def emit_log(msg, severity, time, attributes_to_log) ScoutApm::Logging::Loggers::OpenTelemetry.logger_provider.logger( name: 'scout_apm', @@ -61,7 +69,7 @@ def emit_log(msg, severity, time, attributes_to_log) ), attributes: attributes_to_log.transform_keys(&:to_s), timestamp: time, - body: msg, + body: msg.is_a?(String) ? attributes_to_log[:msg] : msg, context: ::OpenTelemetry::Context.current ) end diff --git a/spec/unit/loggers/formatter_spec.rb b/spec/unit/loggers/formatter_spec.rb index 26c4427..71330d7 100644 --- a/spec/unit/loggers/formatter_spec.rb +++ b/spec/unit/loggers/formatter_spec.rb @@ -1,3 +1,4 @@ +require 'json' require 'logger' require 'stringio' @@ -6,39 +7,80 @@ require 'scout_apm_logging' describe ScoutApm::Logging::Loggers::Formatter do - let(:exporter) { OpenTelemetry::SDK::Logs::Export::InMemoryLogRecordExporter.new } + context 'severity' do + let(:exporter) { OpenTelemetry::SDK::Logs::Export::InMemoryLogRecordExporter.new } - before do - ScoutApm::Logging::Context.instance + before do + ScoutApm::Logging::Context.instance - provider = OpenTelemetry::SDK::Logs::LoggerProvider.new - provider.add_log_record_processor(OpenTelemetry::SDK::Logs::Export::SimpleLogRecordProcessor.new(exporter)) - ScoutApm::Logging::Loggers::OpenTelemetry.logger_provider = provider - end + provider = OpenTelemetry::SDK::Logs::LoggerProvider.new + provider.add_log_record_processor(OpenTelemetry::SDK::Logs::Export::SimpleLogRecordProcessor.new(exporter)) + ScoutApm::Logging::Loggers::OpenTelemetry.logger_provider = provider + end + + { + 'DEBUG' => :SEVERITY_NUMBER_DEBUG, + 'INFO' => :SEVERITY_NUMBER_INFO, + 'WARN' => :SEVERITY_NUMBER_WARN, + 'ERROR' => :SEVERITY_NUMBER_ERROR, + 'FATAL' => :SEVERITY_NUMBER_FATAL, + 'ANY' => :SEVERITY_NUMBER_FATAL, + 'SOMETHING_ELSE' => :SEVERITY_NUMBER_UNSPECIFIED + }.each do |label, expected| + it "emits #{expected} for #{label}" do + described_class.new.call(label, Time.now, nil, 'msg') + + record = exporter.emitted_log_records.last + expect(record.severity_text).to eq(label) + expect(record.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber.const_get(expected)) + end + end + + it 'maps Logger#unknown to FATAL' do + logger = ::Logger.new(StringIO.new) + logger.formatter = described_class.new + logger.unknown('gone') - { - 'DEBUG' => :SEVERITY_NUMBER_DEBUG, - 'INFO' => :SEVERITY_NUMBER_INFO, - 'WARN' => :SEVERITY_NUMBER_WARN, - 'ERROR' => :SEVERITY_NUMBER_ERROR, - 'FATAL' => :SEVERITY_NUMBER_FATAL, - 'ANY' => :SEVERITY_NUMBER_FATAL, - 'SOMETHING_ELSE' => :SEVERITY_NUMBER_UNSPECIFIED - }.each do |label, expected| - it "emits #{expected} for #{label}" do - described_class.new.call(label, Time.now, nil, 'msg') - - record = exporter.emitted_log_records.last - expect(record.severity_text).to eq(label) - expect(record.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber.const_get(expected)) + expect(exporter.emitted_log_records.last.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_FATAL) end end - it 'maps Logger#unknown to FATAL' do - logger = ::Logger.new(StringIO.new) - logger.formatter = described_class.new - logger.unknown('gone') + context 'encoding' do + let(:formatter) { ScoutApm::Logging::Loggers::Formatter.new } + let(:otel_logger) { double(on_emit: nil) } + + before do + allow(ScoutApm::Logging::Loggers::OpenTelemetry).to receive(:logger_provider).and_return(double(logger: otel_logger)) + end + + it 'should replace bytes that are not valid UTF-8' do + line = formatter.call('INFO', Time.now, nil, "bad \xFF byte") + + expect(JSON.parse(line)['msg']).to eq("bad \u{FFFD} byte") + end + + it 'should read binary text, as a request path is logged, as UTF-8' do + line = formatter.call('INFO', Time.now, nil, 'café /x?%FF'.b + "\xFF".b) + + expect(JSON.parse(line)['msg']).to eq("café /x?%FF\u{FFFD}") + end + + it 'should keep valid text in another encoding' do + line = formatter.call('INFO', Time.now, nil, 'café'.encode('UTF-16LE')) + + expect(JSON.parse(line)['msg']).to eq('café') + end - expect(exporter.emitted_log_records.last.severity_number).to eq(OpenTelemetry::Logs::SeverityNumber::SEVERITY_NUMBER_FATAL) + it 'should replace bad bytes in an exception message' do + line = formatter.call('ERROR', Time.now, nil, RuntimeError.new("bad \xFF byte".b)) + + expect(JSON.parse(line)['msg']).to eq("bad \u{FFFD} byte (RuntimeError)\n") + end + + it 'should emit the replaced text as the OpenTelemetry body' do + formatter.call('INFO', Time.now, nil, "bad \xFF byte".b) + + expect(otel_logger).to have_received(:on_emit).with(hash_including(body: "bad \u{FFFD} byte")) + end end end