Skip to content

Encode log entries one at a time so one bad value can't drop a batch - #54

Merged
PetrHeinz merged 4 commits into
mainfrom
claude/encode-entries-individually
Oct 2, 2026
Merged

PetrHeinz merged 4 commits into
mainfrom
claude/encode-entries-individually

Conversation

@PetrHeinz

@PetrHeinz PetrHeinz commented Oct 1, 2026 •

Copy link
Copy Markdown
Member

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: with use Rack::CommonLogger, logger in a Rack app, the red-team got 0 of the app's 3 log lines in Better Stack, against 3 of 3 without it.

  • Each entry is now encoded on its own and the msgpack array is assembled from the encoded entries, so the request body has the same shape as before.
  • Before encoding, values msgpack can't encode are converted, recursively (table below).
  • If an entry still can't be encoded (for example a value whose to_s raises), it is replaced by a minimal line with its level, its dt and the message Logtail 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 the Config debug logger.
  • Logtail::Logger#<< logs the string, without its trailing newline, as an info line instead of writing it raw to the device.
  • HTTP#write wraps anything that isn't a Logtail::LogEntry in an info-level entry, so strings from a plain ::Logger writing to the device arrive too.
Value Sent as
Time, DateTime, ActiveSupport::TimeWithZone ISO 8601 in UTC with microseconds, the same format as dt: "2026-10-01T12:00:00.123456Z"
Date ISO 8601 date: "2026-10-01"
BigDecimal String without exponent: "19.99"
Rational and other numbers that aren't an Integer or a Float String: "1/3"
Integer outside the signed 64-bit range String of its digits: "18446744073709551616"
Set Array
Struct Hash of its members
Exception {"class" => "ArgumentError", "message" => "boom"}
Object with a private_id, like a Rack::Session::SessionId its private_id
Hash, Array, Set or Struct that contains itself "[circular]" where it repeats
Anything else: Range, Class, Proc, records, other objects its to_s

Strings, Symbols, Floats, true, false, nil and Integers in range pass through unchanged, and Hashes and Arrays are converted element by element. A string that isn't valid UTF-8 goes to force_utf8_encoding, wherever it is.

Behaviour and compatibility:

  • Lines that used to vanish now arrive. Values that were already deliverable are sent exactly as before.
  • A << line now goes through the formatter like any info line: it respects the logger's level, reaches the extra loggers passed to Logtail::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_stack blocks now always receive a LogEntry, also for lines written to the device directly.
  • Encoding a batch costs about what it did on 0.1.20, see the follow-up below; the request format doesn't change.
  • On its own, this PR sends a binary string in an Array or a Hash key as a UTF-8 string, as 0.1.20 already did for Hash values; with Send only valid UTF-8 so one bad string can't break queries on a source #56 such strings are scrubbed.
  • I checked ActiveSupport::TimeWithZone locally 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):

  • Speed. The first version copied every Hash and Array of a log line twice, once here and once in 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_value now 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 to force_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.
  • Session ids. With the released logtail-rack 0.2.8, which logs the Rack::Session::SessionId itself, the to_s fallback sent its public id, which for Rack::Session::Pool and other server-side stores is the session cookie. An object that responds to private_id is now sent as its private_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:

0.1.20 before after
Encoding a typical line, incl. deflate, this PR alone 3.42 µs 9.0 µs 3.55 µs
The same, merged with #56 3.42 µs 13.0 µs 3.5–3.7 µs
30,000 requests through the middleware stack from the docs, merged with #56: p99.9, the requests that encode the full buffer 4.8 ms 16.2–16.5 ms 5.0 ms
The same: mean 152 µs 177 µs 154 µs

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

PetrHeinz and others added 2 commits October 1, 2026 18:40
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>
PetrHeinz and others added 2 commits October 2, 2026 08:12
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
PetrHeinz marked this pull request as ready for review October 2, 2026 09:07
@PetrHeinz
PetrHeinz merged commit 54b83ac into main Oct 2, 2026
13 checks passed
@PetrHeinz
PetrHeinz deleted the claude/encode-entries-individually branch October 2, 2026 11:36
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>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant