Skip to content

Commit 20670ef

Browse files
nbouliolclaude
andcommitted
fix(agent-bff): flush spans from the shutdown path, not from a signal handler
Two problems with the flush being its own SIGTERM listener, both raised in review. It armed at --require time, before the CLI arms its shutdown handler. A signal in that window was consumed by a listener that terminates nothing, so the process ran on until SIGKILL — the same PID 1 trap as before, one layer up. And it was detached, so the exit could cut an export still in flight. The preload now parks the SDK on a shared handle and arms nothing; armShutdown flushes through it and waits, so the exit cannot race the export. The flush gets its own 2s deadline rather than the 10s in-flight requests get: telemetry is not worth holding a shutdown past an orchestrator's patience. Worst case a dead collector adds ~3s. Verified: exit 0 either way. Co-Authored-By: Claude Opus 5 (1M context) <noreply@anthropic.com>
1 parent 3f6a321 commit 20670ef

10 files changed

Lines changed: 246 additions & 126 deletions

File tree

packages/agent-bff/README.md

Lines changed: 4 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -84,8 +84,10 @@ The Docker image ships with [OpenTelemetry](https://opentelemetry.io/) APM built
8484
any OTLP-compatible backend (Datadog, Grafana Tempo, Jaeger, Honeycomb, etc.). It is **off by
8585
default** and turns on as soon as you point it at an OTLP receiver — no code changes or extra
8686
installs required. Tracing is set up before the app starts (auto-instrumentation for HTTP and the
87-
outbound calls to the agent and the Forest SaaS), and buffered spans are flushed on `SIGTERM` /
88-
`SIGINT`, alongside the graceful shutdown described above.
87+
outbound calls to the agent and the Forest SaaS). The graceful shutdown described above waits for
88+
the buffered spans to be exported before it exits, but gives that its own 2 second deadline rather
89+
than the 10 seconds in-flight requests get: an unreachable collector costs you the last spans, never
90+
the ability to stop. Worst case it adds ~3 seconds to a shutdown.
8991

9092
Configure it entirely through the standard OTel environment variables:
9193

packages/agent-bff/src/cli.ts

Lines changed: 5 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -4,13 +4,17 @@ import createConsoleLogger from './adapters/console-logger';
44
import { reportFatalError } from './cli-core';
55
import dispatchCli from './cli-dispatch';
66
import armShutdown from './shutdown';
7+
import { flushTracing } from './tracing-handle';
78

89
if (require.main === module) {
910
dispatchCli(process.argv.slice(2), process.env)
1011
.then(({ exitCode, server }) => {
1112
// Only the server command has anything to shut down; `openapi` and the flags
1213
// have already finished by the time they return.
13-
if (server) armShutdown({ server, logger: createConsoleLogger() });
14+
// flushTracing is a no-op unless the image's tracing preload armed an SDK. Wiring it here,
15+
// rather than letting the preload arm its own signal handler, is what makes the exit wait
16+
// for the export instead of racing it.
17+
if (server) armShutdown({ server, logger: createConsoleLogger(), flush: flushTracing });
1418
if (exitCode !== 0) process.exitCode = exitCode;
1519
})
1620
.catch(reportFatalError);

packages/agent-bff/src/shutdown.ts

Lines changed: 35 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,19 @@ export interface ShutdownOptions {
1010
logger?: Logger;
1111
/** How long in-flight requests get before their sockets are cut. */
1212
graceMs?: number;
13+
/**
14+
* Anything that must reach its destination before the process ends — today the buffered
15+
* OpenTelemetry spans. It runs alongside `server.stop()` and is awaited with it, so the exit
16+
* cannot cut an export that is still in flight.
17+
*/
18+
flush?: () => Promise<void>;
19+
/**
20+
* The flush's own, much shorter deadline. It deliberately does not share `graceMs`: finishing a
21+
* request someone is waiting on is worth ten seconds, telemetry is not, and an unreachable
22+
* collector that held the process for the full grace period would be SIGKILLed by an orchestrator
23+
* whose own patience starts at the same ten seconds — losing the shutdown, not just the spans.
24+
*/
25+
flushMs?: number;
1326
/** Signal registration, as a seam: a test must not arm a handler on the real process. */
1427
onSignal?: (signal: NodeJS.Signals, handler: () => void) => void;
1528
exit?: (code: number) => void;
@@ -18,6 +31,7 @@ export interface ShutdownOptions {
1831
export const SIGNALS: NodeJS.Signals[] = ['SIGTERM', 'SIGINT'];
1932
export const DEFAULT_GRACE_MS = 10_000;
2033
export const FORCE_EXIT_MS = 1_000;
34+
export const DEFAULT_FLUSH_MS = 2_000;
2135

2236
/**
2337
* Ends the process without `process.exit`, which would discard whatever is still buffered on stdout
@@ -34,6 +48,24 @@ function defaultExit(code: number): void {
3448
setTimeout(() => process.exit(code), FORCE_EXIT_MS).unref();
3549
}
3650

51+
/**
52+
* Gives a promise a deadline, resolving either way — a slow collector should cost the shutdown its
53+
* last spans, not its ability to end. The timer is cleared on settle so it cannot hold the loop open
54+
* once the work is done.
55+
*/
56+
function bounded(work: Promise<void>, ms: number): Promise<void> {
57+
return new Promise(resolve => {
58+
const timer = setTimeout(resolve, ms);
59+
60+
void work
61+
.catch(() => undefined)
62+
.then(() => {
63+
clearTimeout(timer);
64+
resolve();
65+
});
66+
});
67+
}
68+
3769
/**
3870
* Stops the server on a termination signal, then exits.
3971
*
@@ -51,6 +83,8 @@ export default function armShutdown(options: ShutdownOptions): void {
5183
server,
5284
logger,
5385
graceMs = DEFAULT_GRACE_MS,
86+
flush,
87+
flushMs = DEFAULT_FLUSH_MS,
5488
onSignal = (signal, handler) => {
5589
process.on(signal, handler);
5690
},
@@ -75,8 +109,7 @@ export default function armShutdown(options: ShutdownOptions): void {
75109
stopping = true;
76110
logger?.('Info', 'Shutting down', { signal, graceMs });
77111

78-
server
79-
.stop(graceMs)
112+
Promise.all([server.stop(graceMs), flush ? bounded(flush(), flushMs) : undefined])
80113
.then(() => {
81114
if (interrupted) return;
82115

Lines changed: 38 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,38 @@
1+
/**
2+
* The one piece of state the preload and the CLI have to share.
3+
*
4+
* `--require` runs the preload in its own module, before `cli.js` is even loaded, so the SDK it
5+
* builds has nowhere to go but a module both sides resolve to the same instance. Keeping it here —
6+
* rather than having the preload arm a signal handler of its own — is what lets the shutdown path
7+
* WAIT for the flush instead of racing it, and keeps the preload from consuming a signal the CLI
8+
* has not armed a handler for yet.
9+
*
10+
* Nothing OpenTelemetry-specific is imported here, so the npm bin pays only for an empty variable.
11+
*/
12+
13+
export interface TracingHandle {
14+
shutdown(): Promise<void>;
15+
}
16+
17+
let handle: TracingHandle | undefined;
18+
19+
export function setTracingHandle(sdk: TracingHandle | undefined): void {
20+
handle = sdk;
21+
}
22+
23+
export function getTracingHandle(): TracingHandle | undefined {
24+
return handle;
25+
}
26+
27+
/**
28+
* Flushes buffered spans, or resolves immediately when tracing was never armed — the shutdown path
29+
* should not have to know which. A failing export is swallowed: a dead collector must not turn a
30+
* clean shutdown into a failed one.
31+
*/
32+
export async function flushTracing(): Promise<void> {
33+
try {
34+
await handle?.shutdown();
35+
} catch {
36+
/* istanbul ignore next — nothing to do about it, and it must not change the exit code. */
37+
}
38+
}
Lines changed: 6 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,10 @@
11
// The `--require` entry point of the Docker image (see the Dockerfile's ENTRYPOINT). Separate from
22
// `tracing.ts` on purpose: importing the setup must never arm an SDK, only calling it should.
3+
//
4+
// The SDK is handed to `tracing-handle` rather than wired to a signal here. The CLI arms the only
5+
// termination handler, and it flushes through that handle — so a signal arriving before the CLI is
6+
// up cannot be swallowed by a listener that does not terminate anything.
37
import initTracing from './tracing';
8+
import { setTracingHandle } from './tracing-handle';
49

5-
initTracing();
10+
setTracingHandle(initTracing());

packages/agent-bff/src/tracing.ts

Lines changed: 6 additions & 34 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,10 @@ import createConsoleLogger from './adapters/console-logger';
88
* apart is what lets this module be imported by a test without arming an SDK.
99
*
1010
* The SDK is initialised only when `OTEL_EXPORTER_OTLP_ENDPOINT` is set, so an install that never
11-
* opted into APM pays nothing. Ending the process is not this module's business — see `armFlush`.
11+
* opted into APM pays nothing. Neither ending the process nor flushing on the way out is this
12+
* module's business: it hands the SDK back, the preload parks it in `tracing-handle`, and the
13+
* shutdown path flushes through that. Arming a signal handler here would consume a signal the CLI
14+
* has not armed its own handler for yet, and nothing would then terminate the process.
1215
* All configuration goes through the standard OTel environment variables:
1316
*
1417
* OTEL_EXPORTER_OTLP_ENDPOINT OTLP receiver (e.g. http://localhost:4318)
@@ -23,7 +26,7 @@ import createConsoleLogger from './adapters/console-logger';
2326

2427
export const DEFAULT_SERVICE_NAME = 'forestadmin-agent-bff';
2528

26-
interface OtelSdk {
29+
export interface OtelSdk {
2730
start(): void;
2831
shutdown(): Promise<void>;
2932
}
@@ -39,8 +42,6 @@ export interface TracingOptions {
3942
logger?: Logger;
4043
/** The dynamic require, as a seam: the packages exist only in the Docker image. */
4144
load?: () => OtelModules | undefined;
42-
/** Signal registration, as a seam: a test must not arm a handler on the real process. */
43-
onSignal?: (signal: NodeJS.Signals, handler: () => void) => void;
4445
}
4546

4647
/** The packages this image installs for APM, and the export it takes from each. */
@@ -71,27 +72,6 @@ export function loadOtelModules(load: ModuleLoader = require): OtelModules | und
7172
}
7273
}
7374

74-
/**
75-
* Flushes buffered spans on the way out, alongside the shutdown `armShutdown` runs — this handler
76-
* does not end the process and must not try to. Ending it is `src/shutdown.ts`'s job: it closes the
77-
* server, bounds the wait for in-flight requests and exits explicitly, which is the only thing that
78-
* works when node is PID 1 (the kernel gives PID 1 no default disposition, so "let the default
79-
* action terminate" ends in a SIGKILL rather than a clean exit).
80-
*
81-
* So this only flushes. Once both the flush and that shutdown settle the loop empties and the
82-
* process exits on its own. A rejected flush is swallowed for the same reason: it must not become
83-
* an unhandled rejection that outlives the shutdown it is running beside.
84-
*/
85-
function armFlush(sdk: OtelSdk, onSignal: NonNullable<TracingOptions['onSignal']>): void {
86-
const signals: NodeJS.Signals[] = ['SIGTERM', 'SIGINT'];
87-
88-
for (const signal of signals) {
89-
onSignal(signal, () => {
90-
void sdk.shutdown().catch(() => undefined);
91-
});
92-
}
93-
}
94-
9575
/**
9676
* The OTel specification defines its boolean environment variables as case-insensitive, and this
9777
* one is the kill switch: reading `TRUE` as "not disabled" would leave tracing running for someone
@@ -102,14 +82,7 @@ function isDisabled(raw: string | undefined): boolean {
10282
}
10383

10484
export default function initTracing(options: TracingOptions = {}): OtelSdk | undefined {
105-
const {
106-
env = process.env,
107-
logger = createConsoleLogger(),
108-
load = loadOtelModules,
109-
onSignal = (signal, handler) => {
110-
process.once(signal, handler);
111-
},
112-
} = options;
85+
const { env = process.env, logger = createConsoleLogger(), load = loadOtelModules } = options;
11386

11487
const endpoint = env.OTEL_EXPORTER_OTLP_ENDPOINT?.trim();
11588

@@ -135,7 +108,6 @@ export default function initTracing(options: TracingOptions = {}): OtelSdk | und
135108
});
136109

137110
sdk.start();
138-
armFlush(sdk, onSignal);
139111

140112
logger('Info', 'OpenTelemetry tracing enabled', { serviceName, endpoint });
141113

packages/agent-bff/test/shutdown.test.ts

Lines changed: 62 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,7 @@ import type { Logger } from '../src/ports/logger-port';
22

33
import armShutdown, { DEFAULT_GRACE_MS, FORCE_EXIT_MS } from '../src/shutdown';
44

5-
const flush = () =>
5+
const settle = () =>
66
new Promise(resolve => {
77
setImmediate(resolve);
88
});
@@ -38,7 +38,7 @@ describe('armShutdown', () => {
3838
arm(500);
3939

4040
handlers.SIGTERM();
41-
await flush();
41+
await settle();
4242

4343
expect(stop).toHaveBeenCalledWith(500);
4444
expect(exit).toHaveBeenCalledWith(0);
@@ -48,7 +48,7 @@ describe('armShutdown', () => {
4848
arm();
4949

5050
handlers.SIGINT();
51-
await flush();
51+
await settle();
5252

5353
expect(stop).toHaveBeenCalledWith(DEFAULT_GRACE_MS);
5454
});
@@ -60,7 +60,7 @@ describe('armShutdown', () => {
6060
arm();
6161

6262
handlers.SIGTERM();
63-
await flush();
63+
await settle();
6464

6565
expect(exit).toHaveBeenCalledWith(1);
6666
expect(logger).toHaveBeenCalledWith('Error', 'Shutdown failed, exiting anyway', {
@@ -69,6 +69,61 @@ describe('armShutdown', () => {
6969
});
7070
});
7171

72+
describe('with a flush to run', () => {
73+
it('should run it alongside the stop and exit only once both settle', async () => {
74+
let releaseFlush: () => void = () => undefined;
75+
const flush = jest.fn(
76+
() =>
77+
new Promise<void>(resolve => {
78+
releaseFlush = resolve;
79+
}),
80+
);
81+
armShutdown({ server: { stop }, logger, onSignal, exit, flush, flushMs: 500 });
82+
83+
handlers.SIGTERM();
84+
await settle();
85+
86+
expect(flush).toHaveBeenCalledTimes(1);
87+
expect(exit).not.toHaveBeenCalled();
88+
89+
releaseFlush();
90+
await settle();
91+
92+
expect(exit).toHaveBeenCalledWith(0);
93+
});
94+
95+
// A collector that never answers must cost the shutdown its last spans, not its ability to end.
96+
// The deadline is the flush's own: telemetry does not get the grace period in-flight requests do.
97+
it('should give up on the flush once its own deadline elapses', async () => {
98+
jest.useFakeTimers();
99+
const flush = jest.fn(
100+
() =>
101+
new Promise<void>(() => {
102+
/* never settles */
103+
}),
104+
);
105+
armShutdown({ server: { stop }, logger, onSignal, exit, flush, flushMs: 500 });
106+
107+
handlers.SIGTERM();
108+
await Promise.resolve();
109+
jest.advanceTimersByTime(500);
110+
jest.useRealTimers();
111+
await settle();
112+
113+
expect(exit).toHaveBeenCalledWith(0);
114+
});
115+
116+
it('should not let a failing flush change the exit code', async () => {
117+
const flush = jest.fn().mockRejectedValue(new Error('collector down'));
118+
armShutdown({ server: { stop }, logger, onSignal, exit, flush });
119+
120+
handlers.SIGTERM();
121+
await settle();
122+
123+
expect(exit).toHaveBeenCalledWith(0);
124+
});
125+
});
126+
72127
describe('on a second signal', () => {
73128
it('should exit 1 instead of stopping the server again', async () => {
74129
let release: () => void = () => undefined;
@@ -86,7 +141,7 @@ describe('armShutdown', () => {
86141
expect(exit).toHaveBeenCalledWith(1);
87142

88143
release();
89-
await flush();
144+
await settle();
90145
});
91146

92147
it('should not let the interrupted stop report success once it finishes', async () => {
@@ -101,7 +156,7 @@ describe('armShutdown', () => {
101156
handlers.SIGTERM();
102157
handlers.SIGINT();
103158
release();
104-
await flush();
159+
await settle();
105160

106161
expect(exit).toHaveBeenCalledTimes(1);
107162
expect(exit).toHaveBeenCalledWith(1);
@@ -120,7 +175,7 @@ describe('armShutdown', () => {
120175
handlers.SIGTERM();
121176
handlers.SIGINT();
122177
fail(new Error('close failed'));
123-
await flush();
178+
await settle();
124179

125180
expect(exit).toHaveBeenCalledTimes(1);
126181
expect(logger).not.toHaveBeenCalledWith(

0 commit comments

Comments
 (0)