From 1e56705b86b31f6014b23aa9591474499e8968b0 Mon Sep 17 00:00:00 2001 From: enricobuehler Date: Mon, 3 Aug 2026 15:53:29 +0200 Subject: [PATCH] fix(sdk/log-ship): a busy plugin's lines survive a POST, and the shutdown tail is actually sent MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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) --- sdk/src/log-ship.ts | 17 +++++++++++++-- sdk/test/log-ship.test.ts | 45 +++++++++++++++++++++++++++++++++++++++ 2 files changed, 60 insertions(+), 2 deletions(-) diff --git a/sdk/src/log-ship.ts b/sdk/src/log-ship.ts index dd000749..f7003fca 100644 --- a/sdk/src/log-ship.ts +++ b/sdk/src/log-ship.ts @@ -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 = Promise.resolve(); + const runFlush = (): Promise => { + 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; diff --git a/sdk/test/log-ship.test.ts b/sdk/test/log-ship.test.ts index e289945b..a088db48 100644 --- a/sdk/test/log-ship.test.ts +++ b/sdk/test/log-ship.test.ts @@ -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((r) => { + release = r; + }); + let arrived: (() => void) | undefined; + const received = new Promise((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.