diff --git a/specs/014-full-observability/checklists/requirements.md b/specs/014-full-observability/checklists/requirements.md index 3f820d9..7bc665f 100644 --- a/specs/014-full-observability/checklists/requirements.md +++ b/specs/014-full-observability/checklists/requirements.md @@ -41,3 +41,60 @@ untracked today were confirmed by direct code inspection before writing this spec, not assumed. - All items pass; no revision iterations were needed. No [NEEDS CLARIFICATION] markers were required — every open question had a reasonable, documented default (see Assumptions). + +## Implementation Notes (post-build) + +- Registering a real `TracerProvider` alone was not sufficient to make span nesting work across + this feature's own async event-bus subscribers: without also registering an + `AsyncLocalStorageContextManager` (`@opentelemetry/context-async-hooks`, a third new + dependency beyond the two research.md originally named), the OpenTelemetry API's + `context.active()` is a no-op that does not propagate across `await` boundaries at all — + `orchestration.assignment` came out as its own unrelated root span/trace instead of nesting + under `ai.escalation`. Caught by the tracing integration test's own parent/child assertions + actually failing on the first implementation, not assumed correct from reading the SDK's docs. +- Installing `@opentelemetry/exporter-trace-otlp-http` alongside the already-pinned + `@opentelemetry/sdk-trace-base@^1.22.0` pulled two incompatible OpenTelemetry core/resources + major versions (1.x and 2.x) side by side. Resolved by bumping `sdk-trace-base` to `^2.11.0` to + match — this also happened to close a moderate DoS advisory in `@opentelemetry/core <2.8.0` + that the 1.x line was pinned to. +- T016 (graceful degradation under an unreachable OTLP endpoint) ended up as its own unit test + (`tests/unit/observability/tracing-graceful-degradation.test.ts`) rather than living in + `tracing.test.ts` as tasks.md originally described. Reason: `tracing.ts` always uses the + in-memory test exporter when `NODE_ENV=test`, so the integration suite's own running app can't + be pointed at a bad OTLP endpoint to exercise this. The unit test instead constructs a real + `BasicTracerProvider`/`BatchSpanProcessor`/`OTLPTraceExporter` pointed at a genuinely + unreachable address directly, and — importantly — verifies the SDK's _background_ export path + (what production actually exercises) never produces an unhandled rejection, rather than calling + `forceFlush()` directly, which is documented OpenTelemetry behavior that _does_ reject on a + failed export by design (the first version of this test asserted the wrong thing and failed + against real, correct SDK behavior — not a bug in this feature's own code). +- `sla.service.ts`'s pre-existing status-overwrite gap (a `'breached'` run's status silently + becomes `'completed'` if the ticket later resolves — see research.md §5) was worked around for + the metric's own correctness (read `run.status` before the overwrite) but left unfixed in the + underlying data, consistent with how 013-auth-hardening documented a pre-existing bug it found + without fixing it. +- Found and fixed one genuine cross-file test-isolation bug this feature's own new test caused: + `business-metrics.test.ts`'s "human resolution" case originally drove a ticket through a real + `HUMAN_ESCALATION` transition via `ticketsService.updateStatus`, which — same as any other + escalation in this codebase — triggers the real orchestration subscriber's default + `ROUND_ROBIN` auto-assignment against every agent in the shared throwaway database, including + other concurrently-running test files' own dedicated agents (reproduced deterministically + against `agent-ticket-queue.test.ts`). Fixed by driving the intermediate state-machine + transitions directly through `ticketsRepository.updateStatus` (no domain-event publish) + instead, reserving the real, event-publishing `ticketsService.updateStatus` call for only the + final `RESOLVED` transition the metric subscriber actually needs to observe. +- Separately, found (not caused by this feature — confirmed via `git checkout` to the clean + pre-014 commit and reproducing the identical failure) a pre-existing systemic collision risk in + ticket-code generation: `ticket-code.ts`'s `deriveProductCode` keeps only the first 4 + alphabetic characters of `externalProductId`, so essentially every integration test file in + this codebase (nearly all of which name their test products `TEST_`) collapses to + the identical `"TEST"` code prefix. Running enough `TEST_*`-prefixed files concurrently (as + vitest does by default across worker threads/processes) makes independent files race for the + same `TEST--` numbering space, occasionally exceeding + `tickets.service.ts`'s fixed `MAX_CODE_RETRIES = 5` and surfacing as a real `500` + (`Unique constraint failed on the fields: (code)`) instead of the retry silently absorbing it. + Confirmed independent of this feature (reproduces on `79bc2ef`, 013-auth-hardening's tip, with + none of this feature's code present) and left unfixed here — a ticket-code-generation + concurrency fix belongs to 003-ticketing's own module, out of scope for an observability + feature. Worth a dedicated future fix (e.g. a longer/hash-based product code, or a + database-level sequence rather than a `COUNT`-then-retry scheme). diff --git a/specs/014-full-observability/tasks.md b/specs/014-full-observability/tasks.md index 0146e06..12086a2 100644 --- a/specs/014-full-observability/tasks.md +++ b/specs/014-full-observability/tasks.md @@ -1,5 +1,5 @@ --- -description: "Task list for 014-full-observability" +description: 'Task list for 014-full-observability' --- # Tasks: Full Observability @@ -23,12 +23,12 @@ All file paths are relative to `supporthub-api/` (repo root). ## Phase 1: Foundational (Blocking Prerequisites) -- [ ] T001 Add `@opentelemetry/exporter-trace-otlp-http` and `@opentelemetry/resources` to +- [x] T001 Add `@opentelemetry/exporter-trace-otlp-http` and `@opentelemetry/resources` to `package.json` (`npm install`) -- [ ] T002 Add `src/infrastructure/observability/request-context.store.ts` — a module-level +- [x] T002 Add `src/infrastructure/observability/request-context.store.ts` — a module-level `AsyncLocalStorage<{requestId: string; correlationId: string}>` with a `run()` passthrough and a `getStore()` re-export -- [ ] T003 [P] Wire `logger.ts`'s Pino options with a `mixin` function reading from T002's store +- [x] T003 [P] Wire `logger.ts`'s Pino options with a `mixin` function reading from T002's store (returns `{}` when no store is active — a log call outside any request, e.g. at startup, must not throw) (depends on T002) @@ -47,22 +47,22 @@ request's handling shares its request ID. ### Tests for User Story 1 -- [ ] T004 [P] [US1] Unit test: a `logger.info(...)` call made inside T002's `store.run(...)` +- [x] T004 [P] [US1] Unit test: a `logger.info(...)` call made inside T002's `store.run(...)` carries `requestId`/`correlationId` in its output; one made outside carries neither, in `tests/unit/observability/request-context-mixin.test.ts` (depends on T003) ### Implementation for User Story 1 -- [ ] T005 [US1] In `plugins/request-context.plugin.ts`'s existing `onRequest` hook, after +- [x] T005 [US1] In `plugins/request-context.plugin.ts`'s existing `onRequest` hook, after building `request.reqContext`, call the T002 store's `run()` wrapping the remainder of the request's handling (Fastify's `onRequest` hooks accept a `done` callback / return a promise — the run wraps whichever style this hook currently uses) so every subsequent hook/handler for this request executes inside the ALS context (depends on T002) -- [ ] T006 [US1] Add an `onResponse` hook (same plugin) that logs one line via the shared +- [x] T006 [US1] Add an `onResponse` hook (same plugin) that logs one line via the shared `logger`: `{event: "http_request_completed", method, route: request.routeOptions.url, - statusCode: reply.statusCode, durationMs: reply.elapsedTime}`, at `info`/`warn`/`error` + statusCode: reply.statusCode, durationMs: reply.elapsedTime}`, at `info`/`warn`/`error` level by status class (depends on T005) -- [ ] T007 [US1] Integration test covering Quickstart Scenario 1 (one access-log line per +- [x] T007 [US1] Integration test covering Quickstart Scenario 1 (one access-log line per request incl. 404; shared requestId across the access-log line and an internal log line from the same request) in `tests/integration/observability/access-log.test.ts`, using a `logger.info`/`logger.warn` spy the same way `password-reset-flow.test.ts` (013) already @@ -82,10 +82,10 @@ error rate per route/status is computable from `/metrics` alone. ### Implementation for User Story 2 -- [ ] T008 [US2] In the same `onResponse` hook added by T006, call +- [x] T008 [US2] In the same `onResponse` hook added by T006, call `httpRequestDurationHistogram.observe({method, route: request.routeOptions.url, status_code: - String(reply.statusCode)}, reply.elapsedTime / 1000)` (depends on T006) -- [ ] T009 [US2] Integration test covering Quickstart Scenario 2 (send a mix of successful/ + String(reply.statusCode)}, reply.elapsedTime / 1000)` (depends on T006) +- [x] T009 [US2] Integration test covering Quickstart Scenario 2 (send a mix of successful/ failing requests to the same route, scrape `/metrics`, assert both status-code label values are present with the expected counts) in `tests/integration/observability/request-metrics.test.ts` (depends on T008) @@ -103,7 +103,7 @@ exported; two named cross-module paths are instrumented. ### Implementation for User Story 3 -- [ ] T010 [P] [US3] Rewrite `infrastructure/observability/tracing.ts` to initialize a +- [x] T010 [P] [US3] Rewrite `infrastructure/observability/tracing.ts` to initialize a `BasicTracerProvider` at module load with a `Resource` (`service.name: "supporthub-api"`) and register it via `trace.setGlobalTracerProvider(...)`; exporter/processor chosen by `NODE_ENV`/`OTEL_EXPORTER_OTLP_ENDPOINT` per research.md §4 (`InMemorySpanExporter` + @@ -111,26 +111,26 @@ exported; two named cross-module paths are instrumented. is set, `ConsoleSpanExporter` + `SimpleSpanProcessor` otherwise); export a `getTestSpanExporter()` accessor (test env only) for T015 to read exported spans back; `getTracer()`'s own exported signature is unchanged (depends on T001) -- [ ] T011 [US3] Wire the OpenTelemetry SDK's internal diagnostic logger +- [x] T011 [US3] Wire the OpenTelemetry SDK's internal diagnostic logger (`diag.setLogger(...)`) to the shared `logger.warn`, so span-export failures land in this project's own log stream instead of stderr or nowhere (depends on T010) -- [ ] T012 [P] [US3] Add a `ticket.create` span (`getTracer().startActiveSpan(...)`) around +- [x] T012 [P] [US3] Add a `ticket.create` span (`getTracer().startActiveSpan(...)`) around `tickets/service/tickets.service.ts`'s ticket-creation method, with `ticket.id` and `product.externalProductId` attributes, ended in a `finally` (depends on T010) -- [ ] T013 [P] [US3] Add an `ai.escalation` span around `ai-support/sessions/service/ - session.service.ts`'s escalation branch(es), with `ticket.id`/`session.id` attributes +- [x] T013 [P] [US3] Add an `ai.escalation` span around `ai-support/sessions/service/ + session.service.ts`'s escalation branch(es), with `ticket.id`/`session.id` attributes (depends on T010) -- [ ] T014 [US3] Add an `orchestration.assignment` span wrapping the existing +- [x] T014 [US3] Add an `orchestration.assignment` span wrapping the existing `orchestrationService.handleHumanEscalation` call in the `TICKET_UPDATED`/ `HUMAN_ESCALATION` subscriber (`src/events/handlers/index.ts`), with `ticket.id`/ `strategy` attributes, so it nests under T013's span when both occur in the same request (depends on T010, T013) -- [ ] T015 [US3] Integration test covering Quickstart Scenario 3 steps 1-2: drive a real +- [x] T015 [US3] Integration test covering Quickstart Scenario 3 steps 1-2: drive a real ticket-creation → escalation → orchestration/assignment flow, read spans back via T010's `getTestSpanExporter()`, assert `ticket.create`/`ai.escalation`/`orchestration.assignment` all share one trace ID with correct parent/child `spanId` relationships, in `tests/integration/observability/tracing.test.ts` (depends on T012, T013, T014) -- [ ] T016 [US3] Integration test covering Quickstart Scenario 3 steps 3-4: point +- [x] T016 [US3] Integration test covering Quickstart Scenario 3 steps 3-4: point `OTEL_EXPORTER_OTLP_ENDPOINT` at an unreachable address, confirm `buildApp()` still resolves and a request still completes successfully, in the same test file (depends on T010) @@ -149,44 +149,44 @@ exact real event research.md identified. ### Implementation for User Story 4 -- [ ] T017 [US4] Define all eleven new `Counter`/`Histogram` objects in +- [x] T017 [US4] Define all eleven new `Counter`/`Histogram` objects in `infrastructure/observability/metrics.ts` per data-model.md's table, exported individually (depends on T001) -- [ ] T018 [P] [US4] Increment `supporthub_ai_session_outcomes_total` in `ai-support/sessions/ - repository/session.repository.ts`'s `updateStatus`, labeled `outcome` when `status` is +- [x] T018 [P] [US4] Increment `supporthub_ai_session_outcomes_total` in `ai-support/sessions/ + repository/session.repository.ts`'s `updateStatus`, labeled `outcome` when `status` is `'resolved'`/`'escalated'` (depends on T017) -- [ ] T019 [P] [US4] Add a `TICKET_UPDATED`/`newStatus === 'RESOLVED'` subscriber in +- [x] T019 [P] [US4] Add a `TICKET_UPDATED`/`newStatus === 'RESOLVED'` subscriber in `src/events/handlers/index.ts` that looks up `resolutionRepository.findByTicketId`, increments `supporthub_ticket_resolutions_total{resolved_by}` (`ai` vs. any other value), fetches the ticket for `createdAt`, and observes `supporthub_ticket_resolution_duration_seconds` (depends on T017) -- [ ] T020 [P] [US4] In `ticketing/messages/service/messages.service.ts`'s `post`, when +- [x] T020 [P] [US4] In `ticketing/messages/service/messages.service.ts`'s `post`, when `type === 'AGENT_MESSAGE'`, check for a prior `AGENT_MESSAGE` on the ticket and — only for the first one — observe `supporthub_ticket_first_response_duration_seconds` against the ticket's `createdAt` (depends on T017) -- [ ] T021 [P] [US4] In `orchestration/sla/service/sla.service.ts`: in `complete()`, read +- [x] T021 [P] [US4] In `orchestration/sla/service/sla.service.ts`: in `complete()`, read `run.status` before updating and increment `supporthub_sla_run_outcomes_total{outcome: - "met"}` only if it was not already `'breached'`; in `runBreachDetectionSweep()`, increment + "met"}` only if it was not already `'breached'`; in `runBreachDetectionSweep()`, increment `{outcome: "breached"}` for each newly-flagged run (depends on T017) -- [ ] T022 [P] [US4] Add an `ESCALATION_TRIGGERED` subscriber in `src/events/handlers/index.ts` +- [x] T022 [P] [US4] Add an `ESCALATION_TRIGGERED` subscriber in `src/events/handlers/index.ts` that increments `supporthub_escalations_total{reason}` from the event payload's `reason` (depends on T017) -- [ ] T023 [P] [US4] In `ticketing/tickets/service/tickets.service.ts`'s ticket-creation method, +- [x] T023 [P] [US4] In `ticketing/tickets/service/tickets.service.ts`'s ticket-creation method, increment `supporthub_problems_created_total{category_id}` right after `problemsRepo.create` succeeds (`categoryId ?? 'uncategorized'`) (depends on T017) -- [ ] T024 [P] [US4] In `ai-support/knowledge/service/error-codes.service.ts`'s +- [x] T024 [P] [US4] In `ai-support/knowledge/service/error-codes.service.ts`'s `findKnownIssuesByErrorCode`, increment `supporthub_known_error_lookups_total{code}` once the error code is confirmed to exist (after the `NotFoundError` branch, not before) (depends on T017) -- [ ] T025 [P] [US4] In `ai-support/tools/service/tools.service.ts`'s single `executeTool(...)` +- [x] T025 [P] [US4] In `ai-support/tools/service/tools.service.ts`'s single `executeTool(...)` call site: increment `supporthub_tool_invocations_total{tool, outcome}` for every call, and — only when `block.name === 'searchProductKnowledge'` — increment `supporthub_knowledge_retrieval_outcomes_total{matched}` from whether `result.output` is a non-empty array (depends on T017) -- [ ] T026 [US4] Unit test: `sla.service.ts`'s `complete()` does not increment the `met` outcome +- [x] T026 [US4] Unit test: `sla.service.ts`'s `complete()` does not increment the `met` outcome for a run already `'breached'` (a fake repo returning `status: 'breached'`) in `tests/unit/observability/sla-compliance-metric.test.ts` (depends on T021) -- [ ] T027 [US4] Integration test covering Quickstart Scenario 4 (all ten sub-scenarios — the +- [x] T027 [US4] Integration test covering Quickstart Scenario 4 (all ten sub-scenarios — the eleventh, tool-failure, is covered by the same test file's tool-invocation case) — scrape `/metrics` before/after driving each real event through the real API, in `tests/integration/observability/business-metrics.test.ts` (depends on T018, T019, T020, @@ -199,11 +199,11 @@ against real infrastructure. ## Phase 6: Polish & Cross-Cutting Concerns -- [ ] T028 [P] Update `specs/014-full-observability/checklists/requirements.md` Notes with any +- [x] T028 [P] Update `specs/014-full-observability/checklists/requirements.md` Notes with any implementation-time findings (including the pre-existing SLA-run status data-quality gap research.md §5 already surfaced) -- [ ] T029 Run `npx tsx scripts/check-architecture.ts` and `npm run lint`/`npm run typecheck` -- [ ] T030 Full regression: `npm run test:unit` then the full integration suite against real +- [x] T029 Run `npx tsx scripts/check-architecture.ts` and `npm run lint`/`npm run typecheck` +- [x] T030 Full regression: `npm run test:unit` then the full integration suite against real Docker-provisioned Postgres/Redis, confirming nothing outside this feature regressed (particularly every module touched by a single-line instrumentation addition: ai-support sessions/knowledge/tools, ticketing tickets/messages, orchestration/sla, and the event-bus diff --git a/tests/integration/observability/business-metrics.test.ts b/tests/integration/observability/business-metrics.test.ts index 5f48b15..38e35f6 100644 --- a/tests/integration/observability/business-metrics.test.ts +++ b/tests/integration/observability/business-metrics.test.ts @@ -9,7 +9,7 @@ import { issueIntegrationToken, } from '@/modules/catalog/products'; import { sessionsService, sessionRepository } from '@/modules/ai-support/sessions'; -import { ticketsService } from '@/modules/ticketing/tickets'; +import { ticketsService, ticketsRepository } from '@/modules/ticketing/tickets'; import { messagesService } from '@/modules/ticketing/messages'; import { resolutionRepository } from '@/modules/problem-management/resolutions'; import { slaService, slaRunRepository } from '@/modules/orchestration/sla'; @@ -150,32 +150,19 @@ describe('Business-health metrics (User Story 4)', () => { it('counts a human resolution and observes resolution duration when a ticket reaches RESOLVED', async () => { const ticketId = await createTicket(); - // Drive the state machine directly (NEW -> HUMAN_ESCALATION -> [maybe already - // auto-assigned to IN_PROGRESS by orchestration] -> RESOLUTION_PENDING_CUSTOMER -> - // RESOLVED) — the metric subscriber only cares about the final RESOLVED transition and the - // Resolution row's own resolvedBy, not how the ticket got to RESOLUTION_PENDING_CUSTOMER. + // Reach RESOLUTION_PENDING_CUSTOMER via the repository directly (bypassing + // ticketsService.updateStatus's domain-event publish) — this test only cares about the + // final RESOLVED transition and the Resolution row's own resolvedBy, not the intermediate + // states, and going through the real event bus here would trigger a REAL, unscoped + // HUMAN_ESCALATION auto-assignment against the default strategy — which can land on some + // other concurrently-running test file's own dedicated agent (a real cross-file + // contamination this test caused once, fixed here by not publishing those events at all). let ticket = await prismaClient.ticket.findUniqueOrThrow({ where: { id: ticketId } }); - ticket = await ticketsService.updateStatus( - ticketId, - 'HUMAN_ESCALATION', - ticket.version, - 'agent-1', - ); - ticket = await prismaClient.ticket.findUniqueOrThrow({ where: { id: ticketId } }); - if (ticket.status !== 'IN_PROGRESS') { - ticket = await ticketsService.updateStatus( - ticketId, - 'IN_PROGRESS', - ticket.version, - 'agent-1', - ); + for (const status of ['HUMAN_ESCALATION', 'IN_PROGRESS', 'RESOLUTION_PENDING_CUSTOMER']) { + const updated = await ticketsRepository.updateStatus(ticketId, status, ticket.version); + if (!updated) throw new Error(`Failed to transition ticket to ${status} in test setup.`); + ticket = updated; } - ticket = await ticketsService.updateStatus( - ticketId, - 'RESOLUTION_PENDING_CUSTOMER', - ticket.version, - 'agent-1', - ); await resolutionRepository.create({ ticketId, outcome: 'fixed', resolvedBy: 'agent-1' }); const bodyBefore = await scrape();