diff --git a/docs/activity-trace.md b/docs/activity-trace.md index de01fc2f..b626071d 100644 --- a/docs/activity-trace.md +++ b/docs/activity-trace.md @@ -257,6 +257,39 @@ buffers, so a slow disk delays the trace instead of blocking the main thread — the trade is that the last few lines may be lost on a hard crash. A clean quit flushes and closes (`app.quit` is the last line). +## Testing the async prune path + +`rotate()` runs `openSegment()` synchronously but hands the retired stream's +cleanup (`pruneSegments`) to its `end()` callback, because Windows refuses to +unlink a handle that is still open — the callback only fires once the OS has +actually closed the file. Under `node --test`'s default concurrency (one +process per test file, dozens running at once), that callback can take far +longer than it does in isolation: CPU and disk contention from the sibling +processes delays the event loop turn it needs. + +Two tests in `test/activity-trace.test.js` used to bridge that async gap with +a fixed `setTimeout(60)`. That is a duration bet, not a correctness check, and +it hides a real ordering hazard rather than just being slow: `close()` sets +`stream = null` synchronously. If a `pruneSegments` callback from an earlier +rotation is still queued when `close()` runs, it later calls `trace()` to +record the `trace.prune-failed` warning, finds `stream` already null, and +`trace()`'s own `if (!stream && !write) return;` guard drops the line with no +error — a silent no-op, not a crash. On a quiet machine 60 ms is enough for +the callback to run before `close()` is reached; under the full suite's +parallel load it sometimes is not, and the warning that the test asserts on +never gets written. This is a test-ordering bug, not a production one: at +real quit time losing one diagnostic warning about pruning (never the trace +data itself) is an acceptable trade, not a defect worth guarding against. + +All three of these tests now poll the actual condition (`waitUntil`, capped at +10 s) instead of sleeping a fixed duration — bounded by an outcome, not a +clock — and, in the prune-failure test, wait for the warning to land on disk +*before* calling `close()`, so the shutdown never races the pending callback. +The segment-count test above them flaked the same way once under full-suite +load even with a 1 s poll budget, purely from Windows filesystem-metadata +contention across dozens of concurrent `node --test` processes — not a logic +bug, just headroom that needed to be more generous. + ## Related - [Notifications](notifications.md) — what each indicator means to a user diff --git a/test/activity-trace.test.js b/test/activity-trace.test.js index 1e9a901f..94641953 100644 --- a/test/activity-trace.test.js +++ b/test/activity-trace.test.js @@ -222,6 +222,29 @@ test('an enabled trace that was never init()ed still writes nothing', () => { assert.equal(t.currentFile, null); }); +// Pruning runs on the retired stream's close callback — see docs/activity-trace.md +// "Testing the async prune path" for why these wait on the condition, not the clock. +async function waitUntil(check, { tries = 500, intervalMs = 20 } = {}) { + for (let i = 0; i < tries; i++) { + if (check()) return true; + await new Promise(r => setTimeout(r, intervalMs)); + } + return check(); +} + +function readEntries(files) { + const out = []; + for (const f of files) { + let content; + try { content = fs.readFileSync(f, 'utf8'); } catch { continue; } + for (const line of content.split('\n')) { + if (!line) continue; + try { out.push(JSON.parse(line)); } catch { /* mid-flush line, next poll picks it up */ } + } + } + return out; +} + // --- bounding: rotation with a fixed number of retained segments ----------- test('the trace rotates segments and retains a bounded number of them', async () => { @@ -232,22 +255,16 @@ test('the trace rotates segments and retains a bounded number of them', async () assert.ok(t.files.length > 2, 'the run produced more segments than it retains'); t.close(); - // Pruning runs on the retired stream's close callback. let files = []; - for (let i = 0; i < 100; i++) { + await waitUntil(() => { files = fs.readdirSync(dir).filter(f => f.endsWith('.jsonl')); - if (files.length <= 2) break; - await new Promise(r => setTimeout(r, 10)); - } + return files.length <= 2; + }); assert.equal(files.length, 2, 'older segments are unlinked, disk use stays bounded'); assert.ok(files.every(f => f.startsWith('activity-trace-'))); fs.rmSync(dir, { recursive: true, force: true }); }); -// Pruning runs on the retired stream's close callback, so it always lags a -// synchronous burst of writes by at least a tick. -const settle = () => new Promise(r => setTimeout(r, 60)); - test('a segment that cannot be unlinked stays queued and is retried, not forgotten', async () => { const dir = fs.mkdtempSync(path.join(os.tmpdir(), 'sb-trace-lock-')); let locked = true; @@ -263,7 +280,7 @@ test('a segment that cannot be unlinked stays queued and is retried, not forgott }); t.init(dir); for (let i = 0; i < 60; i++) t.trace('fill', 's1', { i, pad: 'xxxxxxxxxxxxxxxxxxxx' }); - await settle(); + await waitUntil(() => attempts.length > 1); const stale = t.files[0]; assert.ok(attempts.length > 1, 'the locked segment is retried at each rotation'); @@ -272,7 +289,7 @@ test('a segment that cannot be unlinked stays queued and is retried, not forgott locked = false; for (let i = 0; i < 40; i++) t.trace('fill', 's1', { i, pad: 'xxxxxxxxxxxxxxxxxxxx' }); - await settle(); + await waitUntil(() => t.files.length === 2); assert.equal(t.files.length, 2, 'the backlog drains back to the ceiling once the lock clears'); assert.equal(t.files.includes(stale), false); t.close(); @@ -287,15 +304,16 @@ test('a failed prune is reported in the trace itself, once per file', async () = }); t.init(dir); for (let i = 0; i < 60; i++) t.trace('fill', 's1', { i, pad: 'xxxxxxxxxxxxxxxxxxxx' }); - await settle(); const files = t.files.slice(); + + // Order matters here — see docs/activity-trace.md "Testing the async prune path". + let warnings = []; + await waitUntil(() => { + warnings = readEntries(files).filter(e => e.cat === 'trace.prune-failed'); + return warnings.length >= 1; + }); t.close(); - await settle(); - const rows = files - .flatMap(f => fs.readFileSync(f, 'utf8').split('\n')) - .filter(Boolean).map(l => JSON.parse(l)); - const warnings = rows.filter(e => e.cat === 'trace.prune-failed'); assert.ok(warnings.length >= 1, 'exceeding the announced ceiling is not silent'); assert.equal(warnings[0].error, 'EBUSY'); assert.equal(new Set(warnings.map(w => w.file)).size, warnings.length,