fix(sdk/log-ship): a busy plugin's lines survive a POST, and the shutdown tail is actually sent

Two bugs in the log shipper, both found by re-reading it rather than by a
failing test, and both of the kind where the symptom is a missing log line —
which is the one failure a logging path must not have.

The recursion guard was held across the whole `await fetch`, and `enqueue`
checked it. So every line logged while a POST was open was dropped, silently.
That window is milliseconds when the host is healthy and much longer when it is
not, and the lines lost are whatever a busy plugin happened to be saying — so
the shipper was least reliable exactly when it was most needed. The flag now
guards flush re-entry only (the interval can fire while a slow POST is still
open, and two concurrent flushes would splice disjoint batches out of one queue
and deliver them out of order). Nothing on the shipping path logs, so the
recursion it was guarding cannot form; that is now a stated rule at the top of
the file rather than a flag that costs real lines.

An explicit `flush()` hit that same re-entry guard and returned having sent
nothing. That is the shutdown path: the runner flushes once more after its
units' finalizers have run, and those last lines are the ones that say whether
the shutdown was clean. It now waits for an in-flight flush before starting its
own.

Both are covered by tests that fail against the previous code. The first needed
a server that signals when it has the request — logging merely "after calling
flush()" passes against the bug, because flush yields at its own awaits long
before the fetch starts.

Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
This commit is contained in:
2026-08-03 15:53:29 +02:00
co-authored by Claude Opus 5
parent 365caa23be
commit 1e56705b86
2 changed files with 60 additions and 2 deletions
+15 -2
View File
@@ -244,12 +244,23 @@ export const installLogShipper = (
}
};
// The most recent flush, so an explicit `flush()` can WAIT for a periodic one rather than hit
// the re-entry guard and return having sent nothing. That matters on the shutdown path: the
// runner flushes once more after its units' finalizers have run, and those last lines are the
// ones that say whether the shutdown was clean. The window is widest exactly when the host is
// slow — which is when the logs are worth most.
let inFlight: Promise<void> = Promise.resolve();
const runFlush = (): Promise<void> => {
inFlight = flush();
return inFlight;
};
const timer = setInterval(() => {
if (skipTicks > 0) {
skipTicks -= 1;
return;
}
void flush();
void runFlush();
}, options.intervalMs ?? 2_000);
// The runner parks on its own keep-alive handle; this timer must not be what holds the process
// open, or a runner with nothing to run would never exit.
@@ -258,7 +269,9 @@ export const installLogShipper = (
return {
flush: async () => {
skipTicks = 0;
await flush();
// `flush` never rejects (every path is caught); `.catch` only keeps that a guarantee.
await inFlight.catch(() => {});
await runFlush();
},
stop: () => {
stopped = true;
+45
View File
@@ -228,6 +228,51 @@ describe("shipping", () => {
expect(all).toContain("during");
});
test("an explicit flush waits for an in-flight one instead of no-opping", async () => {
// This is the shutdown path. The runner flushes once more after its units' finalizers have
// run, and those last lines are the ones that say whether the shutdown WAS clean. If a
// periodic flush happened to be mid-POST, an explicit flush that simply returned would
// leave them unsent — and the window is widest exactly when the host is slow, which is when
// the logs matter most.
let release: (() => void) | undefined;
const held = new Promise<void>((r) => {
release = r;
});
let arrived: (() => void) | undefined;
const received = new Promise<void>((r) => {
arrived = r;
});
let first = true;
const batches: Captured[] = [];
const server = Bun.serve({
port: 0,
fetch: async (req) => {
batches.push((await req.json()) as Captured);
if (first) {
first = false;
arrived?.();
await held;
}
return new Response(null, { status: 204 });
},
});
stopHost = () => server.stop(true);
await withShipper(`http://127.0.0.1:${server.port}`, async (shipper) => {
console.log("2026-08-03T10:11:12.345Z [x] first");
const slow = shipper.flush();
await received;
console.log("2026-08-03T10:11:12.345Z [x] shutdown line");
release?.();
// The shutdown flush: must not return until the tail is actually sent.
await shipper.flush();
await slow;
});
const all = batches.flatMap((b) => b.entries.map((e) => e.msg));
expect(all).toContain("shutdown line");
});
test("overlapping flushes do not double-send", async () => {
// The timer can fire while a slow POST is still open. Two concurrent flushes would splice
// disjoint batches out of one queue and deliver them out of order.