Structured logging: a failed JSON encode corrupts the next log event written on the same thread

[edwardsre]

When WritableJson.toByteArray(Charset) fails part-way through writing, the partial output is left behind in the thread-local AppendableByteArray buffer and is emitted as a prefix to the next value encoded on that thread. In structured logging this means a single failed log event corrupts the following log event into invalid JSON.

This is a regression in 4.1.0: AppendableByteArray was introduced in this line (see #50369), replacing a per-call ByteArrayOutputStream. 4.0.x and earlier are not affected.

Minimal reproduction (no logging involved)

It is not specific to duplicate names. See Two notes on scope below.

JsonWriter<String> duplicate = JsonWriter.of(members -> {
  members.add("name", s -> s);
  members.add("name", s -> s);   // any mid-encode failure will do; see note below
});
JsonWriter<String> healthy = JsonWriter.of(members -> members.add("ok", s -> s));

try {
  duplicate.write("first").toByteArray();
}
catch (RuntimeException ex) {
  System.out.println("failed as expected: " + ex.getMessage());
}

// completely unrelated writer, same thread
System.out.println(new String(healthy.write("second").toByteArray()));

4.1.0:

failed as expected: The name 'name' has already been written
{"name":"first",{"ok":"second"}

4.0.7 (same program, same classpath otherwise):

failed as expected: The name 'name' has already been written
{"ok":"second"}

How this shows up in structured logging

With nothing but the built-in formats configured:

logging.structured.format.file=logstash
logging.file.name=app.jsonl

MDC.put("mdc-key", "mdc-value");

LOG.atInfo()
   .addKeyValue("message", "duplicate-via-kvp")   // collides with the formatter's own field
   .log("EVENT-A duplicate key");

LOG.atInfo().log("EVENT-B next event same thread");

app.jsonl — EVENT-A is truncated mid-object (trailing comma, no closing brace) and EVENT-B is appended to the same line, so the line is not parseable as JSON:

{"@timestamp":"...","@version":"1","message":"EVENT-A duplicate key","logger_name":"...","thread_name":"main","level":"INFO","level_value":20000,"mdc-key":"mdc-value",{"@timestamp":"...","message":"EVENT-B next event same thread",...}

Reproduced the same way with logging.structured.format.file=ecs, and with a colliding MDC key instead of a key/value pair. So each occurrence costs two events: the failing one is dropped (as covered by #45217) and the next one on that thread is corrupted.

Cause

JsonWriterStructuredLogFormatter.formatAsBytes encodes into AppendableByteArray.get(charset), a thread-local reused buffer. The only reset() call is inside AppendableByteArray.toByteArray(), which is never reached when the write throws, so the partial bytes survive into the next call:

// WritableJson
default byte[] toByteArray(Charset charset) {
  Assert.notNull(charset, "'charset' must not be null");
  try {
    AppendableByteArray appendable = AppendableByteArray.get(charset);
    to(appendable);                    // throws -> buffer keeps partial output
    return appendable.toByteArray();   // never reached, so reset() never runs
  }
  catch (IOException ex) {
    throw new UncheckedIOException(ex);
  }
}

Two notes on scope:

• It is not specific to duplicate names. Any failure mid-encode leaks. Verified with a value that throws while being written:

  members.add("boom", s -> (WritableJson) out -> { throw new IOException("serialization failed"); });
  // next write on same thread -> {"first":"value","boom":{"ok":"second"}

  So ValueProcessor failures, exceptions inside an application-supplied WritableJson value, and exceeded nesting depth all corrupt the following event too.

• The String path is unaffected, since WritableJson.toJsonString() allocates a fresh StringBuilder per call. Only the byte path leaks — i.e. Logback's StructuredLogEncoder.encode and Log4j2's StructuredLogLayout.toByteArray, both of which call formatAsBytes.

Suggested fix

Ensure the thread-local buffer cannot carry partial output across calls — either reset in a finally:

default byte[] toByteArray(Charset charset) {
  Assert.notNull(charset, "'charset' must not be null");
  AppendableByteArray appendable = AppendableByteArray.get(charset);
  try {
    to(appendable);
    return appendable.toByteArray();
  }
  catch (IOException ex) {
    throw new UncheckedIOException(ex);
  }
  finally {
    appendable.reset();
  }
}

or reset on acquire in AppendableByteArray.get(Charset), which additionally covers any future caller that abandons a buffer.

This is independent of #45217: even if duplicate names become warnings rather than errors, other encode failures would still corrupt the next event.

Environment

• Spring Boot 4.1.0 (regression; verified unaffected on 4.0.7)
• Logback 1.5.34, Java 25

[skdas20]

Excellent write-up — the minimal reproduction without any logging involved makes the mechanism much easier to pin down.

Tracing it in the current code, the buffer is only ever cleaned up on the success path:

WritableJson.toByteArray(Charset):

AppendableByteArray appendable = AppendableByteArray.get(charset);
to(appendable);              // <-- throws here
return appendable.toByteArray();

and reset() is invoked from inside AppendableByteArray.toByteArray():

byte[] toByteArray() {
    ...
    byte[] result = new byte[size];
    System.arraycopy(...);
    reset();                 // only reached when the write completed
    return result;
}

So when to(appendable) fails part-way, toByteArray() is never reached, reset() never runs, and the partially written bytes stay in the instance held by the ThreadLocal cache. get() then hands that same dirty instance to the next caller on that thread, which is exactly the observed prefix. That also explains why it is not specific to duplicate names — any exception raised between get() and toByteArray() leaves the buffer dirty.

Two places it could be addressed:

1. In WritableJson.toByteArray — reset in a finally/catch so a failed encode cleans up after itself.
2. In AppendableByteArray.get — reset the cached instance before returning it, so a buffer is clean by construction no matter how the previous user terminated.

(2) is the more robust of the two, since it also covers the early return in toByteArray():

int size = limit - position;
if (size <= 0) {
    return NO_BYTES;         // returns without reset(), buffer left flipped
}

and any future caller that obtains an AppendableByteArray and abandons it. (1) alone would leave those paths unguarded.

Happy to put up a PR with whichever shape you prefer, plus a regression test along the lines of the reproduction above (failed encode followed by an unrelated writer on the same thread). Just didn't want to jump ahead of triage on the placement.