diff --git a/src/arts/http/consts.ts b/src/arts/http/consts.ts index 3b759d3..0dacdb3 100644 --- a/src/arts/http/consts.ts +++ b/src/arts/http/consts.ts @@ -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; diff --git a/src/arts/http/diagnostics.ts b/src/arts/http/diagnostics.ts index 2712838..fb6e689 100644 --- a/src/arts/http/diagnostics.ts +++ b/src/arts/http/diagnostics.ts @@ -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; @@ -61,6 +73,10 @@ const HTTP_DIAGNOSTIC_LOGS: DiagnosticCatalog = { 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)) diff --git a/src/arts/http/engine-http.ts b/src/arts/http/engine-http.ts index 5506af6..6351f9c 100644 --- a/src/arts/http/engine-http.ts +++ b/src/arts/http/engine-http.ts @@ -142,6 +142,7 @@ async function execute( ); 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( contentType, signal }); + const attemptDurationMs = port.now() - attemptStartedAt; const ctx = attemptResult.ctx; lastCtx = ctx; response = attemptResult.response; @@ -165,6 +167,16 @@ async function execute( // 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( }); 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; } diff --git a/src/arts/http/test/engine-http.test.ts b/src/arts/http/test/engine-http.test.ts index 5b31fc5..8ad9075 100644 --- a/src/arts/http/test/engine-http.test.ts +++ b/src/arts/http/test/engine-http.test.ts @@ -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 () => {