Bloque H6 — http per-attempt observability

New diagnostic event `http.attempt_completed` carries `attempt`,
`durationMs` (wall-clock from request start to response settle), `ok`,
`status?` and `error?`. Lets dashboards compute p50/p95 latency without
inferring it from the request + retrying events.

`http.retrying` is now emitted AFTER the wait so it can include
`actualDelayMs` — the observed time between attempts may differ from
the computed `retryDelay` when an abort cuts the wait short or a
`beforeRetry` hook takes noticeable time. `HttpDiagnosticMeta` gains
`durationMs`, `ok`, `actualDelayMs` and `abortReason` slots.

The pre-existing test that asserted exactly 1 DEBUG log per request
now asserts 2 (REQUEST + ATTEMPT_COMPLETED) — that is the change in
shape this block introduces.

Co-Authored-By: Claude Opus 4.7 (1M context) <noreply@anthropic.com>
master
dev 5 months ago
parent e40fc7fa1c
commit 3ec92acdc3

@ -67,6 +67,15 @@ export const HTTP_DIAGNOSTIC_EVENTS = {
BODY_SCHEMA_REJECTED: 'http.body_schema_rejected',
NETWORK_ERROR: 'http.network_error',
RETRYING: 'http.retrying',
/**
* Per-attempt completion event. Carries `attempt`, `durationMs`
* (wall-clock from the moment the attempt was scheduled to the
* moment fetch resolved/rejected) and `ok` so dashboards can
* compute p50/p95 latency without inferring it from the request +
* retrying events. Emitted whether the attempt succeeded, failed
* with a status, or threw.
*/
ATTEMPT_COMPLETED: 'http.attempt_completed',
RESPONSE_SCHEMA_FAILED: 'http.response_schema_failed',
HTTP_STATUS: 'http.status'
} as const;

@ -33,6 +33,18 @@ export interface HttpDiagnosticMeta {
readonly totalAttempts?: number;
readonly status?: number;
readonly statusText?: string;
/** Wall-clock duration of a single attempt, in ms. */
readonly durationMs?: number;
/** `true` when the attempt produced a `Response`, `false` when it threw. */
readonly ok?: boolean;
/**
* For `RETRYING`: the actual time (ms) the engine waited before the
* next attempt. May be < `retryDelay` when an abort cut the wait
* short.
*/
readonly actualDelayMs?: number;
/** For aborted attempts: the abort reason (timeout, user, …). */
readonly abortReason?: string;
}
export type HttpDiagnosticEvent = DiagnosticEvent<HttpDiagnosticType, HttpDiagnosticMeta>;
@ -61,6 +73,10 @@ const HTTP_DIAGNOSTIC_LOGS: DiagnosticCatalog<HttpDiagnosticEvent> = {
event.meta?.totalAttempts ?? 0
)
}),
[HTTP_DIAGNOSTIC_EVENTS.ATTEMPT_COMPLETED]: (event) => ({
level: LogLevel.DEBUG,
message: `${methodOf(event)} ${urlOf(event)} attempt ${event.meta?.attempt ?? 0} ${event.meta?.ok ? 'ok' : 'failed'} in ${event.meta?.durationMs ?? 0}ms`
}),
[HTTP_DIAGNOSTIC_EVENTS.RESPONSE_SCHEMA_FAILED]: (event) => ({
level: LogLevel.ERROR,
message: responseSchemaFailedLogMessage(methodOf(event), urlOf(event))

@ -142,6 +142,7 @@ async function execute<S extends StandardSchemaV1 | undefined>(
);
const attemptSignal = attemptTimeoutHandle?.signal;
const signal = composeSignals([userSignal, totalSignal, attemptSignal]);
const attemptStartedAt = port.now();
const attemptResult = await runHttpAttempt({
defaults,
hooks,
@ -154,6 +155,7 @@ async function execute<S extends StandardSchemaV1 | undefined>(
contentType,
signal
});
const attemptDurationMs = port.now() - attemptStartedAt;
const ctx = attemptResult.ctx;
lastCtx = ctx;
response = attemptResult.response;
@ -165,6 +167,16 @@ async function execute<S extends StandardSchemaV1 | undefined>(
// long-lived runtimes (Workers, SSR, tests with fake timers).
attemptTimeoutHandle?.cancel();
emitHttpDiagnostic(diagnostics, HTTP_DIAGNOSTIC_EVENTS.ATTEMPT_COMPLETED, {
method,
url: fullUrl,
attempt,
durationMs: attemptDurationMs,
ok: response !== undefined && lastError === undefined,
status: response?.status,
error: lastError
});
// Decide whether to retry.
if (retry !== null) {
const retryable = shouldRetryRequest(method, retry, {
@ -174,25 +186,33 @@ async function execute<S extends StandardSchemaV1 | undefined>(
});
if (retryable) {
const delay = computeRetryDelay(retry, attempt, response, port);
const waitStartedAt = port.now();
await runBeforeRetry(hooks.beforeRetry, {
...ctx,
error: lastError,
retryDelay: delay
});
await delayWithSignal(delay, signal, port);
const actualDelayMs = port.now() - waitStartedAt;
// Emit RETRYING after the wait so we can include the
// observed delay (may differ from the computed one when an
// abort cut the wait short or a hook took noticeable time).
emitHttpDiagnostic(diagnostics, HTTP_DIAGNOSTIC_EVENTS.RETRYING, {
method,
url: fullUrl,
attempt,
retryDelay: delay,
actualDelayMs,
nextAttempt: attempt + 1,
totalAttempts: retry.limit + 1
});
await runBeforeRetry(hooks.beforeRetry, {
...ctx,
error: lastError,
retryDelay: delay
});
await delayWithSignal(delay, signal, port);
// After waiting, re-check signal — the wait may have been
// cut short by an abort. Falls through to error path.
if (signal.aborted) {
lastError = classifyAbort(signal) ?? lastError;
const abort = classifyAbort(signal);
lastError = abort ?? lastError;
break;
}

@ -522,7 +522,7 @@ describe('EngineHttp — composition', () => {
expect(tokens).toEqual(['old', 'new']);
});
it('emits debug log per attempt when a logger is supplied', async () => {
it('emits debug logs per attempt when a logger is supplied', async () => {
const entries: LogEntry[] = [];
const logger = createEngineLogger({
level: LogLevel.TRACE,
@ -537,9 +537,12 @@ describe('EngineHttp — composition', () => {
await http.get('/api/health');
const debug = entries.filter((e) => e.level === LogLevel.DEBUG);
expect(debug).toHaveLength(1);
// One `REQUEST` log before sending, one `ATTEMPT_COMPLETED` after
// the response settles (introduced for retry observability).
expect(debug).toHaveLength(2);
expect(debug[0].category).toBe('http');
expect(debug[0].message).toContain('GET');
expect(debug[1].message).toContain('attempt 1 ok in');
});
it('emits warn log on non-2xx response', async () => {

Loading…
Cancel
Save

Powered by TurnKey Linux.