feat(014-full-observability): real distributed tracing + first 5 business metrics

User Story 3: initializes a real OpenTelemetry TracerProvider (previously
inert — getTracer() returned a no-op tracer with nothing ever exported).
Adds ticket.create, ai.escalation, and orchestration.assignment spans
covering both FR-006 cross-module paths, verified via a real, in-memory
test exporter that confirms actual trace/parent-span nesting, not mocked.

Also registers an AsyncLocalStorageContextManager
(@opentelemetry/context-async-hooks) — without one, OTel's context API is
a no-op that doesn't propagate across the await boundaries this feature's
own event-bus subscribers rely on for span nesting; caught by the first
version of the tracing integration test actually failing on real
parent/child assertions, not assumed.

Graceful degradation (FR-007) verified against a real, deliberately
unreachable OTLP endpoint: the SDK's own background export path (what
production actually exercises) never produces an unhandled rejection.

Starts on the 11 named business-health metrics: AI session
resolved/escalated outcomes (session.repository.ts, the single choke
point every branch in session.service.ts funnels through), human-vs-AI
resolution + resolution-time (a new TICKET_UPDATED/RESOLVED subscriber),
escalation rate (a new subscriber on ESCALATION_TRIGGERED, published
unconditionally since 008 but never previously consumed), and recurring
problems (tickets.service.ts's existing problem-creation call site).

Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
This commit is contained in:
saqib mir
2026-09-08 11:32:14 +05:30
co-authored by Claude Sonnet 5
parent acd3843aaf
commit f75589d9ce
10 changed files with 452 additions and 14 deletions
+13
View File
@@ -17,6 +17,7 @@
"@fastify/swagger": "^8.14.0",
"@fastify/swagger-ui": "^3.0.0",
"@opentelemetry/api": "^1.8.0",
"@opentelemetry/context-async-hooks": "^2.11.0",
"@opentelemetry/exporter-trace-otlp-http": "^0.222.0",
"@opentelemetry/resources": "^2.11.0",
"@opentelemetry/sdk-trace-base": "^2.11.0",
@@ -1401,6 +1402,18 @@
"node": ">=8.0.0"
}
},
"node_modules/@opentelemetry/context-async-hooks": {
"version": "2.11.0",
"resolved": "https://registry.npmjs.org/@opentelemetry/context-async-hooks/-/context-async-hooks-2.11.0.tgz",
"integrity": "sha512-Tr79DyWI8itsBdg+jH+opjfrwLzX+erk1/ExkIwhWoAVjVrJIn2y5+cGjTC0Vy8fyNIA/y8wuJPZwr1T3xCZeQ==",
"license": "Apache-2.0",
"engines": {
"node": "^18.19.0 || >=20.6.0"
},
"peerDependencies": {
"@opentelemetry/api": ">=1.0.0 <1.10.0"
}
},
"node_modules/@opentelemetry/core": {
"version": "2.11.0",
"resolved": "https://registry.npmjs.org/@opentelemetry/core/-/core-2.11.0.tgz",
+1
View File
@@ -54,6 +54,7 @@
"@fastify/swagger": "^8.14.0",
"@fastify/swagger-ui": "^3.0.0",
"@opentelemetry/api": "^1.8.0",
"@opentelemetry/context-async-hooks": "^2.11.0",
"@opentelemetry/exporter-trace-otlp-http": "^0.222.0",
"@opentelemetry/resources": "^2.11.0",
"@opentelemetry/sdk-trace-base": "^2.11.0",
+65 -1
View File
@@ -1,9 +1,18 @@
import { SpanStatusCode } from '@opentelemetry/api';
import { eventBus } from '../event-bus';
import { DomainEventName } from '../domain-events';
import { BaseDomainEvent } from '../event-types';
import { sessionsService } from '@/modules/ai-support/sessions';
import { orchestrationService } from '@/modules/orchestration/orchestration';
import { slaService } from '@/modules/orchestration/sla';
import { ticketsService } from '@/modules/ticketing/tickets';
import { resolutionRepository } from '@/modules/problem-management/resolutions';
import {
getTracer,
ticketResolutionsCounter,
ticketResolutionDurationHistogram,
escalationsCounter,
} from '@/infrastructure/observability';
interface TicketUpdatedPayload {
ticketId: string;
@@ -19,6 +28,14 @@ interface TicketAssignedPayload {
actor: string;
}
interface EscalationTriggeredPayload {
ticketId: string;
ruleId: string;
targetNodeId: string;
actor: string;
reason: string;
}
let registered = false;
/**
@@ -50,7 +67,44 @@ export function registerDomainEventHandlers(): void {
DomainEventName.TICKET_UPDATED,
async (event: BaseDomainEvent<TicketUpdatedPayload>) => {
if (event.payload.newStatus !== 'HUMAN_ESCALATION') return;
await orchestrationService.handleHumanEscalation(event.payload.ticketId);
// 014-full-observability data-model.md: nests under session.service.ts's `ai.escalation`
// span when this fired from that same await chain (an escalation triggered some other way
// — e.g. a direct admin action — still gets its own root span here, never left untraced).
await getTracer().startActiveSpan(
'orchestration.assignment',
{ attributes: { 'ticket.id': event.payload.ticketId } },
async (span) => {
try {
await orchestrationService.handleHumanEscalation(event.payload.ticketId);
} catch (error) {
span.recordException(error as Error);
span.setStatus({ code: SpanStatusCode.ERROR });
throw error;
} finally {
span.end();
}
},
);
},
);
// 014-full-observability data-model.md #3/#4: human-vs-AI resolution and resolution-time,
// read off the Resolution row's own resolvedBy ("ai" | agentId — see prisma/schema.prisma)
// rather than duplicating that distinction here.
eventBus.subscribe(
DomainEventName.TICKET_UPDATED,
async (event: BaseDomainEvent<TicketUpdatedPayload>) => {
if (event.payload.newStatus !== 'RESOLVED') return;
const [ticket, resolution] = await Promise.all([
ticketsService.getById(event.payload.ticketId),
resolutionRepository.findByTicketId(event.payload.ticketId),
]);
if (!resolution) return;
ticketResolutionsCounter.inc({
resolved_by: resolution.resolvedBy === 'ai' ? 'ai' : 'human',
});
ticketResolutionDurationHistogram.observe((Date.now() - ticket.createdAt.getTime()) / 1000);
},
);
@@ -87,4 +141,14 @@ export function registerDomainEventHandlers(): void {
await slaService.complete(event.payload.ticketId);
},
);
// 014-full-observability data-model.md #7: ESCALATION_TRIGGERED has been published
// unconditionally on every escalation since 008-sla-escalation ("for audit, not for logic" —
// escalation.service.ts's own comment) but had zero subscribers until now.
eventBus.subscribe(
DomainEventName.ESCALATION_TRIGGERED,
async (event: BaseDomainEvent<EscalationTriggeredPayload>) => {
escalationsCounter.inc({ reason: event.payload.reason });
},
);
}
@@ -9,4 +9,70 @@ export const httpRequestDurationHistogram = new client.Histogram({
buckets: [0.01, 0.05, 0.1, 0.3, 0.5, 1, 3, 5],
});
// 014-full-observability data-model.md "Metrics (Prometheus, via prom-client)" — the eleven
// named business-health metrics docs/09-testing-observability-cicd.md calls for, each a raw
// counter/histogram for an external monitoring stack (FR-009 — no aggregation/dashboard logic
// here). "Recurring problems" and "most common errors" are deliberately read directly off
// problemsCreatedCounter/knownErrorLookupsCounter via a topk/rate query, not a separate metric.
export const aiSessionOutcomesCounter = new client.Counter({
name: 'supporthub_ai_session_outcomes_total',
help: 'Count of AI support sessions by terminal outcome',
labelNames: ['outcome'],
});
export const ticketResolutionsCounter = new client.Counter({
name: 'supporthub_ticket_resolutions_total',
help: 'Count of ticket resolutions by who resolved them',
labelNames: ['resolved_by'],
});
export const ticketResolutionDurationHistogram = new client.Histogram({
name: 'supporthub_ticket_resolution_duration_seconds',
help: 'Duration from ticket creation to resolution, in seconds',
buckets: [60, 300, 900, 3600, 14400, 86400, 259200, 604800],
});
export const ticketFirstResponseDurationHistogram = new client.Histogram({
name: 'supporthub_ticket_first_response_duration_seconds',
help: 'Duration from ticket creation to the first agent response, in seconds',
buckets: [60, 300, 900, 3600, 14400, 86400],
});
export const slaRunOutcomesCounter = new client.Counter({
name: 'supporthub_sla_run_outcomes_total',
help: 'Count of SLA runs by outcome',
labelNames: ['outcome'],
});
export const escalationsCounter = new client.Counter({
name: 'supporthub_escalations_total',
help: 'Count of escalation events by trigger reason',
labelNames: ['reason'],
});
export const problemsCreatedCounter = new client.Counter({
name: 'supporthub_problems_created_total',
help: 'Count of problems created, by category',
labelNames: ['category_id'],
});
export const knownErrorLookupsCounter = new client.Counter({
name: 'supporthub_known_error_lookups_total',
help: 'Count of known-issue lookups by error code',
labelNames: ['code'],
});
export const knowledgeRetrievalOutcomesCounter = new client.Counter({
name: 'supporthub_knowledge_retrieval_outcomes_total',
help: 'Count of AI knowledge-retrieval attempts by whether a match was found',
labelNames: ['matched'],
});
export const toolInvocationsCounter = new client.Counter({
name: 'supporthub_tool_invocations_total',
help: 'Count of AI tool invocations by tool and outcome',
labelNames: ['tool', 'outcome'],
});
export const metricsRegistry = client.register;
+79 -1
View File
@@ -1,5 +1,83 @@
import { trace, Tracer } from '@opentelemetry/api';
import { trace, context, diag, DiagLogLevel, Tracer } from '@opentelemetry/api';
import {
BasicTracerProvider,
BatchSpanProcessor,
SimpleSpanProcessor,
ConsoleSpanExporter,
InMemorySpanExporter,
} from '@opentelemetry/sdk-trace-base';
import type { SpanProcessor } from '@opentelemetry/sdk-trace';
import { AsyncLocalStorageContextManager } from '@opentelemetry/context-async-hooks';
import { resourceFromAttributes } from '@opentelemetry/resources';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { env } from '@/config';
import { logger } from './logger';
/**
* Without a registered ContextManager, the OpenTelemetry API's `context.active()` is a no-op
* that does not propagate across async boundaries at all — `startActiveSpan` would only make a
* span "active" for the literal synchronous extent of its callback, so a child span created
* after an `await` (e.g. across this codebase's own event-bus `await eventBus.publish(...)`
* chain, data-model.md's whole reason FR-006's two paths work) would silently come out as its
* own unrelated root span instead of nesting. This is the tracing equivalent of the ALS-backed
* request-context store — same mechanism, different consumer.
*/
context.setGlobalContextManager(new AsyncLocalStorageContextManager().enable());
/**
* 014-full-observability research.md §4: routes the OpenTelemetry SDK's own internal
* diagnostics (span export failures included — FR-007) through this project's own log stream
* instead of stderr/nowhere, at WARN so routine SDK chatter isn't logged at every span.
*/
diag.setLogger(
{
error: (msg, ...args) => logger.error({ otel: args }, msg),
warn: (msg, ...args) => logger.warn({ otel: args }, msg),
info: (msg, ...args) => logger.info({ otel: args }, msg),
debug: (msg, ...args) => logger.debug({ otel: args }, msg),
verbose: (msg, ...args) => logger.trace({ otel: args }, msg),
},
DiagLogLevel.WARN,
);
let testSpanExporter: InMemorySpanExporter | undefined;
/**
* Real infra, substituted destination only (same pattern as pino-pretty in development, or the
* password-reset token's stub delivery) — never a mock of the tracer/provider itself:
* - test: `InMemorySpanExporter`, so integration tests can read back real exported spans.
* - `OTEL_EXPORTER_OTLP_ENDPOINT` set: real OTLP/HTTP export via `BatchSpanProcessor` (the
* exporter reads the same env var itself for the actual collector URL — no need to hand-build
* the `/v1/traces` path here).
* - otherwise (local dev, or any environment with no collector configured): `ConsoleSpanExporter`
* so spans are visible without standing one up.
*/
function buildSpanProcessor(): SpanProcessor {
if (env.NODE_ENV === 'test') {
testSpanExporter = new InMemorySpanExporter();
return new SimpleSpanProcessor(testSpanExporter);
}
if (env.OTEL_EXPORTER_OTLP_ENDPOINT) {
return new BatchSpanProcessor(new OTLPTraceExporter());
}
return new SimpleSpanProcessor(new ConsoleSpanExporter());
}
const tracerProvider = new BasicTracerProvider({
resource: resourceFromAttributes({ 'service.name': 'supporthub-api' }),
spanProcessors: [buildSpanProcessor()],
});
trace.setGlobalTracerProvider(tracerProvider);
export function getTracer(name = 'supporthub-api'): Tracer {
return trace.getTracer(name);
}
/** Test environment only — throws otherwise. See tests/integration/observability/tracing.test.ts. */
export function getTestSpanExporter(): InMemorySpanExporter {
if (!testSpanExporter) {
throw new Error('getTestSpanExporter() is only available when NODE_ENV=test.');
}
return testSpanExporter;
}
@@ -1,5 +1,6 @@
import { AISupportSession } from '@prisma/client';
import { prismaClient } from '@/infrastructure/database';
import { aiSessionOutcomesCounter } from '@/infrastructure/observability';
import { ACTIVE_SESSION_STATUSES } from '../mapper';
export class SessionRepository {
@@ -38,10 +39,19 @@ export class SessionRepository {
async updateStatus(sessionId: string, status: string): Promise<AISupportSession> {
const isTerminal =
status === 'resolved' || status === 'escalated' || status === 'ended_by_agent';
return this.prisma.aISupportSession.update({
const updated = await this.prisma.aISupportSession.update({
where: { id: sessionId },
data: { status, ...(isTerminal ? { endedAt: new Date() } : {}) },
});
// 014-full-observability data-model.md: the single choke point every escalation/resolution
// branch in session.service.ts funnels through (research.md §5's "why the repository layer"
// — observability calls are already a cross-cutting concern used from any layer here).
if (status === 'resolved' || status === 'escalated') {
aiSessionOutcomesCounter.inc({ outcome: status });
}
return updated;
}
async setActiveRunbook(sessionId: string, runbookKey: string, stepIndex: number): Promise<void> {
@@ -1,5 +1,7 @@
import { SpanStatusCode } from '@opentelemetry/api';
import { AISupportSession, KnowledgeEntry, AIInteraction, Ticket, Problem } from '@prisma/client';
import { AppError, NotFoundError } from '@/common/errors';
import { getTracer } from '@/infrastructure/observability';
import { ticketsService, problemsRepository } from '@/modules/ticketing/tickets';
import { messagesService } from '@/modules/ticketing/messages';
import { knowledgeService } from '@/modules/ai-support/knowledge';
@@ -125,17 +127,35 @@ export class SessionsService {
reason: string,
stepsAttempted: string[] = [],
) {
const diagnosis = await this.diagnoses.findLatestBySession(session.id);
const result = this.escalation.buildSummary(diagnosis, reason, stepsAttempted);
// 014-full-observability data-model.md — root span for the AI-escalation -> orchestration/
// assignment path (FR-006): syncTicketStatus below publishes TICKET_UPDATED synchronously,
// and the orchestration subscriber's own span (src/events/handlers/index.ts) nests under
// this one automatically via OTel's active-context propagation through that same await chain.
return getTracer().startActiveSpan(
'ai.escalation',
{ attributes: { 'ticket.id': ticketId, 'session.id': session.id } },
async (span) => {
try {
const diagnosis = await this.diagnoses.findLatestBySession(session.id);
const result = this.escalation.buildSummary(diagnosis, reason, stepsAttempted);
if (!(ACTIVE_SESSION_STATUSES as readonly string[]).includes(session.status)) {
return result;
}
if (!(ACTIVE_SESSION_STATUSES as readonly string[]).includes(session.status)) {
return result;
}
await this.sessions.updateStatus(session.id, 'escalated');
await syncTicketStatus(ticketId, 'escalated');
await this.sessions.updateStatus(session.id, 'escalated');
await syncTicketStatus(ticketId, 'escalated');
return result;
return result;
} catch (error) {
span.recordException(error as Error);
span.setStatus({ code: SpanStatusCode.ERROR });
throw error;
} finally {
span.end();
}
},
);
}
private async runDiagnosisTurn(
@@ -1,6 +1,8 @@
import { randomUUID } from 'crypto';
import { SpanStatusCode } from '@opentelemetry/api';
import { Ticket } from '@prisma/client';
import { AppError } from '@/common/errors';
import { getTracer, problemsCreatedCounter } from '@/infrastructure/observability';
import {
ticketsRepository,
TicketsRepository,
@@ -48,10 +50,31 @@ export class TicketsService {
async createFromInboundRequest(
input: InboundTicketRequest,
): Promise<{ ticket: Ticket; wasExisting: boolean }> {
const span = getTracer().startSpan('ticket.create', {
attributes: { 'product.externalProductId': input.externalProductId },
});
try {
const result = await this.doCreateFromInboundRequest(input);
span.setAttribute('ticket.id', result.ticket.id);
return result;
} catch (error) {
span.recordException(error as Error);
span.setStatus({ code: SpanStatusCode.ERROR });
throw error;
} finally {
span.end();
}
}
private async doCreateFromInboundRequest(
input: InboundTicketRequest,
): Promise<{ ticket: Ticket; wasExisting: boolean }> {
const existingProblem = input.referenceIds?.length
? await this.problemsRepo.findByReference(input.referenceIds)
: null;
const problem =
(input.referenceIds?.length
? await this.problemsRepo.findByReference(input.referenceIds)
: null) ??
existingProblem ??
(await this.problemsRepo.create({
statement: input.problem,
symptoms: input.problem,
@@ -59,6 +82,14 @@ export class TicketsService {
severity: 'medium',
}));
// 014-full-observability: "recurring problems" — a raw counter, ranked/aggregated by an
// external monitoring stack (spec.md FR-009/Assumptions), not computed here.
if (!existingProblem) {
problemsCreatedCounter.inc({
category_id: problem.categoryId ?? 'uncategorized',
});
}
const year = new Date().getFullYear();
const codePrefix = `${deriveProductCode(input.externalProductId)}-${year}-`;
let attempt = 0;
@@ -0,0 +1,101 @@
import { describe, it, expect, beforeAll, afterAll } from 'vitest';
import { buildApp } from '@/app';
import { prismaClient } from '@/infrastructure/database';
import { FastifyInstance } from 'fastify';
import {
encryptCredential,
generateCredentialSecret,
issueIntegrationToken,
} from '@/modules/catalog/products';
import { sessionsService, sessionRepository } from '@/modules/ai-support/sessions';
import { getTestSpanExporter } from '@/infrastructure/observability';
/**
* Covers specs/014-full-observability/quickstart.md Scenario 3, against a real running app.
* Reads spans back from getTestSpanExporter() (a real TracerProvider, real spans — only the
* export *destination* is swapped for an in-memory one, per research.md §4) rather than through
* an external collector.
*
* Drives the escalation path directly via sessionsService.escalate(...) instead of through a
* real AI reasoning turn — the tracing behavior under test (span creation/nesting) is identical
* either way, and this avoids requiring a paid ANTHROPIC_API_KEY for every test run (see
* ai-verification-and-escalation.test.ts's own `describe.skipIf(!hasRealApiKey)` for the
* alternative this project already uses when a real reasoning call is actually required).
*/
describe('Cross-module trace (User Story 3)', () => {
let app: FastifyInstance;
beforeAll(async () => {
app = await buildApp();
});
afterAll(async () => {
await app.close();
});
async function createTicketViaInboundRequest(): Promise<string> {
const externalProductId = `TEST_TRACE_PROD_${Date.now()}_${Math.random().toString(36).slice(2)}`;
const product = await prismaClient.product.create({
data: { externalProductId, name: 'Tracing Test Product', status: 'active' },
});
const secret = generateCredentialSecret();
await prismaClient.productIntegration.create({
data: {
productId: product.id,
credentialRef: encryptCredential(secret),
authMechanism: 'signed_token',
allowedScope: { tenantIds: ['tenant-1'] },
status: 'active',
rateLimitPerMinute: 1000,
rateLimitPerUserPerMinute: 1000,
},
});
const token = issueIntegrationToken(secret, {
externalProductId,
tenantId: 'tenant-1',
userId: 'user-1',
});
const created = await app.inject({
method: 'POST',
url: '/v1/support/requests',
headers: { authorization: `Bearer ${token}` },
payload: {
productId: externalProductId,
tenantId: 'tenant-1',
userId: 'user-1',
source: 'test',
problem: 'Needs a human, for tracing.',
},
});
expect(created.statusCode).toBe(202);
return created.json().data.ticketId as string;
}
it('produces a ticket.create span for ticket intake', async () => {
getTestSpanExporter().reset();
await createTicketViaInboundRequest();
const spans = getTestSpanExporter().getFinishedSpans();
const createSpan = spans.find((s) => s.name === 'ticket.create');
expect(createSpan).toBeDefined();
expect(createSpan?.attributes['ticket.id']).toBeTruthy();
});
it('nests orchestration.assignment under ai.escalation, sharing one trace', async () => {
getTestSpanExporter().reset();
const ticketId = await createTicketViaInboundRequest();
const session = await sessionRepository.create(ticketId);
await sessionsService.escalate(session, ticketId, 'Escalating for tracing test.');
const spans = getTestSpanExporter().getFinishedSpans();
const escalationSpan = spans.find((s) => s.name === 'ai.escalation');
const assignmentSpan = spans.find((s) => s.name === 'orchestration.assignment');
expect(escalationSpan).toBeDefined();
expect(assignmentSpan).toBeDefined();
expect(assignmentSpan?.spanContext().traceId).toBe(escalationSpan?.spanContext().traceId);
expect(assignmentSpan?.parentSpanContext?.spanId).toBe(escalationSpan?.spanContext().spanId);
});
});
@@ -0,0 +1,54 @@
import { describe, it, expect, afterEach } from 'vitest';
import { BasicTracerProvider, BatchSpanProcessor } from '@opentelemetry/sdk-trace-base';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
/**
* 014-full-observability FR-007/Quickstart Scenario 3 steps 3-4: an unreachable tracing
* collector must never surface as an application-level failure. This exercises the real
* OpenTelemetry SDK's actual background export path (BasicTracerProvider + BatchSpanProcessor +
* a real OTLPTraceExporter, against a real, deliberately-unreachable address — not a mock) the
* same way it runs in production: a span ends, the processor's own internal timer schedules the
* export, and a failed export is caught by the SDK's own error handler — never left as an
* unhandled rejection that could crash the process.
*
* (Deliberately does NOT call provider.forceFlush() to prove this — forceFlush() is documented
* OpenTelemetry SDK behavior that *does* reject on a failed export, by design, so a caller that
* explicitly asks "did my flush succeed?" can find out. This feature's own code never calls
* forceFlush() on the request-handling path, only the SDK's own background timer does, which is
* what this test exercises instead.)
*/
describe('Tracing graceful degradation', () => {
let unhandledRejection: unknown;
const onUnhandledRejection = (reason: unknown) => {
unhandledRejection = reason;
};
afterEach(() => {
process.removeListener('unhandledRejection', onUnhandledRejection);
});
it('does not produce an unhandled rejection when the background export to an unreachable endpoint fails', async () => {
unhandledRejection = undefined;
process.on('unhandledRejection', onUnhandledRejection);
const exporter = new OTLPTraceExporter({
url: 'http://127.0.0.1:1/v1/traces', // port 1 — nothing listens there
timeoutMillis: 500,
});
const provider = new BasicTracerProvider({
spanProcessors: [
new BatchSpanProcessor(exporter, { scheduledDelayMillis: 10, exportTimeoutMillis: 500 }),
],
});
const span = provider.getTracer('test').startSpan('unreachable-export-test');
span.end(); // triggers the processor's own internal timer, not forceFlush()
// Long enough for the internal timer (10ms) + the failed connection attempt to resolve.
await new Promise((resolve) => setTimeout(resolve, 1500));
expect(unhandledRejection).toBeUndefined();
await provider.shutdown();
}, 10000);
});