Encode log entries one at a time so one bad value can't drop a batch - #54
Merged
Merged
Conversation
One value msgpack can't encode (Time, Date, BigDecimal, Set, Struct, an exception, a cyclic Hash, ...) currently drops the whole batch, and so does a raw String from Logger#<< or a plain ::Logger writing to the HTTP device. These tests pin the expected behaviour: every line of the batch arrives, the value is converted, a line that still can't be encoded is replaced by one that says why, and raw strings arrive as info lines. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
The HTTP device msgpacked the whole batch in one call, after taking it
off the queue, and swallowed the error. One value msgpack can't encode
lost every line of the batch, up to 1,000 lines from all threads.
- Values msgpack can't encode are converted first, recursively: times
to ISO 8601 in UTC with microseconds (like dt), dates to ISO 8601,
BigDecimal, Rational and Integers beyond 64 bits to strings, Sets to
Arrays, Structs to Hashes, exceptions to {class, message}, cycles to
"[circular]", anything else to its to_s.
- Each entry is encoded on its own and the msgpack array is assembled
from the encoded entries. An entry that still fails is replaced by a
minimal line with its level, dt and a message naming the error.
- Logger#<< logs the chomped string at info instead of writing it raw
to the device (Rack::CommonLogger uses <<), and HTTP#write wraps any
write that isn't a LogEntry in an info-level LogEntry.
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Encoding a log line copied every hash and array in it twice, once to convert what msgpack can't encode and once to force strings to UTF-8, even when nothing had to change. That made it several times slower than on 0.1.20. These tests pin that: - a log line msgpack can encode is sent as it is, without a copy; - strings that aren't valid UTF-8 go to force_utf8_encoding wherever they are, also in arrays and hash keys, so a single pass can replace the second copy; - an object with a private id is sent as that id. A Rack::Session::SessionId is one: logtail-rack 0.2.8 logs it, and its public id, which to_s returns, is the session cookie of a server-side session store. Three more pin what has to stay as it is: the order of the keys of a hash whose keys are converted, the logged values themselves, and hashes and arrays nested deeper than a pass that doesn't look for cycles would go. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
encode_log_entry copied every hash and array of a log line twice: once in encodable_value, to convert what msgpack can't encode, and once in force_utf8_encoding. Encoding a typical line took 13.5 us instead of 3.7 us on 0.1.20, and a request that fills the buffer, which encodes the whole batch, took about 17 ms instead of 5 ms. - encodable_value returns the log line itself when nothing in it needs to change, and otherwise copies only the hashes and arrays that change. - Strings that are valid UTF-8 are left as they are, any other string goes to force_utf8_encoding, also in arrays and hash keys, so the second pass is gone. On its own this sends a binary string in an array or a key as UTF-8, as 0.1.20 already did for hash values. - The first pass doesn't keep track of the hashes and arrays it is in, it gives up at 100 nested levels, which a cycle reaches, and a second pass keeps track of them to cut cycles off with "[circular]" as before. - One packer encodes the whole batch, entry by entry. - An object with a private id is sent as that id instead of to_s. A Rack::Session::SessionId logged by logtail-rack 0.2.8 is one: its public id is the session cookie of a server-side store. The spec that strings go to force_utf8_encoding now checks for at least one call, not exactly one: a hash whose key changes is copied from scratch, which converts that key again. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
PetrHeinz
marked this pull request as ready for review
October 2, 2026 09:07
PetrHeinz
added a commit
that referenced
this pull request
Oct 2, 2026
Conflicts in lib/logtail/log_devices/http.rb, both sides kept: - require block: #54's require "set" and this branch's require "time" - constants after MAX_RECONNECT_WAIT: this branch's MAX_RETRY_AFTER, REPORTED_REJECTIONS and REPORTED_REJECTIONS_LOCK, then SYNCHRONOUS_DELIVERY_TIMEOUT from #57/#58 Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
The HTTP device takes the whole batch off the queue, msgpacks it in one call and swallows any error. So a single value msgpack can't encode silently loses every line in the batch, up to 1,000 lines from all threads: a
Time,Date,BigDecimal,Set,Struct, an exception, an ActiveRecord record, an Integer beyond 64 bits, a Hash that contains itself.logger << "x"does the same, because it puts a raw String into the device's queue: withuse Rack::CommonLogger, loggerin a Rack app, the red-team got 0 of the app's 3 log lines in Better Stack, against 3 of 3 without it.to_sraises), it is replaced by a minimal line with itslevel, itsdtand the messageLogtail could not encode this log line (RuntimeError: to_s failed): <original message>, cut at 8,192 bytes. The rest of the batch is delivered, and the error also goes to theConfigdebug logger.Logtail::Logger#<<logs the string, without its trailing newline, as an info line instead of writing it raw to the device.HTTP#writewraps anything that isn't aLogtail::LogEntryin an info-level entry, so strings from a plain::Loggerwriting to the device arrive too.Time,DateTime,ActiveSupport::TimeWithZonedt:"2026-10-01T12:00:00.123456Z"Date"2026-10-01"BigDecimal"19.99"Rationaland other numbers that aren't an Integer or a Float"1/3""18446744073709551616"SetStruct{"class" => "ArgumentError", "message" => "boom"}private_id, like aRack::Session::SessionIdprivate_id"[circular]"where it repeatsRange,Class,Proc, records, other objectsto_sStrings, Symbols, Floats,
true,false,niland Integers in range pass through unchanged, and Hashes and Arrays are converted element by element. A string that isn't valid UTF-8 goes toforce_utf8_encoding, wherever it is.Behaviour and compatibility:
<<line now goes through the formatter like any info line: it respects the logger's level, reaches the extra loggers passed toLogtail::Logger.new, and on a STDOUT logger with the JSON formatter it becomes a JSON line instead of the raw string.filter_sent_to_better_stackblocks now always receive aLogEntry, also for lines written to the device directly.ActiveSupport::TimeWithZonelocally against activesupport 8.1.4. The suite doesn't depend on ActiveSupport, so it isn't covered on CI.Follow-up after the E2E run of the release candidate (two more commits, the first one only tests and red on CI):
force_utf8_encoding, so encoding was several times slower than on 0.1.20, and a request whose log line fills the 1,000-line buffer, which encodes the batch in the request's thread, got about 3× slower.encodable_valuenow returns the log line itself when nothing in it has to change, copies only the Hashes and Arrays that do, and hands only strings that aren't valid UTF-8 toforce_utf8_encoding, so there is a single pass. It doesn't look for cycles until Hashes and Arrays nest 100 levels deep; then a second pass that keeps track of them cuts cycles off with"[circular]"as before. One packer encodes the batch entry by entry. What is sent doesn't change: merged with Send only valid UTF-8 so one bad string can't break queries on a source #56, 67 tricky log lines (the cases above, invalid and binary strings, keys that change, cycles, 150 levels of nesting, subclasses of String, Hash and Array) encode byte for byte as before.Rack::Session::SessionIditself, theto_sfallback sent its public id, which forRack::Session::Pooland other server-side stores is the session cookie. An object that responds toprivate_idis now sent as itsprivate_id, as Log the private session id so session rows arrive and can't leak session cookies logtail-ruby-rack#30 does on its side. This is duck-typed, without a dependency on Rack.Numbers on Ruby 3.4.9, in process, with the released logtail-rack 0.2.8 so the log lines are the same in every column:
Targets the logtail 0.1.21 patch release. No dependencies on the other open PRs. It pairs with #56, which makes every string valid UTF-8 in the same code path; the two merge cleanly in either order and pass the suite together.
The first commit only adds the tests and is expected to fail on CI; the fix follows in the next commit. In that first run the Ruby 2.6 job hung on the test with an Array that contains itself, because the released code makes msgpack recurse without end. I cancelled the run after the other ten jobs had failed.
🤖 Generated with Claude Code