diff --git a/.changeset/official-prometheus-client.md b/.changeset/official-prometheus-client.md new file mode 100644 index 00000000..a07b84bd --- /dev/null +++ b/.changeset/official-prometheus-client.md @@ -0,0 +1,8 @@ +--- +'@when/web': patch +'@when/worker': patch +--- + +Replace deprecated prom-client with the official @prometheus-io/client and remove Node collectors and their background sampling. Aggregate private worker snapshots natively and expose worker collection health. Centralize instrumentation at operation boundaries, count appointment operation outcomes, and categorize SMTP/calendar failures without putting metric calls in business implementations. + +Booking attempts now label unclassified failures `error` rather than `database_error`. diff --git a/apps/web/eslint.config.js b/apps/web/eslint.config.js index ddf47855..3bd7a5ce 100644 --- a/apps/web/eslint.config.js +++ b/apps/web/eslint.config.js @@ -31,6 +31,24 @@ export default defineConfig( 'no-undef': 'off' } }, + { + files: ['src/**/*.ts', 'src/**/*.svelte'], + ignores: ['src/lib/server/metrics/**', 'src/**/*.test.ts'], + rules: { + 'no-restricted-imports': [ + 'error', + { + patterns: [ + { + group: ['@prometheus-io/client', '@prometheus-io/client/*', '**/metrics/registry*'], + message: + 'Keep Prometheus details inside server/metrics; use an observer or an explicit HTTP outcome recorder.' + } + ] + } + ] + } + }, { files: ['**/*.svelte', '**/*.svelte.ts', '**/*.svelte.js'], languageOptions: { diff --git a/apps/web/package.json b/apps/web/package.json index 34da34dd..3e0b8a2d 100644 --- a/apps/web/package.json +++ b/apps/web/package.json @@ -53,6 +53,7 @@ "dependencies": { "@dicebear/core": "10.4.0", "@internationalized/date": "3.12.2", + "@prometheus-io/client": "0.16.1", "@when/calendar": "workspace:*", "@when/config": "workspace:*", "@when/db": "workspace:*", @@ -64,7 +65,6 @@ "mrmime": "2.0.1", "openworkflow": "0.11.0", "pino": "10.3.1", - "prom-client": "15.1.3", "takumi-js": "2.2.0", "temporal-polyfill": "1.0.1", "ts-ics": "2.4.4", diff --git a/apps/web/src/lib/server/appointment-operations.ts b/apps/web/src/lib/server/appointment-operations.ts new file mode 100644 index 00000000..367c5db5 --- /dev/null +++ b/apps/web/src/lib/server/appointment-operations.ts @@ -0,0 +1,24 @@ +import { createAppointment as create } from './appointment/create'; +import { acceptAppointment as accept } from './appointment/accept'; +import { declineAppointment as decline } from './appointment/decline'; +import { cancelAppointment as cancel } from './appointment/cancel'; +import { rescheduleAppointment as reschedule } from './appointment/reschedule'; +import { observeAppointmentOperation } from './metrics/appointments'; + +export const createAppointment = observeAppointmentOperation( + 'create', + create, + (_ctx, input) => input.initiator ?? 'guest' +); +export const acceptAppointment = observeAppointmentOperation('accept', accept, () => 'host'); +export const declineAppointment = observeAppointmentOperation('decline', decline, () => 'host'); +export const cancelAppointment = observeAppointmentOperation( + 'cancel', + cancel, + (_ctx, input) => input.initiator +); +export const rescheduleAppointment = observeAppointmentOperation( + 'reschedule', + reschedule, + (_ctx, input) => input.initiator +); diff --git a/apps/web/src/lib/server/auth/index.test.ts b/apps/web/src/lib/server/auth/index.test.ts index 98a249b9..fcf1ee1e 100644 --- a/apps/web/src/lib/server/auth/index.test.ts +++ b/apps/web/src/lib/server/auth/index.test.ts @@ -2,7 +2,7 @@ import type { Handle } from '@sveltejs/kit/hooks'; import { afterAll, afterEach, beforeEach, expect, test, vi } from 'vitest'; import { parseSetCookieHeader } from 'better-auth/cookies'; import { validConfig } from '../__fixtures__/valid-config'; -import { userLoginsTotal } from '../metrics'; +import { userLoginsTotal } from '../metrics/registry'; import { authHandle, getAuth, makeAuth } from './index'; // Exercise the actual production limiter and origin checks, not test-mode defaults. diff --git a/apps/web/src/lib/server/auth/index.ts b/apps/web/src/lib/server/auth/index.ts index 97246999..40dcc8e2 100644 --- a/apps/web/src/lib/server/auth/index.ts +++ b/apps/web/src/lib/server/auth/index.ts @@ -4,6 +4,7 @@ import { betterAuth, type BetterAuthOptions } from 'better-auth/minimal'; import { svelteKitHandler } from 'better-auth/svelte-kit'; import type { WhenConfiguration } from '@when/config'; import { logger } from '../logger'; +import { loginMetricsHooks } from '../metrics/auth'; import { buildAuthOptions } from './providers'; import { requireAuthSecret } from './secret'; @@ -38,6 +39,7 @@ export function makeAuth(cfg: WhenConfiguration) { ipAddress: { ipAddressHeaders: ['x-real-ip'] } }, ...buildAuthOptions(cfg), + hooks: loginMetricsHooks(cfg.auth.credentials ? 'credentials' : 'oidc'), logger: { // Library messages/arguments can contain credentials, codes or tokens. log: (level) => logger[level]({ source: 'better-auth' }, 'authentication event') diff --git a/apps/web/src/lib/server/auth/providers.ts b/apps/web/src/lib/server/auth/providers.ts index 3d0064be..1f93dde8 100644 --- a/apps/web/src/lib/server/auth/providers.ts +++ b/apps/web/src/lib/server/auth/providers.ts @@ -1,17 +1,11 @@ import { timingSafeEqual } from 'node:crypto'; import type { BetterAuthOptions, BetterAuthPlugin } from 'better-auth'; -import { - APIError, - createAuthEndpoint, - createAuthMiddleware, - formCsrfMiddleware -} from 'better-auth/api'; +import { APIError, createAuthEndpoint, formCsrfMiddleware } from 'better-auth/api'; import { setSessionCookie } from 'better-auth/cookies'; import { genericOAuth } from 'better-auth/plugins/generic-oauth'; import type { CredentialsAuth, OidcAuth, WhenConfiguration } from '@when/config'; -import { userLoginsTotal } from '../metrics'; -type AuthOptions = Pick; +type AuthOptions = Pick; export function buildAuthOptions(cfg: WhenConfiguration): AuthOptions { if (cfg.auth.credentials) return credentialsAuth(cfg.auth.credentials, cfg.user.email); @@ -21,14 +15,7 @@ export function buildAuthOptions(cfg: WhenConfiguration): AuthOptions { function credentialsAuth(admin: CredentialsAuth, email: string): AuthOptions { return { - plugins: [credentialsProvider(admin, email)], - hooks: { - after: createAuthMiddleware(async (ctx) => { - if (ctx.path !== '/sign-in/credentials') return; - const status = ctx.context.newSession ? 'success' : 'failure'; - userLoginsTotal.inc({ provider: 'credentials', status }); - }) - } + plugins: [credentialsProvider(admin, email)] }; } @@ -52,15 +39,7 @@ function oidcAuth(oidc: OidcAuth, appUrl: string): AuthOptions { ] }) ], - onAPIError: { errorURL: new URL('/signin', appUrl).href }, - hooks: { - after: createAuthMiddleware(async (ctx) => { - if (ctx.path !== '/callback/:id') return; - if (ctx.params?.id !== 'oidc') return; - const status = ctx.context.newSession ? 'success' : 'failure'; - userLoginsTotal.inc({ provider: 'oidc', status }); - }) - } + onAPIError: { errorURL: new URL('/signin', appUrl).href } }; } diff --git a/apps/web/src/lib/server/metrics.test.ts b/apps/web/src/lib/server/metrics.test.ts deleted file mode 100644 index 98f77bf0..00000000 --- a/apps/web/src/lib/server/metrics.test.ts +++ /dev/null @@ -1,38 +0,0 @@ -import { expect, test } from 'vitest'; -import { register } from './metrics'; - -test('register has default labels', async () => { - const json = await register.getMetricsAsJSON(); - const firstMetric = json.find((m) => m.name === 'process_resident_memory_bytes'); - expect(firstMetric).toBeDefined(); - if (firstMetric) { - const firstVal = firstMetric.values[0]; - expect(firstVal).toBeDefined(); - if (firstVal) { - expect(firstVal.labels).toMatchObject({ app: 'when', service: 'web' }); - } - } -}); - -test('low-value default metrics are pruned', async () => { - const json = await register.getMetricsAsJSON(); - const names = json.map((m) => m.name); - - // High-value metrics we keep - expect(names).toContain('process_resident_memory_bytes'); - expect(names).toContain('process_cpu_seconds_total'); - - // Low-value metrics we prune - expect(names).not.toContain('nodejs_active_handles'); - expect(names).not.toContain('nodejs_heap_space_size_total_bytes'); - expect(names).not.toContain('process_virtual_memory_bytes'); -}); - -test('custom web metrics are registered', async () => { - const json = await register.getMetricsAsJSON(); - const names = json.map((m) => m.name); - - expect(names).toContain('when_booking_attempts_total'); - expect(names).toContain('when_user_logins_total'); - expect(names).toContain('when_ics_downloads_total'); -}); diff --git a/apps/web/src/lib/server/metrics.ts b/apps/web/src/lib/server/metrics.ts deleted file mode 100644 index cd000d6b..00000000 --- a/apps/web/src/lib/server/metrics.ts +++ /dev/null @@ -1,60 +0,0 @@ -import { collectDefaultMetrics, Counter, Registry } from 'prom-client'; - -export const register = new Registry(); -register.setDefaultLabels({ app: 'when', service: 'web' }); - -collectDefaultMetrics({ register }); - -// Prune low-value default metrics to keep the footprint minimal -const metricsToPrune = [ - 'nodejs_active_handles', - 'nodejs_active_handles_total', - 'nodejs_active_requests', - 'nodejs_active_requests_total', - 'nodejs_heap_space_size_total_bytes', - 'nodejs_heap_space_size_used_bytes', - 'nodejs_heap_space_size_available_bytes', - 'nodejs_heap_space_size_bytes_total', - 'nodejs_heap_space_size_bytes_used', - 'nodejs_heap_space_size_bytes_available', - 'nodejs_heap_space_size_bytes_required', - 'nodejs_eventloop_lag_seconds', - 'nodejs_eventloop_lag_min_seconds', - 'nodejs_eventloop_lag_max_seconds', - 'nodejs_eventloop_lag_mean_seconds', - 'nodejs_eventloop_lag_stddev_seconds', - 'nodejs_eventloop_lag_p50_seconds', - 'nodejs_eventloop_lag_p90_seconds', - 'nodejs_eventloop_lag_p99_seconds', - 'process_virtual_memory_bytes', - 'process_virtual_memory_max_bytes', - 'process_heap_bytes', - 'process_start_time_seconds', - 'process_open_fds', - 'process_max_fds' -]; - -for (const metric of metricsToPrune) { - register.removeSingleMetric(metric); -} - -export const bookingAttemptsTotal = new Counter({ - name: 'when_booking_attempts_total', - help: 'Total number of visitor booking attempts.', - labelNames: ['event_type_id', 'status'], - registers: [register] -}); - -export const userLoginsTotal = new Counter({ - name: 'when_user_logins_total', - help: 'Total number of host dashboard login attempts.', - labelNames: ['provider', 'status'], - registers: [register] -}); - -export const icsDownloadsTotal = new Counter({ - name: 'when_ics_downloads_total', - help: 'Total number of ICS calendar invite downloads.', - labelNames: ['status'], - registers: [register] -}); diff --git a/apps/web/src/lib/server/metrics/appointments.test.ts b/apps/web/src/lib/server/metrics/appointments.test.ts new file mode 100644 index 00000000..b5ef2f88 --- /dev/null +++ b/apps/web/src/lib/server/metrics/appointments.test.ts @@ -0,0 +1,76 @@ +import { beforeEach, expect, test, vi } from 'vitest'; +import { openDb, runMigrations } from '@when/db'; +import { validConfig } from '../__fixtures__/valid-config'; +import { systemClock } from '../clock'; +import { createAppointment } from '../appointment-operations'; +import { observeAppointmentOperation } from './appointments'; +import { appointmentOperationsTotal } from './registry'; + +vi.mock('../workflow', () => ({ enqueueAppointmentReconciliation: vi.fn() })); +import { enqueueAppointmentReconciliation } from '../workflow'; + +beforeEach(() => { + appointmentOperationsTotal.reset(); + vi.mocked(enqueueAppointmentReconciliation).mockReset(); +}); + +test.each([ + { result: { ok: true }, status: 'success' }, + { result: { ok: false }, status: 'rejected' } +])('records $status without changing the operation result', async ({ result, status }) => { + const operation = vi.fn(async (input: { actor: 'host' | 'guest' }) => ({ + ...result, + actor: input.actor + })); + const observed = observeAppointmentOperation('cancel', operation, (input) => input.actor); + const input = { actor: 'host' as const }; + const output = await observed(input); + expect(operation).toHaveBeenCalledExactlyOnceWith(input); + expect(output).toEqual({ ...result, actor: 'host' }); + expect((await appointmentOperationsTotal.get()).values).toMatchObject([ + { labels: { action: 'cancel', actor: 'host', status }, value: 1 } + ]); +}); + +test('records an error and rethrows the original exception', async () => { + const failure = new Error('operation failed'); + const observed = observeAppointmentOperation( + 'accept', + async () => { + throw failure; + }, + () => 'host' + ); + await expect(observed()).rejects.toBe(failure); + expect((await appointmentOperationsTotal.get()).values).toMatchObject([ + { labels: { action: 'accept', actor: 'host', status: 'error' }, value: 1 } + ]); +}); + +test('the public create API records an error even when insertion committed before enqueue failed', async () => { + const db = openDb(':memory:'); + await runMigrations(db); + const failure = new Error('queue unavailable'); + vi.mocked(enqueueAppointmentReconciliation).mockRejectedValueOnce(failure); + try { + await expect( + createAppointment( + { db, cfg: validConfig, clock: systemClock }, + { + slug: '30-min-chat', + eventType: validConfig.meetings['30-min-chat'], + start: '2099-01-01T15:00:00Z', + end: '2099-01-01T15:30:00Z', + guest: { name: 'Booker', email: 'guest@example.test', answers: [], timezone: 'UTC' }, + location: null + } + ) + ).rejects.toBe(failure); + expect(await db.selectFrom('appointments').select('id').execute()).toHaveLength(1); + expect((await appointmentOperationsTotal.get()).values).toMatchObject([ + { labels: { action: 'create', actor: 'guest', status: 'error' }, value: 1 } + ]); + } finally { + await db.destroy(); + } +}); diff --git a/apps/web/src/lib/server/metrics/appointments.ts b/apps/web/src/lib/server/metrics/appointments.ts new file mode 100644 index 00000000..55e2e6bc --- /dev/null +++ b/apps/web/src/lib/server/metrics/appointments.ts @@ -0,0 +1,24 @@ +import { appointmentOperationsTotal } from './registry'; + +type AppointmentAction = 'create' | 'accept' | 'decline' | 'cancel' | 'reschedule'; +type AppointmentActor = 'host' | 'guest'; + +export function observeAppointmentOperation( + action: AppointmentAction, + operation: (...args: Args) => Promise, + actor: (...args: Args) => AppointmentActor +): (...args: Args) => Promise { + return async (...args) => { + const initiator = actor(...args); + let result: Result; + try { + result = await operation(...args); + } catch (err) { + appointmentOperationsTotal.inc({ action, actor: initiator, status: 'error' }); + throw err; + } + const status = result.ok ? 'success' : 'rejected'; + appointmentOperationsTotal.inc({ action, actor: initiator, status }); + return result; + }; +} diff --git a/apps/web/src/lib/server/metrics/auth.ts b/apps/web/src/lib/server/metrics/auth.ts new file mode 100644 index 00000000..c23183a7 --- /dev/null +++ b/apps/web/src/lib/server/metrics/auth.ts @@ -0,0 +1,17 @@ +import type { BetterAuthOptions } from 'better-auth'; +import { createAuthMiddleware } from 'better-auth/api'; +import { userLoginsTotal } from './registry'; + +export function loginMetricsHooks( + provider: 'credentials' | 'oidc' +): NonNullable { + return { + after: createAuthMiddleware(async (ctx) => { + if (provider === 'credentials' && ctx.path !== '/sign-in/credentials') return; + if (provider === 'oidc' && (ctx.path !== '/callback/:id' || ctx.params?.id !== 'oidc')) + return; + const status = ctx.context.newSession ? 'success' : 'failure'; + userLoginsTotal.inc({ provider, status }); + }) + }; +} diff --git a/apps/web/src/lib/server/metrics/registry.test.ts b/apps/web/src/lib/server/metrics/registry.test.ts new file mode 100644 index 00000000..d20055ec --- /dev/null +++ b/apps/web/src/lib/server/metrics/registry.test.ts @@ -0,0 +1,30 @@ +import { expect, test } from 'vitest'; +import { bookingAttemptsTotal, register } from './registry'; + +test('register has default labels', async () => { + bookingAttemptsTotal.inc({ event_type_id: 'test-meeting', status: 'success' }); + try { + const json = await register.getMetricsAsJSON(); + expect( + json.find((metric) => metric.name === 'when_booking_attempts_total')?.values + ).toMatchObject([ + { + labels: { app: 'when', service: 'web', event_type_id: 'test-meeting', status: 'success' }, + value: 1 + } + ]); + } finally { + bookingAttemptsTotal.reset(); + } +}); + +test('only application metrics are registered', async () => { + const json = await register.getMetricsAsJSON(); + expect(json.map((metric) => metric.name).sort()).toEqual([ + 'when_appointment_operations_total', + 'when_booking_attempts_total', + 'when_ics_downloads_total', + 'when_operation_failures_total', + 'when_user_logins_total' + ]); +}); diff --git a/apps/web/src/lib/server/metrics/registry.ts b/apps/web/src/lib/server/metrics/registry.ts new file mode 100644 index 00000000..ce28e739 --- /dev/null +++ b/apps/web/src/lib/server/metrics/registry.ts @@ -0,0 +1,39 @@ +import { Counter, Registry } from '@prometheus-io/client'; + +export const register = new Registry(); +register.setDefaultLabels({ app: 'when', service: 'web' }); + +export const bookingAttemptsTotal = new Counter({ + name: 'when_booking_attempts_total', + help: 'Total number of visitor booking attempts.', + labelNames: ['event_type_id', 'status'], + registers: [register] +}); + +export const userLoginsTotal = new Counter({ + name: 'when_user_logins_total', + help: 'Total number of host dashboard login attempts.', + labelNames: ['provider', 'status'], + registers: [register] +}); + +export const icsDownloadsTotal = new Counter({ + name: 'when_ics_downloads_total', + help: 'Total number of ICS calendar invite downloads.', + labelNames: ['status'], + registers: [register] +}); + +export const appointmentOperationsTotal = new Counter({ + name: 'when_appointment_operations_total', + help: 'Appointment operation outcomes, not committed changes.', + labelNames: ['action', 'actor', 'status'], + registers: [register] +}); + +export const operationFailuresTotal = new Counter({ + name: 'when_operation_failures_total', + help: 'Failed operation attempts by bounded operation and failure code.', + labelNames: ['operation', 'code'], + registers: [register] +}); diff --git a/apps/web/src/lib/server/metrics/requests.ts b/apps/web/src/lib/server/metrics/requests.ts new file mode 100644 index 00000000..93988252 --- /dev/null +++ b/apps/web/src/lib/server/metrics/requests.ts @@ -0,0 +1,12 @@ +import { bookingAttemptsTotal, icsDownloadsTotal } from './registry'; + +type BookingOutcome = 'success' | 'invalid_input' | 'slot_taken' | 'error'; +type IcsOutcome = 'success' | 'not_found' | 'forbidden' | 'error'; + +export function recordBookingOutcome(eventTypeId: string, status: BookingOutcome): void { + bookingAttemptsTotal.inc({ event_type_id: eventTypeId, status }); +} + +export function recordIcsDownload(status: IcsOutcome): void { + icsDownloadsTotal.inc({ status }); +} diff --git a/apps/web/src/lib/server/metrics/scrape.ts b/apps/web/src/lib/server/metrics/scrape.ts new file mode 100644 index 00000000..be2cb81e --- /dev/null +++ b/apps/web/src/lib/server/metrics/scrape.ts @@ -0,0 +1,105 @@ +import { Gauge, Registry } from '@prometheus-io/client'; +import { register, operationFailuresTotal } from './registry'; +import { decodeMetricsSnapshot } from './snapshot'; +import { logger } from '../logger'; + +type WebSnapshot = Awaited>; +type WorkerSnapshot = ReturnType; + +export async function collectMetricsResponse( + fetch: typeof globalThis.fetch, + workerUrl: string, + token: string +): Promise { + const { web, worker } = await collectMetrics(fetch, workerUrl, token); + return metricsResponse(web, worker); +} + +async function collectMetrics(fetch: typeof globalThis.fetch, workerUrl: string, token: string) { + const [worker, web] = await Promise.all([ + collectWorkerMetrics(fetch, workerUrl, token), + register.getMetricsAsJSON() + ]); + // Worker failure can add a counter series after the concurrent web snapshot. + const webMetrics = worker === null ? await register.getMetricsAsJSON() : web; + return { web: webMetrics, worker }; +} + +async function collectWorkerMetrics( + fetch: typeof globalThis.fetch, + workerUrl: string, + token: string +): Promise { + let body: string; + try { + const response = await fetch(`${workerUrl}/metrics`, { + headers: { authorization: `Bearer ${token}`, accept: 'application/json' }, + signal: AbortSignal.timeout(2000) + }); + if (!response.ok) { + const code = + response.status === 401 || response.status === 403 ? 'unauthorized' : 'http_error'; + recordWorkerFailure(code, { status: response.status }); + return null; + } + body = await response.text(); + } catch (err) { + recordWorkerFailure( + err instanceof Error && err.name === 'TimeoutError' ? 'timeout' : 'transport_error', + { err } + ); + return null; + } + + try { + const snapshot: unknown = JSON.parse(body); + const metrics = decodeMetricsSnapshot(snapshot); + assertCompatibleMetricTypes(metrics); + return metrics; + } catch (err) { + recordWorkerFailure('invalid_snapshot', { err }); + return null; + } +} + +function assertCompatibleMetricTypes(workerMetrics: WorkerSnapshot): void { + const webTypes = new Map( + register.getMetricsAsArray().map((metric) => [metric.name, metric.type]) + ); + for (const metric of workerMetrics) { + const webType = webTypes.get(metric.name); + if (webType !== undefined && webType !== metric.type) { + throw new Error('Conflicting metric types'); + } + } +} + +async function metricsResponse( + webMetrics: WebSnapshot, + workerMetrics: WorkerSnapshot | null +): Promise { + const scrapeRegistry = createScrapeRegistry(workerMetrics !== null); + const scrapeMetrics = await scrapeRegistry.getMetricsAsJSON(); + const combined = Registry.aggregate([webMetrics, workerMetrics ?? [], scrapeMetrics]); + const body = await combined.metrics(); + return new Response(body, { headers: { 'content-type': combined.contentType } }); +} + +function createScrapeRegistry(success: boolean): Registry { + const registry = new Registry(); + registry.setDefaultLabels({ app: 'when' }); + new Gauge({ + name: 'when_worker_scrape_success', + help: 'Whether this scrape collected usable worker metrics; not proof of queue progress.', + registers: [registry] + }).set(success ? 1 : 0); + return registry; +} + +function recordWorkerFailure( + code: 'unauthorized' | 'http_error' | 'invalid_snapshot' | 'timeout' | 'transport_error', + details: { status?: number; err?: unknown } +): void { + operationFailuresTotal.inc({ operation: 'worker_scrape', code }); + logger.warn({ operation: 'worker_scrape', code, ...details }, 'Worker metrics unavailable'); +} diff --git a/apps/web/src/lib/server/metrics/snapshot.ts b/apps/web/src/lib/server/metrics/snapshot.ts new file mode 100644 index 00000000..959df5c8 --- /dev/null +++ b/apps/web/src/lib/server/metrics/snapshot.ts @@ -0,0 +1,61 @@ +const metricTypes = ['counter', 'gauge', 'histogram', 'summary']; +const aggregators = ['sum', 'first', 'min', 'max', 'average', 'omit']; + +export function decodeMetricsSnapshot(value: unknown) { + if (!Array.isArray(value)) throw new Error('Invalid metrics snapshot'); + return value.map(decodeMetric); +} + +function decodeMetric(metric: unknown) { + if ( + !isRecord(metric) || + !isMetricName(metric.name) || + typeof metric.help !== 'string' || + typeof metric.type !== 'string' || + !metricTypes.includes(metric.type) || + !isAggregator(metric.aggregator) || + !Array.isArray(metric.values) + ) { + throw new Error('Invalid metrics snapshot'); + } + return { + ...metric, + name: metric.name, + type: metric.type, + values: metric.values.map(decodeSample) + }; +} + +function decodeSample(sample: unknown) { + if ( + !isRecord(sample) || + !isWorkerLabels(sample.labels) || + typeof sample.value !== 'number' || + !Number.isFinite(sample.value) || + (sample.metricName !== undefined && !isMetricName(sample.metricName)) + ) { + throw new Error('Invalid metrics sample'); + } + return { ...sample, value: sample.value }; +} + +function isWorkerLabels(value: unknown): boolean { + if (!isRecord(value) || value.app !== 'when' || value.service !== 'worker') return false; + return Object.entries(value).every( + ([name, label]) => + /^[a-zA-Z_][a-zA-Z_0-9]*$/.test(name) && + (typeof label === 'string' || (typeof label === 'number' && Number.isFinite(label))) + ); +} + +function isAggregator(value: unknown): boolean { + return value === undefined || (typeof value === 'string' && aggregators.includes(value)); +} + +function isMetricName(value: unknown): value is string { + return typeof value === 'string' && /^[:a-zA-Z_][:a-zA-Z_0-9]*$/.test(value); +} + +function isRecord(value: unknown): value is Record { + return value !== null && typeof value === 'object' && !Array.isArray(value); +} diff --git a/apps/web/src/routes/(app)/appointment/[id]/+page.server.ts b/apps/web/src/routes/(app)/appointment/[id]/+page.server.ts index 7e45ab3c..e9e19461 100644 --- a/apps/web/src/routes/(app)/appointment/[id]/+page.server.ts +++ b/apps/web/src/routes/(app)/appointment/[id]/+page.server.ts @@ -21,7 +21,7 @@ import { toPublicAppointment } from '#lib/server/appointment/sanitize.js'; import { readMeetingSnapshot } from '#lib/server/appointment/snapshot.js'; import { resolveBookingDurations } from '#lib/server/appointment/duration.js'; import type { Actions, PageServerLoad } from './$types'; -import { cancelAppointment } from '#lib/server/appointment/cancel.js'; +import { cancelAppointment } from '#lib/server/appointment-operations.js'; import { validateReason } from '#lib/server/appointment/form.server.js'; import { appointmentContext } from '#lib/server/appointment/context.js'; diff --git a/apps/web/src/routes/(app)/appointment/[id]/ics/+server.ts b/apps/web/src/routes/(app)/appointment/[id]/ics/+server.ts index 963d6ec8..ee9d4ef0 100644 --- a/apps/web/src/routes/(app)/appointment/[id]/ics/+server.ts +++ b/apps/web/src/routes/(app)/appointment/[id]/ics/+server.ts @@ -5,37 +5,34 @@ import { buildIcs } from '@when/calendar'; import { senderEmail } from '@when/config'; import { findAppointment } from '@when/db'; import { getConfig, getDb } from '#lib/server/state.js'; -import { icsDownloadsTotal } from '#lib/server/metrics.js'; +import { recordIcsDownload } from '#lib/server/metrics/requests.js'; import type { RequestHandler } from './$types'; export const GET: RequestHandler = async ({ params, url }) => { try { const token = url.searchParams.get('token'); if (!token) { - icsDownloadsTotal.inc({ status: 'not_found' }); + recordIcsDownload('not_found'); error(404); } const row = await findAppointment(getDb(), params.id); if (!row || !(await isViewAllowed(getDb(), row, token, systemClock.now()))) { - icsDownloadsTotal.inc({ status: 'not_found' }); + recordIcsDownload('not_found'); error(404); } - if (row.status !== 'confirmed') { - icsDownloadsTotal.inc({ status: 'forbidden' }); + recordIcsDownload('forbidden'); error(403, 'Calendar invites are only available for confirmed appointments.'); } const cfg = getConfig(); const eventType = cfg.meetings[row.event_type_id]; if (!eventType) { - icsDownloadsTotal.inc({ status: 'not_found' }); + recordIcsDownload('not_found'); error(404); } - const cancelUrl = `${url.origin}/appointment/${row.id}?token=${encodeURIComponent(token)}`; - const ics = buildIcs({ appointment: row, eventTypeName: eventType?.title ?? row.event_type_id, @@ -44,19 +41,17 @@ export const GET: RequestHandler = async ({ params, url }) => { cancelUrl, method: 'REQUEST' }); - - icsDownloadsTotal.inc({ status: 'success' }); - return new Response(ics, { + const response = new Response(ics, { status: 200, headers: { 'content-type': 'text/calendar; charset=utf-8', 'content-disposition': `attachment; filename="${row.id}.ics"` } }); + recordIcsDownload('success'); + return response; } catch (err) { - if (!isHttpError(err)) { - icsDownloadsTotal.inc({ status: 'error' }); - } + if (!isHttpError(err)) recordIcsDownload('error'); throw err; } }; diff --git a/apps/web/src/routes/(app)/appointment/[id]/ics/server.test.ts b/apps/web/src/routes/(app)/appointment/[id]/ics/server.test.ts index e51e208a..7e7d4826 100644 --- a/apps/web/src/routes/(app)/appointment/[id]/ics/server.test.ts +++ b/apps/web/src/routes/(app)/appointment/[id]/ics/server.test.ts @@ -1,6 +1,7 @@ import { describe, expect, test, vi, beforeEach } from 'vitest'; import { validConfig } from '#lib/server/__fixtures__/valid-config.js'; import type { Appointment } from '@when/db'; +import { icsDownloadsTotal } from '#lib/server/metrics/registry.js'; const h = vi.hoisted(() => ({ row: { current: null as Appointment | null }, @@ -52,6 +53,7 @@ function appt(status = 'confirmed'): Appointment { beforeEach(() => { vi.clearAllMocks(); + icsDownloadsTotal.reset(); h.row.current = appt(); h.viewAllowed.mockResolvedValue(true); h.buildIcs.mockReturnValue('BEGIN:VCALENDAR'); @@ -60,6 +62,9 @@ beforeEach(() => { describe('GET /appointment/[id]/ics', () => { test('404s when no token is supplied', async () => { expect((await caught(() => GET(event(null)))).status).toBe(404); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'not_found' }, value: 1 }] + }); }); test('serves the ics for a confirmed, viewable appointment', async () => { @@ -68,6 +73,9 @@ describe('GET /appointment/[id]/ics', () => { expect(res.headers.get('content-type')).toBe('text/calendar; charset=utf-8'); expect(res.headers.get('content-disposition')).toBe('attachment; filename="appt-1.ics"'); expect(await res.text()).toBe('BEGIN:VCALENDAR'); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'success' }, value: 1 }] + }); }); test('403s when the appointment is not confirmed', async () => { @@ -75,6 +83,9 @@ describe('GET /appointment/[id]/ics', () => { h.viewAllowed.mockResolvedValue(true); expect((await caught(() => GET(event('tok-1')))).status).toBe(403); expect(h.buildIcs).not.toHaveBeenCalled(); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'forbidden' }, value: 1 }] + }); }); test('404s when the meeting type no longer exists', async () => { @@ -82,10 +93,27 @@ describe('GET /appointment/[id]/ics', () => { h.row.current.event_type_id = 'gone'; h.viewAllowed.mockResolvedValue(true); expect((await caught(() => GET(event('tok-1')))).status).toBe(404); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'not_found' }, value: 1 }] + }); }); test('404s on a bad or expired token', async () => { h.viewAllowed.mockResolvedValue(false); expect((await caught(() => GET(event('tok-1')))).status).toBe(404); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'not_found' }, value: 1 }] + }); + }); + + test('counts a rendering failure once and rethrows the same error', async () => { + const fault = new Error('Rendering failed'); + h.buildIcs.mockImplementationOnce(() => { + throw fault; + }); + await expect(GET(event('tok-1'))).rejects.toBe(fault); + expect(await icsDownloadsTotal.get()).toMatchObject({ + values: [{ labels: { status: 'error' }, value: 1 }] + }); }); }); diff --git a/apps/web/src/routes/(app)/appointment/[id]/reschedule/+page.server.ts b/apps/web/src/routes/(app)/appointment/[id]/reschedule/+page.server.ts index 695367ea..a10e6ee1 100644 --- a/apps/web/src/routes/(app)/appointment/[id]/reschedule/+page.server.ts +++ b/apps/web/src/routes/(app)/appointment/[id]/reschedule/+page.server.ts @@ -7,7 +7,8 @@ import { isRescheduleSlotBookable, loadAvailability } from '#lib/server/availabi import { resolveDuration } from '#lib/server/appointment/duration.js'; import { isViewAllowed } from '#lib/server/appointment/access.js'; import type { AppointmentRole } from '#lib/server/appointment/actions.js'; -import { classifyReschedule, rescheduleAppointment } from '#lib/server/appointment/reschedule.js'; +import { classifyReschedule } from '#lib/server/appointment/reschedule.js'; +import { rescheduleAppointment } from '#lib/server/appointment-operations.js'; import { parseAndValidateAppointmentForm, parseSlot, diff --git a/apps/web/src/routes/(app)/appointment/[id]/server.test.ts b/apps/web/src/routes/(app)/appointment/[id]/server.test.ts index 83229c79..f519e16e 100644 --- a/apps/web/src/routes/(app)/appointment/[id]/server.test.ts +++ b/apps/web/src/routes/(app)/appointment/[id]/server.test.ts @@ -4,6 +4,7 @@ import { validConfig } from '#lib/server/__fixtures__/valid-config.js'; import type { Appointment } from '@when/db'; import type { AppointmentRole } from '#lib/server/appointment/actions.js'; import { resolveBookingDurations } from '#lib/server/appointment/duration.js'; +import { appointmentOperationsTotal } from '#lib/server/metrics/registry.js'; const h = vi.hoisted(() => ({ cancelAppointment: vi.fn() })); @@ -13,7 +14,10 @@ vi.mock('#lib/server/appointment/duration.js', async (importOriginal) => { return { ...original, resolveBookingDurations: vi.fn(original.resolveBookingDurations) }; }); -beforeEach(() => vi.clearAllMocks()); +beforeEach(() => { + vi.clearAllMocks(); + appointmentOperationsTotal.reset(); +}); const mockDb = { selectFrom: vi.fn(), @@ -520,6 +524,9 @@ describe('/appointment/[id] cancel action — characterization', () => { reason: 'no longer needed' }) ); + expect(await appointmentOperationsTotal.get()).toMatchObject({ + values: [{ labels: { action: 'cancel', actor: 'guest', status: 'success' }, value: 1 }] + }); }); test('another row token in the chain cannot cancel this row', async () => { diff --git a/apps/web/src/routes/(app)/schedule/[slug]/+page.server.ts b/apps/web/src/routes/(app)/schedule/[slug]/+page.server.ts index 819551c7..122a030e 100644 --- a/apps/web/src/routes/(app)/schedule/[slug]/+page.server.ts +++ b/apps/web/src/routes/(app)/schedule/[slug]/+page.server.ts @@ -3,7 +3,7 @@ import { isNewSlotBookable, loadAvailability } from '#lib/server/availability/bo import { logger } from '#lib/server/logger.js'; import { getConfig, getDb } from '#lib/server/state.js'; import { resolveFormFields } from '@when/config'; -import { createAppointment } from '#lib/server/appointment/create.js'; +import { createAppointment } from '#lib/server/appointment-operations.js'; import type { AppointmentRole } from '#lib/server/appointment/actions.js'; import { resolveBookingDurations, resolveDuration } from '#lib/server/appointment/duration.js'; import { @@ -14,7 +14,7 @@ import { import { appointmentContext } from '#lib/server/appointment/context.js'; import { normalizeDeepLinkParams } from '#lib/appointment.js'; import { toPublicEventType } from '#lib/server/appointment/sanitize.js'; -import { bookingAttemptsTotal } from '#lib/server/metrics.js'; +import { recordBookingOutcome } from '#lib/server/metrics/requests.js'; import type { Actions, PageServerLoad } from './$types'; export const load: PageServerLoad = async ({ params, url, locals }) => { @@ -81,20 +81,20 @@ export const actions: Actions = { const start = parseSlot(slotStr); if (!start) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'invalid_input' }); + recordBookingOutcome(params.slug, 'invalid_input'); return fail(400, { error: 'Please pick a time slot.' }); } const parsed = parseAndValidateAppointmentForm(eventType, form); if (!parsed.ok) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'invalid_input' }); + recordBookingOutcome(params.slug, 'invalid_input'); return fail(400, { fieldErrors: parsed.errors }); } const { name, email, answers, location: resolvedLocation } = parsed.data; const duration = resolveDuration(eventType, 'guest', form); if (duration === null) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'invalid_input' }); + recordBookingOutcome(params.slug, 'invalid_input'); return fail(400, { error: 'Please pick a valid meeting length.' }); } @@ -108,7 +108,7 @@ export const actions: Actions = { duration ); if (!bookable) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'slot_taken' }); + recordBookingOutcome(params.slug, 'slot_taken'); return fail(409, { error: 'That time is no longer available. Please pick another.' }); } @@ -131,7 +131,7 @@ export const actions: Actions = { initiator: 'guest' }); } catch (err) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'database_error' }); + recordBookingOutcome(params.slug, 'error'); logger.error( { err, eventTypeId: params.slug, slot: slotStr }, 'failed to insert appointment' @@ -139,12 +139,10 @@ export const actions: Actions = { return fail(500, { error: 'Could not save the appointment. Please try again.' }); } if (!created.ok) { - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'slot_taken' }); + recordBookingOutcome(params.slug, 'slot_taken'); return fail(409, { error: 'That time was just taken. Please pick another.' }); } - bookingAttemptsTotal.inc({ event_type_id: params.slug, status: 'success' }); - cookies.set('submitted', 'request', { path: '/', maxAge: 10, @@ -152,6 +150,7 @@ export const actions: Actions = { sameSite: 'lax' }); + recordBookingOutcome(params.slug, 'success'); redirect( 303, `/appointment/${created.appointment.id}?token=${encodeURIComponent(created.appointment.cancel_token)}` diff --git a/apps/web/src/routes/(app)/schedule/[slug]/server.test.ts b/apps/web/src/routes/(app)/schedule/[slug]/server.test.ts index 289d93ba..77279a00 100644 --- a/apps/web/src/routes/(app)/schedule/[slug]/server.test.ts +++ b/apps/web/src/routes/(app)/schedule/[slug]/server.test.ts @@ -4,6 +4,7 @@ import type { Meeting, WhenConfiguration } from '@when/config'; import type { AppointmentRole } from '#lib/server/appointment/actions.js'; import { resolveBookingDurations } from '#lib/server/appointment/duration.js'; import { toPublicEventType } from '#lib/server/appointment/sanitize.js'; +import { appointmentOperationsTotal, bookingAttemptsTotal } from '#lib/server/metrics/registry.js'; const h = vi.hoisted(() => ({ cfg: { current: null as unknown as WhenConfiguration }, @@ -76,6 +77,8 @@ async function caught(fn: () => unknown): Promise { beforeEach(() => { vi.clearAllMocks(); + appointmentOperationsTotal.reset(); + bookingAttemptsTotal.reset(); h.cfg.current = validConfig; h.resolveTimezone.mockReturnValue('UTC'); h.getDb.mockReturnValue(h.db); @@ -227,6 +230,7 @@ describe('/schedule/[slug] book action', () => { event.params.slug = 'missing'; const result = await caught(() => actions.default(event)); expect(result.status).toBe(404); + expect((await bookingAttemptsTotal.get()).values).toEqual([]); expect(h.isNewSlotBookable).not.toHaveBeenCalled(); expect(h.createAppointment).not.toHaveBeenCalled(); }); @@ -235,6 +239,9 @@ describe('/schedule/[slug] book action', () => { const response = await actions.default(bookEvent(new FormData())); const result = response as Failure; expect(result?.status).toBe(400); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'invalid_input' }, value: 1 }] + }); }); test.for(['not-a-time', '2099-13-45T99:99:99Z', '2099-05-01'])( @@ -252,6 +259,9 @@ describe('/schedule/[slug] book action', () => { h.parseForm.mockReturnValue({ ok: false, errors: { name: 'required' } }); const response = await actions.default(bookEvent(validForm())); expect((response as Failure)?.status).toBe(400); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'invalid_input' }, value: 1 }] + }); }); test('rejects an invalid duration with 400', async () => { @@ -259,6 +269,9 @@ describe('/schedule/[slug] book action', () => { h.resolveDuration.mockReturnValue(null); const response = await actions.default(bookEvent(validForm())); expect((response as Failure)?.status).toBe(400); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'invalid_input' }, value: 1 }] + }); expect(h.isNewSlotBookable).not.toHaveBeenCalled(); expect(h.createAppointment).not.toHaveBeenCalled(); }); @@ -270,6 +283,9 @@ describe('/schedule/[slug] book action', () => { const response = await actions.default(bookEvent(validForm())); const result = response as Failure; expect(result?.status).toBe(409); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'slot_taken' }, value: 1 }] + }); expect(h.isNewSlotBookable).toHaveBeenCalledExactlyOnceWith( h.db, h.cfg.current, @@ -358,6 +374,12 @@ describe('/schedule/[slug] book action', () => { initiator: 'guest' }) ); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'success' }, value: 1 }] + }); + expect(await appointmentOperationsTotal.get()).toMatchObject({ + values: [{ labels: { action: 'create', actor: 'guest', status: 'success' }, value: 1 }] + }); }); test('409s when the row insert loses the race (created not ok)', async () => { @@ -367,6 +389,12 @@ describe('/schedule/[slug] book action', () => { h.createAppointment.mockResolvedValue({ ok: false }); const response = await actions.default(bookEvent(validForm())); expect((response as Failure)?.status).toBe(409); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'slot_taken' }, value: 1 }] + }); + expect(await appointmentOperationsTotal.get()).toMatchObject({ + values: [{ labels: { action: 'create', actor: 'guest', status: 'rejected' }, value: 1 }] + }); }); test('500s when the insert throws', async () => { @@ -376,5 +404,11 @@ describe('/schedule/[slug] book action', () => { h.createAppointment.mockRejectedValue(new Error('db down')); const response = await actions.default(bookEvent(validForm())); expect((response as Failure)?.status).toBe(500); + expect(await bookingAttemptsTotal.get()).toMatchObject({ + values: [{ labels: { event_type_id: '30-min-chat', status: 'error' }, value: 1 }] + }); + expect(await appointmentOperationsTotal.get()).toMatchObject({ + values: [{ labels: { action: 'create', actor: 'guest', status: 'error' }, value: 1 }] + }); }); }); diff --git a/apps/web/src/routes/(auth)/admin/appointment/[id]/+page.server.ts b/apps/web/src/routes/(auth)/admin/appointment/[id]/+page.server.ts index 163acba8..9e542101 100644 --- a/apps/web/src/routes/(auth)/admin/appointment/[id]/+page.server.ts +++ b/apps/web/src/routes/(auth)/admin/appointment/[id]/+page.server.ts @@ -1,9 +1,11 @@ import { fail, redirect } from '@sveltejs/kit'; import { getConfig, getDb } from '#lib/server/state.js'; import { findAppointment, isChainTerminal } from '@when/db'; -import { acceptAppointment } from '#lib/server/appointment/accept.js'; -import { declineAppointment } from '#lib/server/appointment/decline.js'; -import { cancelAppointment } from '#lib/server/appointment/cancel.js'; +import { + acceptAppointment, + declineAppointment, + cancelAppointment +} from '#lib/server/appointment-operations.js'; import { purgeAppointment } from '#lib/server/appointment/purge.js'; import { editAppointment } from '#lib/server/appointment/edit.js'; import { changeAppointmentDuration } from '#lib/server/appointment/change-duration.js'; diff --git a/apps/web/src/routes/(auth)/admin/appointment/[id]/reschedule/+page.server.ts b/apps/web/src/routes/(auth)/admin/appointment/[id]/reschedule/+page.server.ts index dabc2869..59f75a91 100644 --- a/apps/web/src/routes/(auth)/admin/appointment/[id]/reschedule/+page.server.ts +++ b/apps/web/src/routes/(auth)/admin/appointment/[id]/reschedule/+page.server.ts @@ -3,7 +3,7 @@ import { findAppointment } from '@when/db'; import { getConfig, getDb } from '#lib/server/state.js'; import { isRescheduleSlotBookable } from '#lib/server/availability/booking.js'; import { resolveDuration } from '#lib/server/appointment/duration.js'; -import { rescheduleAppointment } from '#lib/server/appointment/reschedule.js'; +import { rescheduleAppointment } from '#lib/server/appointment-operations.js'; import { parseSlot, validateReason } from '#lib/server/appointment/form.server.js'; import { appointmentContext } from '#lib/server/appointment/context.js'; import type { Actions } from './$types'; diff --git a/apps/web/src/routes/(auth)/admin/appointments/+server.ts b/apps/web/src/routes/(auth)/admin/appointments/+server.ts index 2f316c4d..6d15c768 100644 --- a/apps/web/src/routes/(auth)/admin/appointments/+server.ts +++ b/apps/web/src/routes/(auth)/admin/appointments/+server.ts @@ -2,9 +2,11 @@ import { redirect } from '@sveltejs/kit'; import { getConfig, getDb } from '#lib/server/state.js'; import { findAppointment, isChainTerminal } from '@when/db'; import { purgeAppointment } from '#lib/server/appointment/purge.js'; -import { cancelAppointment } from '#lib/server/appointment/cancel.js'; -import { acceptAppointment } from '#lib/server/appointment/accept.js'; -import { declineAppointment } from '#lib/server/appointment/decline.js'; +import { + cancelAppointment, + acceptAppointment, + declineAppointment +} from '#lib/server/appointment-operations.js'; import { validateReason } from '#lib/server/appointment/form.server.js'; import { appointmentContext } from '#lib/server/appointment/context.js'; import { systemClock } from '#lib/server/clock.js'; diff --git a/apps/web/src/routes/(auth)/admin/appointments/server.test.ts b/apps/web/src/routes/(auth)/admin/appointments/server.test.ts index 759ba315..ead730b2 100644 --- a/apps/web/src/routes/(auth)/admin/appointments/server.test.ts +++ b/apps/web/src/routes/(auth)/admin/appointments/server.test.ts @@ -1,4 +1,5 @@ import { describe, expect, test, vi, beforeEach } from 'vitest'; +import { appointmentOperationsTotal } from '#lib/server/metrics/registry.js'; import type { RequestEvent } from './$types'; import { POST } from './+server'; import { validConfig } from '#lib/server/__fixtures__/valid-config.js'; @@ -124,6 +125,7 @@ vi.mock('#lib/server/appointment/decline.js', () => ({ describe('Admin Bulk Actions server actions', () => { beforeEach(() => { + appointmentOperationsTotal.reset(); mockPurgeAppointment.mockClear(); mockCancelAppointment.mockClear(); mockAcceptAppointment.mockClear(); @@ -207,6 +209,9 @@ describe('Admin Bulk Actions server actions', () => { }); expect(mockCancelAppointment).toHaveBeenCalledWith('appt-upcoming', 'Scheduling conflict'); + expect(await appointmentOperationsTotal.get()).toMatchObject({ + values: [{ labels: { action: 'cancel', actor: 'host', status: 'success' }, value: 1 }] + }); }); test('bulkCancel validation failure when reason is missing', async () => { diff --git a/apps/web/src/routes/(auth)/admin/schedule/[slug]/+page.server.ts b/apps/web/src/routes/(auth)/admin/schedule/[slug]/+page.server.ts index aac57db6..aae969c4 100644 --- a/apps/web/src/routes/(auth)/admin/schedule/[slug]/+page.server.ts +++ b/apps/web/src/routes/(auth)/admin/schedule/[slug]/+page.server.ts @@ -1,7 +1,7 @@ import { error, fail, redirect } from '@sveltejs/kit'; import { isNewSlotBookable } from '#lib/server/availability/booking.js'; import { getConfig, getDb } from '#lib/server/state.js'; -import { createAppointment } from '#lib/server/appointment/create.js'; +import { createAppointment } from '#lib/server/appointment-operations.js'; import { resolveDuration } from '#lib/server/appointment/duration.js'; import { parseAndValidateAppointmentForm, diff --git a/apps/web/src/routes/metrics/+server.ts b/apps/web/src/routes/metrics/+server.ts index c3e054fc..2c5dda8e 100644 --- a/apps/web/src/routes/metrics/+server.ts +++ b/apps/web/src/routes/metrics/+server.ts @@ -1,54 +1,15 @@ import { error } from '@sveltejs/kit'; -import { register } from '#lib/server/metrics.js'; +import { collectMetricsResponse } from '#lib/server/metrics/scrape.js'; import { getConfig } from '#lib/server/state.js'; -import { logger } from '#lib/server/logger.js'; import type { RequestHandler } from './$types'; export const GET: RequestHandler = async ({ request, fetch }) => { const config = getConfig(); - - if (!config.prometheus.enabled) { - error(404); - } - + if (!config.prometheus.enabled) error(404); const token = config.prometheus.token; - if (!token) { - return new Response('prometheus.token not configured', { status: 500 }); - } - - const auth = request.headers.get('authorization'); - const expected = `Bearer ${token}`; - if (!auth || auth !== expected) { + if (!token) return new Response('prometheus.token not configured', { status: 500 }); + if (request.headers.get('authorization') !== `Bearer ${token}`) { return new Response('Unauthorized', { status: 401 }); } - - const webMetrics = await register.metrics(); - let workerMetrics = ''; - - try { - const res = await fetch(`${config.url.worker}/metrics`, { - headers: { - authorization: `Bearer ${token}` - }, - signal: AbortSignal.timeout(2000) - }); - - if (res.ok) { - const text = await res.text(); - // Strip duplicate Prometheus headers (# HELP / # TYPE comments) from the worker payload - workerMetrics = text.replace(/^#[^\r\n]*[\r\n]*/gm, ''); - } else { - logger.warn({ status: res.status }, 'Failed to fetch worker metrics'); - } - } catch (err) { - logger.warn({ err }, 'Error fetching worker metrics'); - } - - // Combine web and worker metrics gracefully - const body = [webMetrics, workerMetrics].filter(Boolean).join('\n'); - - return new Response(body, { - status: 200, - headers: { 'content-type': register.contentType } - }); + return collectMetricsResponse(fetch, config.url.worker, token); }; diff --git a/apps/web/src/routes/metrics/server.test.ts b/apps/web/src/routes/metrics/server.test.ts index d5319300..2b2bf6d9 100644 --- a/apps/web/src/routes/metrics/server.test.ts +++ b/apps/web/src/routes/metrics/server.test.ts @@ -1,123 +1,267 @@ -import { describe, expect, test, vi } from 'vitest'; +import { beforeEach, expect, test, vi } from 'vitest'; +import { Counter, Histogram, Registry } from '@prometheus-io/client'; import type { RequestEvent } from './$types'; import { GET } from './+server'; -import { register } from '#lib/server/metrics.js'; +import { + appointmentOperationsTotal, + operationFailuresTotal, + register +} from '#lib/server/metrics/registry.js'; const mockConfig = { - prometheus: { - enabled: true, - token: 'metrics-secret' - }, - url: { - worker: 'http://when-worker:9000' - } + prometheus: { enabled: true, token: 'metrics-secret' }, + url: { worker: 'http://when-worker:9000' } }; +vi.mock('#lib/server/state.js', () => ({ getConfig: () => mockConfig })); +vi.mock('#lib/server/logger.js', () => ({ logger: { warn: vi.fn() } })); -vi.mock('#lib/server/state.js', () => ({ - getConfig: () => mockConfig -})); +beforeEach(() => { + vi.clearAllMocks(); + mockConfig.prometheus.enabled = true; + mockConfig.prometheus.token = 'metrics-secret'; + operationFailuresTotal.reset(); + appointmentOperationsTotal.reset(); +}); -describe('GET /metrics scrape aggregator endpoint', () => { - test('returns 404 if prometheus is disabled', async () => { - mockConfig.prometheus.enabled = false; +function event(fetch: RequestEvent['fetch'], token = 'metrics-secret'): RequestEvent { + return { + request: new Request('http://when.example.test/metrics', { + headers: { authorization: `Bearer ${token}` } + }), + fetch + } as RequestEvent; +} - const mockRequest = { - headers: { - get: () => 'Bearer metrics-secret' - } - } as unknown as Request; +async function workerSnapshot() { + const worker = new Registry(); + worker.setDefaultLabels({ app: 'when', service: 'worker' }); + new Counter({ + name: 'when_appointment_operations_total', + help: 'Appointment operation outcomes, not committed changes.', + labelNames: ['action', 'actor', 'status'], + registers: [worker] + }).inc({ action: 'expire', actor: 'system', status: 'success' }); + new Counter({ + name: 'when_jobs_total', + help: 'Handler executions.', + labelNames: ['job_name', 'status'], + registers: [worker] + }).inc({ job_name: 'deliverEmail', status: 'returned' }, 12); + new Histogram({ + name: 'when_job_duration_seconds', + help: 'Handler duration.', + buckets: [1], + registers: [worker] + }).observe(0.5); + return worker.getMetricsAsJSON(); +} - await expect( - GET({ - request: mockRequest, - fetch: vi.fn() - } as unknown as RequestEvent) - ).rejects.toThrow(); - }); +test('returns 404 if prometheus is disabled without contacting the worker', async () => { + mockConfig.prometheus.enabled = false; + const fetch = vi.fn(); + await expect(GET(event(fetch))).rejects.toMatchObject({ status: 404 }); + expect(fetch).not.toHaveBeenCalled(); +}); - test('returns 401 if unauthorized', async () => { - mockConfig.prometheus.enabled = true; +test('returns 401 if unauthorized without contacting the worker', async () => { + const fetch = vi.fn(); + const response = await GET(event(fetch, 'wrong-secret')); + expect(response.status).toBe(401); + expect(fetch).not.toHaveBeenCalled(); +}); - const mockRequest = { - headers: { - get: (h: string) => (h === 'authorization' ? 'Bearer wrong-secret' : null) - } - } as unknown as Request; +test('returns 500 if enabled without a token', async () => { + mockConfig.prometheus.token = ''; + const fetch = vi.fn(); + expect((await GET(event(fetch))).status).toBe(500); + expect(fetch).not.toHaveBeenCalled(); +}); - const res = await GET({ - request: mockRequest, - fetch: vi.fn() - } as unknown as RequestEvent); - - expect(res.status).toBe(401); - const text = await res.text(); - expect(text).toBe('Unauthorized'); - }); - - test('returns 200 with merged metrics and stripped worker comments on success', async () => { - mockConfig.prometheus.enabled = true; - - const mockRequest = { - headers: { - get: (h: string) => (h === 'authorization' ? 'Bearer metrics-secret' : null) - } - } as unknown as Request; - - const mockFetch = vi.fn().mockResolvedValue({ - ok: true, - text: async () => - `# HELP when_jobs_total Total jobs.\n# TYPE when_jobs_total counter\nwhen_jobs_total{job_name="sendAppointmentEmail",status="returned"} 12` - }); - - const res = await GET({ - request: mockRequest, - fetch: mockFetch - } as unknown as RequestEvent); - - expect(res.status).toBe(200); - expect(res.headers.get('content-type')).toBe(register.contentType); - - const text = await res.text(); - // Web metrics should be present - expect(text).toContain('process_resident_memory_bytes'); - // Custom web metrics should be present - expect(text).toContain('when_booking_attempts_total'); - // Worker metrics should be present - expect(text).toContain('when_jobs_total'); - expect(text).toContain('status="returned"'); - // Helper/type comments from worker metrics must be stripped - expect(text).not.toContain('# HELP when_jobs_total'); - expect(text).not.toContain('# TYPE when_jobs_total'); - - expect(mockFetch).toHaveBeenCalledWith('http://when-worker:9000/metrics', { - headers: { - authorization: 'Bearer metrics-secret' - }, - signal: expect.any(AbortSignal) - }); - }); - - test('returns web-only metrics if worker fetch fails', async () => { - mockConfig.prometheus.enabled = true; - - const mockRequest = { - headers: { - get: (h: string) => (h === 'authorization' ? 'Bearer metrics-secret' : null) - } - } as unknown as Request; - - const mockFetch = vi.fn().mockRejectedValue(new Error('Connection refused')); - - const res = await GET({ - request: mockRequest, - fetch: mockFetch - } as unknown as RequestEvent); - - expect(res.status).toBe(200); - const text = await res.text(); - // Web metrics should still be served - expect(text).toContain('process_resident_memory_bytes'); - // Worker metrics are not present - expect(text).not.toContain('when_jobs_total'); +test('natively aggregates JSON snapshots with service labels and histogram metadata intact', async () => { + appointmentOperationsTotal.inc({ action: 'create', actor: 'guest', status: 'success' }); + const fetch = vi.fn().mockResolvedValue(Response.json(await workerSnapshot())); + const response = await GET(event(fetch)); + const text = await response.text(); + expect(response.status).toBe(200); + expect(response.headers.get('content-type')).toBe(register.contentType); + expect(text).toContain('when_booking_attempts_total'); + const lines = text.split('\n'); + const changes = lines.filter((line) => line.startsWith('when_appointment_operations_total{')); + expect(changes).toHaveLength(2); + const webChange = changes.find((line) => line.includes('service="web"')); + const workerChange = changes.find((line) => line.includes('service="worker"')); + expect(webChange).toContain('action="create"'); + expect(webChange).toContain('actor="guest"'); + expect(webChange).toContain('status="success"'); + expect(webChange).toContain('app="when"'); + expect(webChange).toMatch(/\} 1$/); + expect(workerChange).toContain('action="expire"'); + expect(workerChange).toContain('actor="system"'); + expect(workerChange).toContain('status="success"'); + expect(workerChange).toContain('app="when"'); + expect(workerChange).toMatch(/\} 1$/); + expect( + lines.filter( + (line) => + line === + '# HELP when_appointment_operations_total Appointment operation outcomes, not committed changes.' + ) + ).toHaveLength(1); + expect(text.match(/^# TYPE when_appointment_operations_total counter$/gm) ?? []).toHaveLength(1); + expect(text).toContain('# HELP when_jobs_total Handler executions.'); + expect(text).toContain('# TYPE when_jobs_total counter'); + expect(text).toContain('job_name="deliverEmail",status="returned"'); + expect(text).toContain('# HELP when_job_duration_seconds Handler duration.'); + expect(text).toContain('# TYPE when_job_duration_seconds histogram'); + expect(text).toMatch(/^when_job_duration_seconds_bucket\{[^}]*le="1"[^}]*\} 1$/m); + expect(text).toMatch(/^when_job_duration_seconds_bucket\{[^}]*le="\+Inf"[^}]*\} 1$/m); + expect(text).toMatch(/when_job_duration_seconds_sum\{[^\n]*\} 0\.5/); + expect(text).toMatch(/when_job_duration_seconds_count\{[^\n]*\} 1/); + expect(text).toMatch(/when_worker_scrape_success\{[^\n]*\} 1/); + expect(fetch).toHaveBeenCalledWith('http://when-worker:9000/metrics', { + headers: { authorization: 'Bearer metrics-secret', accept: 'application/json' }, + signal: expect.any(AbortSignal) }); }); + +test.each([ + { + name: 'unauthorized worker', + code: 'unauthorized', + reply: () => Promise.resolve(new Response('Unauthorized', { status: 401 })) + }, + { + name: 'HTTP error', + code: 'http_error', + reply: () => Promise.resolve(new Response('Unavailable', { status: 503 })) + }, + { + name: 'malformed JSON', + code: 'invalid_snapshot', + reply: () => Promise.resolve(new Response('not JSON')) + }, + { + name: 'non-array snapshot', + code: 'invalid_snapshot', + reply: () => Promise.resolve(Response.json({ unexpected: true })) + }, + { + name: 'null sample', + code: 'invalid_snapshot', + reply: () => + Promise.resolve( + Response.json([ + { + name: 'bad', + help: 'bad', + type: 'gauge', + aggregator: 'sum', + values: [{ labels: { app: 'when', service: 'worker' }, value: null }] + } + ]) + ) + }, + { + name: 'unsupported metric type', + code: 'invalid_snapshot', + reply: async () => { + const [metric] = await workerSnapshot(); + return Response.json([{ ...metric, type: 'unsupported' }]); + } + }, + { + name: 'numeric string sample', + code: 'invalid_snapshot', + reply: async () => { + const [metric] = await workerSnapshot(); + return Response.json([ + { ...metric, values: metric.values.map((sample) => ({ ...sample, value: '1' })) } + ]); + } + }, + { + name: 'conflicting web and worker types', + code: 'invalid_snapshot', + reply: async () => { + const [metric] = await workerSnapshot(); + return Response.json([{ ...metric, type: 'gauge' }]); + } + }, + { + name: 'fetch timeout', + code: 'timeout', + reply: () => Promise.reject(new DOMException('Timed out', 'TimeoutError')) + }, + { + name: 'fetch connection failure', + code: 'transport_error', + reply: () => Promise.reject(new Error('Connection failed')) + }, + { + name: 'body timeout after successful headers', + code: 'timeout', + reply: () => + Promise.resolve( + new Response( + new ReadableStream({ + start(controller) { + controller.error(new DOMException('Timed out', 'TimeoutError')); + } + }) + ) + ) + }, + { + name: 'interrupted body after successful headers', + code: 'transport_error', + reply: () => + Promise.resolve( + new Response( + new ReadableStream({ + start(controller) { + controller.error(new TypeError('Body connection interrupted')); + } + }) + ) + ) + } +])('returns truthful web-only metrics for $name', async ({ code, reply }) => { + const response = await GET(event(vi.fn().mockImplementation(reply))); + const text = await response.text(); + expect(response.status).toBe(200); + expect(text).toContain('when_booking_attempts_total'); + expect(text).not.toContain('when_jobs_total'); + expect(text).toMatch(/when_worker_scrape_success\{[^\n]*\} 0/); + const failure = text + .split('\n') + .find( + (line) => line.startsWith('when_operation_failures_total{') && line.includes(`code="${code}"`) + ); + expect(failure).toContain('operation="worker_scrape"'); + expect(failure).toMatch(/\} 1$/); +}); + +test('collects web metrics during a worker request and keeps overlapping scrapes independent', async () => { + let release!: (response: Response) => void; + const delayed = new Promise((resolve) => { + release = resolve; + }); + const collectWeb = vi.spyOn(register, 'getMetricsAsJSON'); + try { + const first = GET(event(vi.fn().mockReturnValue(delayed))); + const webCollectionsWhileWorkerPending = collectWeb.mock.calls.length; + const healthy = await GET( + event(vi.fn().mockResolvedValue(Response.json(await workerSnapshot()))) + ); + release(new Response('Unavailable', { status: 503 })); + const failed = await first; + const failedText = await failed.text(); + expect(webCollectionsWhileWorkerPending).toBe(1); + expect(await healthy.text()).toMatch(/when_worker_scrape_success\{[^\n]*\} 1/); + expect(failedText).toMatch(/when_worker_scrape_success\{[^\n]*\} 0/); + expect(failedText).toMatch(/^when_operation_failures_total\{[^}]*code="http_error"[^}]*\} 1$/m); + } finally { + release(new Response('Unavailable', { status: 503 })); + collectWeb.mockRestore(); + } +}); diff --git a/apps/worker/eslint.config.js b/apps/worker/eslint.config.js index 239a9738..98b92886 100644 --- a/apps/worker/eslint.config.js +++ b/apps/worker/eslint.config.js @@ -8,6 +8,24 @@ export default ts.config( js.configs.recommended, ...ts.configs.recommended, prettier, + { + files: ['src/**/*.ts'], + ignores: ['src/metrics/**', 'src/**/*.test.ts'], + rules: { + 'no-restricted-imports': [ + 'error', + { + patterns: [ + { + group: ['@prometheus-io/client', '@prometheus-io/client/*', '**/metrics/registry*'], + message: + 'Keep Prometheus details inside metrics; wire an operation observer at the service boundary.' + } + ] + } + ] + } + }, { languageOptions: { globals: { ...globals.node } }, rules: { diff --git a/apps/worker/package.json b/apps/worker/package.json index f445647d..c9d5b473 100644 --- a/apps/worker/package.json +++ b/apps/worker/package.json @@ -19,6 +19,7 @@ "test:coverage": "vitest run --coverage" }, "dependencies": { + "@prometheus-io/client": "0.16.1", "@when/calendar": "workspace:*", "@when/config": "workspace:*", "@when/db": "workspace:*", @@ -29,7 +30,6 @@ "nodemailer": "9.0.3", "openworkflow": "0.11.0", "pino": "10.3.1", - "prom-client": "15.1.3", "ts-ics": "2.4.4" }, "devDependencies": { diff --git a/apps/worker/src/calendar/reconcile.ts b/apps/worker/src/calendar/reconcile.ts new file mode 100644 index 00000000..0b1f3251 --- /dev/null +++ b/apps/worker/src/calendar/reconcile.ts @@ -0,0 +1,144 @@ +import { deleteAppointmentFromCalendar, pushAppointment } from '../services/calendar-provider.js'; +import { findCalendar } from '@when/config'; +import { + findAppointment, + listActiveAppointmentsForCalendarEvent, + markSynced, + recordCalendarEventDeletion, + recordCalendarEventReference, + recordServiceOutcome, + type Appointment, + type CalendarEventReference +} from '@when/db'; +import type { WorkerContext } from '../services/context.js'; +import { appointmentLinks } from '../links.js'; +import { appendJobLog, markCalendarFailing } from '../services/job-log.js'; + +export async function reconcileAppointment(ctx: WorkerContext, row: Appointment): Promise { + if (row.status === 'purged') return; + const target = + row.external_calendar_id ?? ctx.config.meetings[row.event_type_id]?.booking_calendar ?? null; + if (row.status === 'confirmed') { + await publishCalendarContent(ctx, row, target); + } else if (row.status === 'cancelled' || row.status === 'declined' || row.status === 'expired') { + await removeCalendarEvent(ctx, row); + } else { + // Pending and rescheduled occurrences keep their inherited event. + await acknowledgeCalendarContent(ctx, row); + } +} + +async function publishCalendarContent( + ctx: WorkerContext, + row: Appointment, + target: string | null +): Promise { + if (!target) { + await acknowledgeCalendarContent(ctx, row); + return; + } + const cancelUrl = appointmentLinks({ baseUrl: ctx.config.url.app, appointment: row }).booked; + const pushed = await pushAppointment(ctx.config, row, target, { cancelUrl }); + if (!pushed.ok) { + await recordCalendarFailure(ctx, row, target, pushed.reason, 'calendar_write'); + return; + } + if (pushed.externalCalendarId && pushed.externalEventId) { + const reference = { calendarId: pushed.externalCalendarId, eventId: pushed.externalEventId }; + await recordCalendarEventReference(ctx.db, row.id, reference); + await markSynced(ctx.db, row.id, row.calendar_revision, reference); + } + await recordCalendarSuccess(ctx, row.id, target); +} + +async function removeCalendarEvent(ctx: WorkerContext, row: Appointment): Promise { + if (!row.external_calendar_id || !row.external_event_id) { + await acknowledgeCalendarContent(ctx, row); + return; + } + const reference = { calendarId: row.external_calendar_id, eventId: row.external_event_id }; + const allowed = await canDeleteCalendarEvent(ctx, row, reference); + if (!allowed) return; + const deleted = await deleteAppointmentFromCalendar( + ctx.config, + reference.calendarId, + reference.eventId + ); + if (!deleted.ok) { + await recordCalendarFailure(ctx, row, reference.calendarId, deleted.reason, 'calendar_delete'); + return; + } + await recordCalendarEventDeletion(ctx.db, row.id, row.calendar_revision, reference); + await recordCalendarSuccess(ctx, row.id, reference.calendarId); +} + +async function canDeleteCalendarEvent( + ctx: WorkerContext, + row: Appointment, + reference: CalendarEventReference +): Promise { + const current = await findAppointment(ctx.db, row.id); + if ( + !current || + current.status !== row.status || + current.calendar_revision !== row.calendar_revision || + current.external_calendar_id !== reference.calendarId || + current.external_event_id !== reference.eventId + ) + return false; + const active = await listActiveAppointmentsForCalendarEvent(ctx.db, reference); + return !active.some((appointment) => appointment.id !== row.id); +} + +async function acknowledgeCalendarContent(ctx: WorkerContext, row: Appointment): Promise { + await markSynced(ctx.db, row.id, row.calendar_revision, { + calendarId: row.external_calendar_id, + eventId: row.external_event_id + }); +} + +async function recordCalendarSuccess( + ctx: WorkerContext, + appointmentId: string, + calendarName: string +): Promise { + await appendJobLog(ctx.db, appointmentId, 'calendar', 'done', Temporal.Now.instant().toString()); + await recordCalendarOutcome(ctx, calendarName, null); +} + +async function recordCalendarFailure( + ctx: WorkerContext, + row: Appointment, + calendarName: string, + reason: string | undefined, + operation: 'calendar_write' | 'calendar_delete' +): Promise { + const code = findCalendar(ctx.config, calendarName) ? 'provider_error' : 'not_configured'; + await markCalendarFailing(ctx.db, row, Temporal.Now.instant().toString()); + await recordCalendarOutcome(ctx, calendarName, reason); + ctx.logger.error( + { appointmentId: row.id, operation, code, reason }, + 'calendar sync failed; will retry next scan' + ); +} + +async function recordCalendarOutcome( + ctx: WorkerContext, + calendarName: string, + error: string | null | undefined +): Promise { + const at = Temporal.Now.instant().toString(); + await recordServiceOutcome( + ctx.db, + { kind: 'calendar', name: calendarName }, + { at, via: 'push', error } + ); + const provider = findCalendar(ctx.config, calendarName)?.providerName; + if (provider) { + await recordServiceOutcome( + ctx.db, + { kind: 'provider', name: provider }, + { at, via: 'push', error } + ); + } +} diff --git a/apps/worker/src/calendar/refresh-calendar.ts b/apps/worker/src/calendar/refresh-calendar.ts new file mode 100644 index 00000000..114ff016 --- /dev/null +++ b/apps/worker/src/calendar/refresh-calendar.ts @@ -0,0 +1,89 @@ +import { type ResolvedCalendar, type WhenConfiguration } from '@when/config'; +import type { BusyWindow, Interval } from '@when/calendar'; +import { busyCalendarsFor } from '@when/calendar'; +import { fetchBusyIntervals } from '../services/calendar-provider.js'; +import { + listOwnEventIds, + recordServiceOutcome, + replaceCalendarBusy, + type ServiceOutcome +} from '@when/db'; +import type { WorkerContext } from '../services/context.js'; + +const DEFAULT_MAX_LOOKAHEAD_DAYS = 60; + +export interface RefreshOptions { + now?: Temporal.Instant; + via?: ServiceOutcome['via']; +} + +export type RefreshResult = { ok: true; busyCount: number } | { ok: false; error: string }; + +export function busyCalendarIds(config: WhenConfiguration): string[] { + const ids = new Set(); + for (const meeting of Object.values(config.meetings)) { + for (const name of busyCalendarsFor(meeting)) ids.add(name); + } + return [...ids]; +} + +export function refreshWindow( + config: WhenConfiguration, + calendarId: string, + now: Temporal.Instant +): BusyWindow { + let days = 0; + for (const meeting of Object.values(config.meetings)) { + if (!busyCalendarsFor(meeting).includes(calendarId)) continue; + const lookahead = meeting.booking_window_days; + days = Math.max(days, lookahead); + } + if (days === 0) days = DEFAULT_MAX_LOOKAHEAD_DAYS; + return { start: now, end: now.add({ hours: 24 * days }) }; +} + +export async function refreshCalendar( + ctx: WorkerContext, + cal: ResolvedCalendar, + window: BusyWindow, + opts: RefreshOptions = {} +): Promise { + const at = (opts.now ?? window.start).toString(); + const via = opts.via ?? 'refresh'; + const ownEventIds = await listOwnEventIds(ctx.db, cal.name); + const excludeUids = new Set(ownEventIds); + let intervals: Interval[]; + try { + intervals = await fetchBusyIntervals(cal, window, { excludeUids }); + } catch (err) { + const error = err instanceof Error ? err.message : String(err); + ctx.logger.error( + { + calendarId: cal.name, + error + }, + 'calendar refresh failed; keeping stale busy times' + ); + await recordRefreshOutcome(ctx, cal, { at, via, error }); + + return { ok: false, error }; + } + await replaceCalendarBusy( + ctx.db, + cal.name, + intervals.map((i) => ({ start: i.start.toString(), end: i.end.toString() })) + ); + await recordRefreshOutcome(ctx, cal, { at, via }); + + return { ok: true, busyCount: intervals.length }; +} + +// A provider backing no calendars has no other source of status. +async function recordRefreshOutcome( + ctx: WorkerContext, + cal: ResolvedCalendar, + outcome: ServiceOutcome +): Promise { + await recordServiceOutcome(ctx.db, { kind: 'calendar', name: cal.name }, outcome); + await recordServiceOutcome(ctx.db, { kind: 'provider', name: cal.providerName }, outcome); +} diff --git a/apps/worker/src/calendar/refresh.test.ts b/apps/worker/src/calendar/refresh.test.ts index 9143fcb1..6e180903 100644 --- a/apps/worker/src/calendar/refresh.test.ts +++ b/apps/worker/src/calendar/refresh.test.ts @@ -1,3 +1,5 @@ +import { busyCalendarIds, refreshWindow } from './refresh-calendar.js'; +import { refreshCalendar } from '../services/calendar.js'; import { expect, test, vi, beforeEach } from 'vitest'; import pino from 'pino'; import { sql } from 'kysely'; @@ -5,14 +7,7 @@ import type { ResolvedCalendar, WhenConfiguration } from '@when/config'; import { openDb, runMigrations, replaceCalendarBusy, recordServiceOutcome } from '@when/db'; import type { Logger } from '../services/logger.js'; import type { WorkerContext } from '../services/context.js'; -import { calendarRefreshTotal } from '../services/metrics.js'; -import { - busyCalendarIds, - refreshCalendar, - refreshCalendars, - refreshCycle, - refreshWindow -} from './refresh.js'; +import { refreshCalendars, refreshCycle } from './refresh.js'; const inst = (s: string) => Temporal.Instant.from(s); const window = { start: inst('2026-04-01T00:00:00Z'), end: inst('2026-05-01T00:00:00Z') }; @@ -107,14 +102,10 @@ test('refreshCalendar populates the mirror and records success', async () => { vi.spyOn(globalThis, 'fetch').mockResolvedValue( new Response(oneEvent('remote-1@x'), { status: 207 }) ); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); + const result = await refreshCalendar(ctx, workCal, window, { now: window.start }); expect(result).toEqual({ ok: true, busyCount: 1 }); - expect(metric).toHaveBeenCalledExactlyOnceWith({ - calendar_id: 'work', - provider_type: 'caldav', - status: 'success' - }); + const busy = await ctx.db.selectFrom('external_calendar_busy').selectAll().execute(); expect(busy).toHaveLength(1); expect(busy[0].start_time).toBe('2026-04-15T14:00:00Z'); @@ -146,14 +137,10 @@ test('refreshCalendar keeps stale data and records the error on provider failure vi.spyOn(globalThis, 'fetch').mockResolvedValue( new Response('boom', { status: 500, statusText: 'err' }) ); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); + const result = await refreshCalendar(ctx, workCal, window, { now: window.start, via: 'test' }); expect(result).toEqual({ ok: false, error: expect.stringContaining('500') }); - expect(metric).toHaveBeenCalledExactlyOnceWith({ - calendar_id: 'work', - provider_type: 'caldav', - status: 'failure' - }); + const busy = await ctx.db.selectFrom('external_calendar_busy').selectAll().execute(); expect(busy).toHaveLength(1); expect(busy[0].start_time).toBe('2026-04-10T09:00:00Z'); @@ -687,13 +674,12 @@ test('refreshCalendar lets the own-event DB read fail before fetching or recordi await ctx.db.schema.dropTable('appointments').execute(); const fetch = vi.spyOn(globalThis, 'fetch'); const log = vi.spyOn(ctx.logger, 'error'); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); await expect(refreshCalendar(ctx, workCal, window)).rejects.toThrow('no such table'); expect(fetch).not.toHaveBeenCalled(); expect(log).not.toHaveBeenCalled(); - expect(metric).not.toHaveBeenCalled(); + const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); expect(statuses).toEqual([]); } finally { @@ -710,12 +696,11 @@ test('refreshCalendar rejects a mirror replacement failure without recording pro begin select raise(abort, 'mirror unavailable'); end`.execute(ctx.db); vi.spyOn(globalThis, 'fetch').mockResolvedValue(new Response(oneEvent('r1'), { status: 207 })); const log = vi.spyOn(ctx.logger, 'error'); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); await expect(refreshCalendar(ctx, workCal, window)).rejects.toThrow('mirror unavailable'); expect(log).not.toHaveBeenCalled(); - expect(metric).not.toHaveBeenCalled(); + const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); expect(statuses).toEqual([]); const busy = await ctx.db @@ -740,12 +725,11 @@ test.each(['calendar', 'provider'] as const)( new Response(oneEvent('r1'), { status: 207 }) ); const log = vi.spyOn(ctx.logger, 'error'); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); await expect(refreshCalendar(ctx, workCal, window)).rejects.toThrow('status unavailable'); expect(log).not.toHaveBeenCalled(); - expect(metric).not.toHaveBeenCalled(); + const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); expect(statuses).toHaveLength(kind === 'provider' ? 1 : 0); for (const status of statuses) { @@ -760,39 +744,14 @@ test.each(['calendar', 'provider'] as const)( } ); -test('refreshCalendar lets a success metric failure escape without recording provider failure', async () => { - const ctx = await ctxWithDb(); - try { - vi.spyOn(globalThis, 'fetch').mockResolvedValue(new Response(oneEvent('r1'), { status: 207 })); - const error = new Error('metric unavailable'); - const metric = vi.spyOn(calendarRefreshTotal, 'inc').mockImplementationOnce(() => { - throw error; - }); - const log = vi.spyOn(ctx.logger, 'error'); - - await expect(refreshCalendar(ctx, workCal, window)).rejects.toBe(error); - - expect(log).not.toHaveBeenCalled(); - expect(metric).toHaveBeenCalledTimes(1); - const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); - expect(statuses).toHaveLength(2); - for (const status of statuses) expect(status.error).toBeNull(); - } finally { - await ctx.db.destroy(); - } -}); - test('refreshCalendar rejects if recording an expected provider failure fails locally', async () => { const ctx = await ctxWithDb(); try { await sql`create trigger fail_status before insert on service_status begin select raise(abort, 'status unavailable'); end`.execute(ctx.db); vi.spyOn(globalThis, 'fetch').mockResolvedValue(new Response('boom', { status: 500 })); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); await expect(refreshCalendar(ctx, workCal, window)).rejects.toThrow('status unavailable'); - - expect(metric).not.toHaveBeenCalled(); } finally { await ctx.db.destroy(); } @@ -860,16 +819,11 @@ test('refreshCycle lets conflict writes fail without marking a successful provid begin select raise(abort, 'conflict unavailable'); end`.execute(ctx.db); vi.spyOn(globalThis, 'fetch').mockResolvedValue(new Response(oneEvent('r1'), { status: 207 })); const log = vi.spyOn(ctx.logger, 'error'); - const metric = vi.spyOn(calendarRefreshTotal, 'inc'); await expect(refreshCycle(ctx, { now: window.start })).rejects.toThrow('conflict unavailable'); expect(log).not.toHaveBeenCalled(); - expect(metric).toHaveBeenCalledExactlyOnceWith({ - calendar_id: 'work', - provider_type: 'caldav', - status: 'success' - }); + const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); expect(statuses).toHaveLength(2); for (const status of statuses) { diff --git a/apps/worker/src/calendar/refresh.ts b/apps/worker/src/calendar/refresh.ts index 6ee5bab5..4532984b 100644 --- a/apps/worker/src/calendar/refresh.ts +++ b/apps/worker/src/calendar/refresh.ts @@ -1,104 +1,10 @@ -import { findCalendar, type ResolvedCalendar, type WhenConfiguration } from '@when/config'; -import type { BusyWindow, Interval } from '@when/calendar'; -import { busyCalendarsFor, fetchBusyIntervals } from '@when/calendar'; -import { - listOwnEventIds, - listServiceStatus, - lastCalendarRefreshAt, - recordServiceOutcome, - replaceCalendarBusy, - type ServiceOutcome -} from '@when/db'; +import { findCalendar, type ResolvedCalendar } from '@when/config'; +import { listServiceStatus, lastCalendarRefreshAt } from '@when/db'; import type { WorkerContext } from '../services/context.js'; -import { calendarRefreshTotal } from '../services/metrics.js'; +import { refreshCalendar } from '../services/calendar.js'; +import { busyCalendarIds, refreshWindow, type RefreshOptions } from './refresh-calendar.js'; import { flagConflicts } from './conflicts.js'; -const DEFAULT_MAX_LOOKAHEAD_DAYS = 60; - -export interface RefreshOptions { - now?: Temporal.Instant; - via?: ServiceOutcome['via']; -} - -export type RefreshResult = { ok: true; busyCount: number } | { ok: false; error: string }; - -export function busyCalendarIds(config: WhenConfiguration): string[] { - const ids = new Set(); - for (const meeting of Object.values(config.meetings)) { - for (const name of busyCalendarsFor(meeting)) ids.add(name); - } - return [...ids]; -} - -export function refreshWindow( - config: WhenConfiguration, - calendarId: string, - now: Temporal.Instant -): BusyWindow { - let days = 0; - for (const meeting of Object.values(config.meetings)) { - if (!busyCalendarsFor(meeting).includes(calendarId)) continue; - const lookahead = meeting.booking_window_days; - days = Math.max(days, lookahead); - } - if (days === 0) days = DEFAULT_MAX_LOOKAHEAD_DAYS; - return { start: now, end: now.add({ hours: 24 * days }) }; -} - -export async function refreshCalendar( - ctx: WorkerContext, - cal: ResolvedCalendar, - window: BusyWindow, - opts: RefreshOptions = {} -): Promise { - const at = (opts.now ?? window.start).toString(); - const via = opts.via ?? 'refresh'; - const ownEventIds = await listOwnEventIds(ctx.db, cal.name); - const excludeUids = new Set(ownEventIds); - let intervals: Interval[]; - try { - intervals = await fetchBusyIntervals(cal, window, { excludeUids }); - } catch (err) { - const error = err instanceof Error ? err.message : String(err); - ctx.logger.error( - { - calendarId: cal.name, - error - }, - 'calendar refresh failed; keeping stale busy times' - ); - await recordRefreshOutcome(ctx, cal, { at, via, error }); - calendarRefreshTotal.inc({ - calendar_id: cal.name, - provider_type: cal.provider.type, - status: 'failure' - }); - return { ok: false, error }; - } - await replaceCalendarBusy( - ctx.db, - cal.name, - intervals.map((i) => ({ start: i.start.toString(), end: i.end.toString() })) - ); - await recordRefreshOutcome(ctx, cal, { at, via }); - calendarRefreshTotal.inc({ - calendar_id: cal.name, - provider_type: cal.provider.type, - status: 'success' - }); - return { ok: true, busyCount: intervals.length }; -} - -// A provider backing no calendars has no other source of status. -async function recordRefreshOutcome( - ctx: WorkerContext, - cal: ResolvedCalendar, - outcome: ServiceOutcome -): Promise { - await recordServiceOutcome(ctx.db, { kind: 'calendar', name: cal.name }, outcome); - await recordServiceOutcome(ctx.db, { kind: 'provider', name: cal.providerName }, outcome); -} - export async function refreshCalendars( ctx: WorkerContext, opts: RefreshOptions = {} diff --git a/apps/worker/src/calendar/sync.test.ts b/apps/worker/src/calendar/sync.test.ts index 0a67be72..b08d1df8 100644 --- a/apps/worker/src/calendar/sync.test.ts +++ b/apps/worker/src/calendar/sync.test.ts @@ -4,7 +4,8 @@ import type { WhenConfiguration } from '@when/config'; import { openDb, runMigrations, listOutOfSyncAppointments, parseActionLog } from '@when/db'; import type { Logger } from '../services/logger.js'; import type { WorkerContext } from '../services/context.js'; -import { reconcileAppointment, scanOnce } from './sync.js'; +import { reconcileAppointment } from '../services/calendar.js'; +import { scanOnce } from '../services/calendar-scan.js'; import { cleanupAppointmentVideoChat } from '../services/video-chat-cleanup.js'; vi.mock('../services/video-chat-cleanup.js', () => ({ @@ -70,6 +71,7 @@ function recordingFetch(status = 204) { beforeEach(() => { vi.restoreAllMocks(); + vi.mocked(cleanupAppointmentVideoChat).mockReset().mockResolvedValue(true); }); @@ -103,6 +105,7 @@ test('confirmed without an external event is created and marked synced', async ( expect(row.external_calendar_id).toBe('work'); expect(row.calendar_synced_revision).toBe(1); expect(calls.some((c) => c.method === 'PUT')).toBe(true); + const states = await calendarJobStates(ctx.db, '1'); expect(states).toEqual(['done']); } finally { @@ -291,6 +294,7 @@ test('a should-not-exist row with no external event is a no-op marked synced', a const row = await rowById(ctx.db, '1'); expect(row.calendar_synced_revision).toBe(2); expect(calls).toHaveLength(0); + const states = await calendarJobStates(ctx.db, '1'); expect(states).toEqual([]); } finally { diff --git a/apps/worker/src/calendar/sync.ts b/apps/worker/src/calendar/sync.ts index 48de4671..d379def4 100644 --- a/apps/worker/src/calendar/sync.ts +++ b/apps/worker/src/calendar/sync.ts @@ -1,156 +1,8 @@ -import { deleteAppointmentFromCalendar, pushAppointment } from '@when/calendar'; -import { findCalendar } from '@when/config'; -import { - findAppointment, - listActiveAppointmentsForCalendarEvent, - listOutOfSyncAppointments, - markSynced, - recordCalendarEventDeletion, - recordCalendarEventReference, - recordServiceOutcome, - type Appointment, - type CalendarEventReference -} from '@when/db'; +import { findAppointment, listOutOfSyncAppointments } from '@when/db'; import type { WorkerContext } from '../services/context.js'; -import { appointmentLinks } from '../links.js'; -import { appendJobLog, markCalendarFailing } from '../services/job-log.js'; -import { calendarSyncDuration } from '../services/metrics.js'; +import { reconcileAppointment } from '../services/calendar.js'; import { cleanupAppointmentVideoChat } from '../services/video-chat-cleanup.js'; -export async function reconcileAppointment(ctx: WorkerContext, row: Appointment): Promise { - if (row.status === 'purged') return; - const target = - row.external_calendar_id ?? ctx.config.meetings[row.event_type_id]?.booking_calendar ?? null; - const calendar = target ? findCalendar(ctx.config, target) : undefined; - const stopTimer = calendarSyncDuration.startTimer({ provider_type: calendar?.type ?? 'unknown' }); - try { - if (row.status === 'confirmed') { - await publishCalendarContent(ctx, row, target); - } else if ( - row.status === 'cancelled' || - row.status === 'declined' || - row.status === 'expired' - ) { - await removeCalendarEvent(ctx, row); - } else { - // Pending and rescheduled occurrences keep their inherited event. - await acknowledgeCalendarContent(ctx, row); - } - } finally { - stopTimer(); - } -} - -async function publishCalendarContent( - ctx: WorkerContext, - row: Appointment, - target: string | null -): Promise { - if (!target) { - await acknowledgeCalendarContent(ctx, row); - return; - } - const cancelUrl = appointmentLinks({ baseUrl: ctx.config.url.app, appointment: row }).booked; - const pushed = await pushAppointment(ctx.config, row, target, { cancelUrl }); - if (!pushed.ok) { - await recordCalendarFailure(ctx, row, target, pushed.reason); - return; - } - if (pushed.externalCalendarId && pushed.externalEventId) { - const reference = { calendarId: pushed.externalCalendarId, eventId: pushed.externalEventId }; - await recordCalendarEventReference(ctx.db, row.id, reference); - await markSynced(ctx.db, row.id, row.calendar_revision, reference); - } - await recordCalendarSuccess(ctx, row.id, target); -} - -async function removeCalendarEvent(ctx: WorkerContext, row: Appointment): Promise { - if (!row.external_calendar_id || !row.external_event_id) { - await acknowledgeCalendarContent(ctx, row); - return; - } - const reference = { calendarId: row.external_calendar_id, eventId: row.external_event_id }; - const allowed = await canDeleteCalendarEvent(ctx, row, reference); - if (!allowed) return; - const deleted = await deleteAppointmentFromCalendar( - ctx.config, - reference.calendarId, - reference.eventId - ); - if (!deleted.ok) { - await recordCalendarFailure(ctx, row, reference.calendarId, deleted.reason); - return; - } - await recordCalendarEventDeletion(ctx.db, row.id, row.calendar_revision, reference); - await recordCalendarSuccess(ctx, row.id, reference.calendarId); -} - -async function canDeleteCalendarEvent( - ctx: WorkerContext, - row: Appointment, - reference: CalendarEventReference -): Promise { - const current = await findAppointment(ctx.db, row.id); - if ( - !current || - current.status !== row.status || - current.calendar_revision !== row.calendar_revision || - current.external_calendar_id !== reference.calendarId || - current.external_event_id !== reference.eventId - ) - return false; - const active = await listActiveAppointmentsForCalendarEvent(ctx.db, reference); - return !active.some((appointment) => appointment.id !== row.id); -} - -async function acknowledgeCalendarContent(ctx: WorkerContext, row: Appointment): Promise { - await markSynced(ctx.db, row.id, row.calendar_revision, { - calendarId: row.external_calendar_id, - eventId: row.external_event_id - }); -} - -async function recordCalendarSuccess( - ctx: WorkerContext, - appointmentId: string, - calendarName: string -): Promise { - await appendJobLog(ctx.db, appointmentId, 'calendar', 'done', Temporal.Now.instant().toString()); - await recordCalendarOutcome(ctx, calendarName, null); -} - -async function recordCalendarFailure( - ctx: WorkerContext, - row: Appointment, - calendarName: string, - reason: string | undefined -): Promise { - await markCalendarFailing(ctx.db, row, Temporal.Now.instant().toString()); - await recordCalendarOutcome(ctx, calendarName, reason); - ctx.logger.error({ appointmentId: row.id, reason }, 'calendar sync failed; will retry next scan'); -} - -async function recordCalendarOutcome( - ctx: WorkerContext, - calendarName: string, - error: string | null | undefined -): Promise { - const at = Temporal.Now.instant().toString(); - await recordServiceOutcome( - ctx.db, - { kind: 'calendar', name: calendarName }, - { at, via: 'push', error } - ); - const provider = findCalendar(ctx.config, calendarName)?.providerName; - if (provider) { - await recordServiceOutcome( - ctx.db, - { kind: 'provider', name: provider }, - { at, via: 'push', error } - ); - } -} - export async function scanOnce(ctx: WorkerContext): Promise { const rows = await listOutOfSyncAppointments(ctx.db); for (const row of rows) { diff --git a/apps/worker/src/email/smtp.test.ts b/apps/worker/src/email/smtp.test.ts index f2267e71..10eea8ac 100644 --- a/apps/worker/src/email/smtp.test.ts +++ b/apps/worker/src/email/smtp.test.ts @@ -93,7 +93,7 @@ describe('smtp', () => { expect(logger.error).not.toHaveBeenCalled(); }); - test('returns the provider failure but logs only its numeric SMTP status', async () => { + test('returns the provider failure but logs only its category and numeric SMTP status', async () => { const response = `550 5.1.1 <${envelope.to}>: Recipient address rejected`; const error = Object.assign( new Error(`Can't send mail - all recipients were rejected: ${response}`), @@ -112,30 +112,57 @@ describe('smtp', () => { const result = await mailer.send(envelope); expect(sendMail).toHaveBeenCalledTimes(1); - expect(result).toEqual({ ok: false, reason: String(error) }); - expect(logger.error).toHaveBeenCalledExactlyOnceWith({ responseCode: 550 }, 'SMTP send failed'); + expect(result).toEqual({ ok: false, reason: String(error), code: 'rejected' }); + expect(logger.error).toHaveBeenCalledExactlyOnceWith( + { code: 'rejected', responseCode: 550 }, + 'SMTP send failed' + ); + expect(logger.info).not.toHaveBeenCalled(); }); test.each([ - { name: 'a connection failure without SMTP status', error: new Error('connect ECONNREFUSED') }, + { + name: 'a connection failure without structured metadata', + error: new Error('connect ECONNREFUSED'), + expected: 'unknown' + }, + { + name: 'structured authentication failure', + error: Object.assign(new Error('Private provider detail'), { code: 'EAUTH' }), + expected: 'auth' + }, + { + name: 'structured timeout', + error: Object.assign(new Error('Private provider detail'), { code: 'ETIMEDOUT' }), + expected: 'timeout' + }, + { + name: 'structured connection failure', + error: Object.assign(new Error('Private provider detail'), { code: 'ECONNREFUSED' }), + expected: 'connection' + }, { name: 'a provider failure with private text in its status', error: Object.assign(new Error(`Recipient ${envelope.to} rejected`), { responseCode: `550 ${envelope.to}` - }) + }), + expected: 'unknown' } - ])('logs no unsafe metadata for $name, preserving its detailed reason', async ({ error }) => { - createTransport.mockReturnValueOnce({ sendMail: vi.fn().mockRejectedValue(error) }); - const mailer = createMailer(configForPort(587), logger as unknown as Logger); + ])( + 'logs no unsafe metadata for $name, preserving its detailed reason', + async ({ error, expected }) => { + createTransport.mockReturnValueOnce({ sendMail: vi.fn().mockRejectedValue(error) }); + const mailer = createMailer(configForPort(587), logger as unknown as Logger); - const result = await mailer.send(envelope); + const result = await mailer.send(envelope); - expect(result).toEqual({ ok: false, reason: String(error) }); - expect(logger.error).toHaveBeenCalledExactlyOnceWith( - { responseCode: undefined }, - 'SMTP send failed' - ); - expect(logger.info).not.toHaveBeenCalled(); - }); + expect(result).toEqual({ ok: false, reason: String(error), code: expected }); + expect(logger.error).toHaveBeenCalledExactlyOnceWith( + { code: expected, responseCode: undefined }, + 'SMTP send failed' + ); + expect(logger.info).not.toHaveBeenCalled(); + } + ); }); diff --git a/apps/worker/src/email/smtp.ts b/apps/worker/src/email/smtp.ts index 8be52d49..04b944d0 100644 --- a/apps/worker/src/email/smtp.ts +++ b/apps/worker/src/email/smtp.ts @@ -3,13 +3,38 @@ import { senderEmail, type WhenConfiguration } from '@when/config'; import type { Logger } from '../services/logger.js'; import type { Envelope } from './recipients.js'; -export type SendResult = { ok: true } | { ok: false; reason: string }; +export type SmtpFailureCode = 'auth' | 'timeout' | 'connection' | 'rejected' | 'unknown'; +export type SendResult = { ok: true } | { ok: false; reason: string; code: SmtpFailureCode }; /** Sends a rendered envelope over SMTP. Built once at boot via `createMailer`. */ export interface Mailer { send(envelope: Envelope): Promise; } +function smtpFailureCode(error: unknown, responseCode: number | undefined): SmtpFailureCode { + let providerCode: unknown; + if (error && typeof error === 'object' && 'code' in error) { + providerCode = error.code; + } + if ( + providerCode === 'EAUTH' || + responseCode === 530 || + responseCode === 534 || + responseCode === 535 + ) + return 'auth'; + if (providerCode === 'ETIMEDOUT') return 'timeout'; + if ( + typeof providerCode === 'string' && + ['ECONNECTION', 'ESOCKET', 'ECONNREFUSED', 'ECONNRESET', 'ENOTFOUND', 'EAI_AGAIN'].includes( + providerCode + ) + ) + return 'connection'; + if (responseCode !== undefined) return 'rejected'; + return 'unknown'; +} + export function isSecurePort(port: number): boolean { return port === 465; } @@ -52,8 +77,9 @@ export function createMailer(config: WhenConfiguration, logger: Logger): Mailer responseCode = code; } } - logger.error({ responseCode }, 'SMTP send failed'); - return { ok: false, reason: String(err) }; + const code = smtpFailureCode(err, responseCode); + logger.error({ code, responseCode }, 'SMTP send failed'); + return { ok: false, reason: String(err), code }; } } }; diff --git a/apps/worker/src/email/status.test.ts b/apps/worker/src/email/status.test.ts index cdb37c85..59dff62d 100644 --- a/apps/worker/src/email/status.test.ts +++ b/apps/worker/src/email/status.test.ts @@ -29,7 +29,7 @@ test('a failed send records the reason using the observed attempt time', async ( const ctx = await freshCtx(); try { const at = '2026-02-01T12:00:00.000Z'; - await recordSendOutcome(ctx, { ok: false, reason: 'EAUTH' }, at); + await recordSendOutcome(ctx, { ok: false, reason: 'EAUTH', code: 'auth' }, at); const [smtp] = await listServiceStatus(ctx.db, 'smtp'); expect(smtp.error).toBe('EAUTH'); diff --git a/apps/worker/src/index.test.ts b/apps/worker/src/index.test.ts index 1ba6590a..9113a40b 100644 --- a/apps/worker/src/index.test.ts +++ b/apps/worker/src/index.test.ts @@ -40,7 +40,7 @@ vi.mock('@when/jobs', async (importOriginal) => { }; }); vi.mock('@when/calendar', () => ({ setLogger: mocks.setLogger })); -vi.mock('./email/smtp.js', () => ({ createMailer: mocks.createMailer })); +vi.mock('./services/email.js', () => ({ createMailer: mocks.createMailer })); vi.mock('./services/context.js', () => ({ setWorkerContext: mocks.setWorkerContext })); vi.mock('./services/health.js', () => ({ createHealthServer: mocks.createHealthServer })); vi.mock('./services/logger.js', () => ({ logger: mocks.logger })); diff --git a/apps/worker/src/metrics/appointments.test.ts b/apps/worker/src/metrics/appointments.test.ts new file mode 100644 index 00000000..9c44080c --- /dev/null +++ b/apps/worker/src/metrics/appointments.test.ts @@ -0,0 +1,40 @@ +import { beforeEach, expect, test, vi } from 'vitest'; +import { expireStalePending } from '@when/db'; +import { expirePending } from '../services/appointments.js'; +import { appointmentOperationsTotal } from './registry.js'; + +vi.mock('@when/db', () => ({ expireStalePending: vi.fn() })); + +beforeEach(() => { + vi.resetAllMocks(); + appointmentOperationsTotal.reset(); +}); + +test('expiry counts invocations, including empty passes, not changed rows', async () => { + vi.mocked(expireStalePending).mockResolvedValueOnce(5).mockResolvedValueOnce(0); + const db = {} as Parameters[0]; + expect(await expirePending(db, '2026-01-01T00:00:00Z')).toBe(5); + expect(await expirePending(db, '2026-01-01T00:00:00Z')).toBe(0); + expect((await appointmentOperationsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { action: 'expire', actor: 'system', status: 'success' }, + value: 2 + }) + ]); + expect((await appointmentOperationsTotal.get()).help).toBe( + 'Appointment operation outcomes, not committed changes.' + ); +}); + +test('expiry counts errors and rethrows the original error unchanged', async () => { + const error = { marker: 'original DB error' }; + vi.mocked(expireStalePending).mockRejectedValue(error); + const db = {} as Parameters[0]; + await expect(expirePending(db, '2026-01-01T00:00:00Z')).rejects.toBe(error); + expect((await appointmentOperationsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { action: 'expire', actor: 'system', status: 'error' }, + value: 1 + }) + ]); +}); diff --git a/apps/worker/src/metrics/appointments.ts b/apps/worker/src/metrics/appointments.ts new file mode 100644 index 00000000..563d0faa --- /dev/null +++ b/apps/worker/src/metrics/appointments.ts @@ -0,0 +1,16 @@ +import type { expireStalePending } from '@when/db'; +import { appointmentOperationsTotal } from './registry.js'; + +export function observeExpiry(operation: typeof expireStalePending): typeof expireStalePending { + return async (...args) => { + let count: number; + try { + count = await operation(...args); + } catch (error) { + appointmentOperationsTotal.inc({ action: 'expire', actor: 'system', status: 'error' }); + throw error; + } + appointmentOperationsTotal.inc({ action: 'expire', actor: 'system', status: 'success' }); + return count; + }; +} diff --git a/apps/worker/src/metrics/calendar-provider.ts b/apps/worker/src/metrics/calendar-provider.ts new file mode 100644 index 00000000..f0e62c7a --- /dev/null +++ b/apps/worker/src/metrics/calendar-provider.ts @@ -0,0 +1,42 @@ +import type { + fetchBusyIntervals, + pushAppointment, + deleteAppointmentFromCalendar +} from '@when/calendar'; +import { findCalendar } from '@when/config'; +import { operationFailuresTotal } from './registry.js'; + +export function observeBusyFetch(operation: typeof fetchBusyIntervals): typeof fetchBusyIntervals { + return async (calendar, window, options) => { + try { + return await operation(calendar, window, options); + } catch (error) { + operationFailuresTotal.inc({ operation: 'calendar_refresh', code: 'provider_error' }); + throw error; + } + }; +} + +export function observeCalendarWrite(operation: typeof pushAppointment): typeof pushAppointment { + return async (config, appointment, calendarId, options) => { + const result = await operation(config, appointment, calendarId, options); + if (!result.ok) { + const code = findCalendar(config, calendarId) ? 'provider_error' : 'not_configured'; + operationFailuresTotal.inc({ operation: 'calendar_write', code }); + } + return result; + }; +} + +export function observeCalendarDelete( + operation: typeof deleteAppointmentFromCalendar +): typeof deleteAppointmentFromCalendar { + return async (config, calendarId, eventId) => { + const result = await operation(config, calendarId, eventId); + if (!result.ok) { + const code = findCalendar(config, calendarId) ? 'provider_error' : 'not_configured'; + operationFailuresTotal.inc({ operation: 'calendar_delete', code }); + } + return result; + }; +} diff --git a/apps/worker/src/metrics/calendar.test.ts b/apps/worker/src/metrics/calendar.test.ts new file mode 100644 index 00000000..042ae943 --- /dev/null +++ b/apps/worker/src/metrics/calendar.test.ts @@ -0,0 +1,212 @@ +import { afterEach, beforeEach, expect, test, vi } from 'vitest'; +import { sql } from 'kysely'; +import { findCalendar, type WhenConfiguration } from '@when/config'; +import { fetchBusyIntervals, pushAppointment, deleteAppointmentFromCalendar } from '@when/calendar'; +import { openDb, runMigrations, findAppointment } from '@when/db'; +import { refreshCalendar, reconcileAppointment } from '../services/calendar.js'; +import { scanOnce } from '../services/calendar-scan.js'; +import { + pushAppointment as write, + deleteAppointmentFromCalendar as remove +} from '../services/calendar-provider.js'; +import { refreshCalendars } from '../calendar/refresh.js'; +import { sampleAppointment, sampleConfig } from '../email/__fixtures__/appointment.js'; +import { createLogger } from '../services/logger.js'; +import type { WorkerContext } from '../services/context.js'; +import { + calendarRefreshTotal, + calendarSyncDuration, + calendarSyncTotal, + operationFailuresTotal +} from './registry.js'; + +vi.mock('@when/calendar', async (importOriginal) => ({ + ...(await importOriginal()), + fetchBusyIntervals: vi.fn(), + pushAppointment: vi.fn(), + deleteAppointmentFromCalendar: vi.fn() +})); + +const config = { + ...sampleConfig, + providers: { + dav: { + type: 'caldav', + url: 'https://calendar.example.test', + username: 'u', + password: 'p', + calendars: { work: { href: '/calendar', sync: { refresh_every_minutes: 10 } } } + } + }, + meetings: { + '30-min': { + title: 'Chat', + booking_calendar: 'work', + additional_busy_calendars: [], + booking_window_days: 60 + } + } +} as unknown as WhenConfiguration; +const cal = findCalendar(config, 'work')!; +const now = Temporal.Instant.from('2026-01-01T00:00:00Z'); +const window = { start: now, end: now.add({ hours: 24 }) }; +let ctx: WorkerContext; + +beforeEach(async () => { + vi.resetAllMocks(); + calendarRefreshTotal.reset(); + calendarSyncDuration.reset(); + calendarSyncTotal.reset(); + operationFailuresTotal.reset(); + const db = openDb(':memory:'); + await runMigrations(db); + ctx = { db, config, logger: createLogger(), mailer: { send: async () => ({ ok: true }) } }; + vi.mocked(fetchBusyIntervals).mockResolvedValue([]); +}); +afterEach(async () => { + vi.restoreAllMocks(); + await ctx.db.destroy(); +}); + +test('batch refreshes count each provider failure and completed refresh, skipping fresh calendars', async () => { + vi.mocked(fetchBusyIntervals) + .mockRejectedValueOnce(new Error('offline')) + .mockRejectedValueOnce(new Error('offline')); + for (let pass = 0; pass < 4; pass++) await refreshCalendars(ctx, { now }); + expect(fetchBusyIntervals).toHaveBeenCalledTimes(3); + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { operation: 'calendar_refresh', code: 'provider_error' }, + value: 2 + }) + ]); + expect((await calendarRefreshTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { calendar_id: 'work', provider_type: 'caldav', status: 'failure' }, + value: 2 + }), + expect.objectContaining({ + labels: { calendar_id: 'work', provider_type: 'caldav', status: 'success' }, + value: 1 + }) + ]); +}); + +test.each(['mirror', 'status'])( + 'refresh %s SQL failure is not a provider failure', + async (stage) => { + if (stage === 'mirror') { + await ctx.db + .insertInto('external_calendar_busy') + .values({ + calendar_id: 'work', + start_time: now.toString(), + end_time: window.end.toString() + }) + .execute(); + await sql`create trigger fail_mirror before delete on external_calendar_busy begin select raise(abort, 'local SQL failure'); end`.execute( + ctx.db + ); + } else { + await sql`create trigger fail_status before insert on service_status begin select raise(abort, 'local SQL failure'); end`.execute( + ctx.db + ); + } + await expect(refreshCalendar(ctx, cal, window)).rejects.toThrow('local SQL failure'); + expect((await operationFailuresTotal.get()).values).toEqual([]); + expect((await calendarRefreshTotal.get()).values).toEqual([]); + } +); + +test('a failed fetch is counted even when persisting its service outcome fails', async () => { + vi.mocked(fetchBusyIntervals).mockRejectedValue(new Error('offline')); + await sql`create trigger fail_status before insert on service_status begin select raise(abort, 'local SQL failure'); end`.execute( + ctx.db + ); + await expect(refreshCalendar(ctx, cal, window)).rejects.toThrow('local SQL failure'); + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { operation: 'calendar_refresh', code: 'provider_error' }, + value: 1 + }) + ]); + expect((await calendarRefreshTotal.get()).values).toEqual([]); +}); + +test('observer errors are not reclassified as provider errors', async () => { + const error = new Error('metric unavailable'); + vi.spyOn(calendarRefreshTotal, 'inc').mockImplementationOnce(() => { + throw error; + }); + await expect(refreshCalendar(ctx, cal, window)).rejects.toBe(error); + expect((await operationFailuresTotal.get()).values).toEqual([]); + const statuses = await ctx.db.selectFrom('service_status').selectAll().execute(); + expect(statuses).toHaveLength(2); + expect(statuses.every((status) => status.error === null)).toBe(true); +}); + +test('scan loops observe each reconciliation retry even when failure logs deduplicate', async () => { + await ctx.db + .insertInto('appointments') + .values({ ...sampleAppointment, calendar_revision: 1 }) + .execute(); + vi.mocked(pushAppointment) + .mockResolvedValueOnce({ ok: false, reason: 'offline' }) + .mockResolvedValueOnce({ ok: false, reason: 'offline' }) + .mockResolvedValueOnce({ ok: true, externalCalendarId: 'work', externalEventId: 'remote' }); + for (let pass = 0; pass < 3; pass++) await scanOnce(ctx); + expect(pushAppointment).toHaveBeenCalledTimes(3); + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { operation: 'calendar_write', code: 'provider_error' }, + value: 2 + }) + ]); + expect((await calendarSyncTotal.get()).values).toEqual([ + expect.objectContaining({ labels: { status: 'success' }, value: 3 }) + ]); + expect( + (await calendarSyncDuration.get()).values.filter((value) => + value.metricName?.endsWith('_count') + ) + ).toEqual([expect.objectContaining({ labels: { provider_type: 'caldav' }, value: 3 })]); +}); + +test('a successful calendar write followed by a DB failure is not a provider failure', async () => { + await ctx.db.insertInto('appointments').values(sampleAppointment).execute(); + const row = (await findAppointment(ctx.db, sampleAppointment.id))!; + vi.mocked(pushAppointment).mockResolvedValue({ + ok: true, + externalCalendarId: 'work', + externalEventId: 'remote' + }); + await sql`create trigger fail_reference before update on appointments begin select raise(abort, 'local SQL failure'); end`.execute( + ctx.db + ); + await expect(reconcileAppointment(ctx, row)).rejects.toThrow('local SQL failure'); + expect((await operationFailuresTotal.get()).values).toEqual([]); + expect( + (await calendarSyncDuration.get()).values.find((value) => value.metricName?.endsWith('_count')) + ?.value + ).toBe(1); +}); + +test.each(['work', 'removed'])( + 'calendar adapter APIs distinguish provider and config failures for %s', + async (calendarId) => { + vi.mocked(pushAppointment).mockResolvedValue({ ok: false, reason: 'private detail' }); + vi.mocked(deleteAppointmentFromCalendar).mockResolvedValue({ + ok: false, + reason: 'private detail' + }); + await write(config, sampleAppointment, calendarId, { + cancelUrl: 'https://when.example.test/booked' + }); + await remove(config, calendarId, 'remote'); + const code = calendarId === 'work' ? 'provider_error' : 'not_configured'; + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ labels: { operation: 'calendar_write', code }, value: 1 }), + expect.objectContaining({ labels: { operation: 'calendar_delete', code }, value: 1 }) + ]); + } +); diff --git a/apps/worker/src/metrics/calendar.ts b/apps/worker/src/metrics/calendar.ts new file mode 100644 index 00000000..624b2011 --- /dev/null +++ b/apps/worker/src/metrics/calendar.ts @@ -0,0 +1,47 @@ +import { findCalendar } from '@when/config'; +import type { refreshCalendar } from '../calendar/refresh-calendar.js'; +import type { reconcileAppointment } from '../calendar/reconcile.js'; +import type { scanOnce } from '../calendar/sync.js'; +import { calendarRefreshTotal, calendarSyncDuration, calendarSyncTotal } from './registry.js'; + +export function observeRefreshCalendar(operation: typeof refreshCalendar): typeof refreshCalendar { + return async (ctx, cal, window, opts) => { + const result = await operation(ctx, cal, window, opts); + const status = result.ok ? 'success' : 'failure'; + calendarRefreshTotal.inc({ + calendar_id: cal.name, + provider_type: cal.provider.type, + status + }); + return result; + }; +} + +export function observeReconciliation( + operation: typeof reconcileAppointment +): typeof reconcileAppointment { + return async (ctx, row) => { + if (row.status === 'purged') return operation(ctx, row); + const target = + row.external_calendar_id ?? ctx.config.meetings[row.event_type_id]?.booking_calendar; + const calendar = target ? findCalendar(ctx.config, target) : undefined; + const stop = calendarSyncDuration.startTimer({ provider_type: calendar?.type ?? 'unknown' }); + try { + return await operation(ctx, row); + } finally { + stop(); + } + }; +} + +export function observeCalendarScan(operation: typeof scanOnce): typeof scanOnce { + return async (ctx) => { + try { + await operation(ctx); + } catch (error) { + calendarSyncTotal.inc({ status: 'failure' }); + throw error; + } + calendarSyncTotal.inc({ status: 'success' }); + }; +} diff --git a/apps/worker/src/metrics/email.test.ts b/apps/worker/src/metrics/email.test.ts new file mode 100644 index 00000000..53145af1 --- /dev/null +++ b/apps/worker/src/metrics/email.test.ts @@ -0,0 +1,54 @@ +import { beforeEach, expect, test, vi } from 'vitest'; +import { createMailer, sendAppointmentEmail } from '../services/email.js'; +import { createLogger } from '../services/logger.js'; +import { sampleConfig } from '../email/__fixtures__/appointment.js'; +import { emailsTotal, operationFailuresTotal } from './registry.js'; + +const { sendMail } = vi.hoisted(() => ({ sendMail: vi.fn() })); +vi.mock('nodemailer', () => ({ default: { createTransport: () => ({ sendMail }) } })); +const envelope = { to: 'guest@example.test', subject: 'Test', text: 'Body' }; + +beforeEach(() => { + sendMail.mockReset(); + emailsTotal.reset(); + operationFailuresTotal.reset(); +}); + +test.each([ + [{ code: 'EAUTH' }, 'auth'], + [{ responseCode: 535 }, 'auth'], + [{ code: 'ETIMEDOUT' }, 'timeout'], + [{ code: 'ECONNREFUSED' }, 'connection'], + [{ responseCode: 550 }, 'rejected'], + [new Error('EAUTH timeout connection rejected'), 'unknown'] +])('observed SMTP attempts use only structured bounded failure codes: %j', async (error, code) => { + sendMail.mockRejectedValue(error); + const mailer = createMailer(sampleConfig, createLogger()); + await mailer.send(envelope); + await mailer.send(envelope); + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ labels: { operation: 'smtp_send', code }, value: 2 }) + ]); + // Direct/test sends do not contribute to the legacy appointment family. + expect((await emailsTotal.get()).values).toEqual([]); +}); + +test('appointment attempt scope retains recipient, kind and outcome', async () => { + const mailer = createMailer(sampleConfig, createLogger()); + sendMail.mockRejectedValueOnce({ code: 'ETIMEDOUT' }).mockResolvedValueOnce({}); + await sendAppointmentEmail(mailer, envelope, 'guest', 'confirmed'); + await sendAppointmentEmail(mailer, envelope, 'guest', 'confirmed'); + expect((await emailsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { recipient_type: 'guest', email_kind: 'confirmed', status: 'failure' }, + value: 1 + }), + expect.objectContaining({ + labels: { recipient_type: 'guest', email_kind: 'confirmed', status: 'success' }, + value: 1 + }) + ]); + expect((await operationFailuresTotal.get()).values).toEqual([ + expect.objectContaining({ labels: { operation: 'smtp_send', code: 'timeout' }, value: 1 }) + ]); +}); diff --git a/apps/worker/src/metrics/email.ts b/apps/worker/src/metrics/email.ts new file mode 100644 index 00000000..13d67d84 --- /dev/null +++ b/apps/worker/src/metrics/email.ts @@ -0,0 +1,34 @@ +import type { AppointmentEmailKind } from '@when/jobs'; +import type { Mailer, SendResult } from '../email/smtp.js'; +import type { Envelope, RecipientRole } from '../email/recipients.js'; +import { emailsTotal, operationFailuresTotal } from './registry.js'; + +/** Physical SMTP attempts, including test mail; no recipient or message labels. */ +export function observeMailer(mailer: Mailer): Mailer { + return { + async send(envelope): Promise { + const result = await mailer.send(envelope); + if (!result.ok) { + operationFailuresTotal.inc({ operation: 'smtp_send', code: result.code }); + } + return result; + } + }; +} + +/** Legacy appointment-only attempt scope, independent of physical failure counting. */ +export async function observeAppointmentEmail( + mailer: Mailer, + envelope: Envelope, + role: RecipientRole, + kind: AppointmentEmailKind +): Promise { + const result = await mailer.send(envelope); + const status = result.ok ? 'success' : 'failure'; + emailsTotal.inc({ + recipient_type: role, + email_kind: kind, + status + }); + return result; +} diff --git a/apps/worker/src/metrics/export.ts b/apps/worker/src/metrics/export.ts new file mode 100644 index 00000000..0cfd7339 --- /dev/null +++ b/apps/worker/src/metrics/export.ts @@ -0,0 +1,11 @@ +import { register } from './registry.js'; + +export async function exportMetrics(json: boolean): Promise<{ contentType: string; body: string }> { + if (json) { + return { + contentType: 'application/json; charset=utf-8', + body: JSON.stringify(await register.getMetricsAsJSON()) + }; + } + return { contentType: register.contentType, body: await register.metrics() }; +} diff --git a/apps/worker/src/workflows/maintenance.test.ts b/apps/worker/src/metrics/maintenance.test.ts similarity index 87% rename from apps/worker/src/workflows/maintenance.test.ts rename to apps/worker/src/metrics/maintenance.test.ts index 78157c4b..b49ac77c 100644 --- a/apps/worker/src/workflows/maintenance.test.ts +++ b/apps/worker/src/metrics/maintenance.test.ts @@ -5,10 +5,10 @@ import { refreshCycle } from '../calendar/refresh.js'; import { sampleAppointment, sampleConfig } from '../email/__fixtures__/appointment.js'; import { setWorkerContext, type WorkerContext } from '../services/context.js'; import { createLogger } from '../services/logger.js'; -import { calendarSyncTotal } from '../services/metrics.js'; -import { runSyncCalendars } from './sync-calendars.js'; -import { runRefreshCalendars } from './refresh-calendars.js'; -import { runExpirePendingAppointments } from './expire-pending-appointments.js'; +import { appointmentOperationsTotal, calendarSyncTotal } from './registry.js'; +import { runSyncCalendars } from '../workflows/sync-calendars.js'; +import { runRefreshCalendars } from '../workflows/refresh-calendars.js'; +import { runExpirePendingAppointments } from '../workflows/expire-pending-appointments.js'; vi.mock('../calendar/sync.js', () => ({ scanOnce: vi.fn() })); vi.mock('../calendar/refresh.js', () => ({ refreshCycle: vi.fn() })); @@ -32,6 +32,7 @@ function makeStep() { beforeEach(async () => { vi.resetAllMocks(); calendarSyncTotal.reset(); + appointmentOperationsTotal.reset(); const db = openDb(':memory:'); await runMigrations(db); ctx = { @@ -152,8 +153,20 @@ test('expiry uses the injected clock, is idempotent, and logs the changed count' const step = makeStep(); const firstExpiryResult = await runExpirePendingAppointments(step, clock); expect(firstExpiryResult).toBe('expired'); + expect((await appointmentOperationsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { action: 'expire', actor: 'system', status: 'success' }, + value: 1 + }) + ]); const repeatedExpiryResult = await runExpirePendingAppointments(step, clock); expect(repeatedExpiryResult).toBe('expired'); + expect((await appointmentOperationsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { action: 'expire', actor: 'system', status: 'success' }, + value: 2 + }) + ]); for (const { id, expectedStatus } of cases) { const row = await ctx.db .selectFrom('appointments') @@ -184,4 +197,10 @@ test('expiry local SQL errors escape rather than completing the pass', async () await ctx.db.schema.dropTable('appointments').execute(); await expect(runExpirePendingAppointments(makeStep(), clock)).rejects.toThrow(); expect(ctx.logger.info).not.toHaveBeenCalled(); + expect((await appointmentOperationsTotal.get()).values).toEqual([ + expect.objectContaining({ + labels: { action: 'expire', actor: 'system', status: 'error' }, + value: 1 + }) + ]); }); diff --git a/apps/worker/src/metrics/registry.ts b/apps/worker/src/metrics/registry.ts new file mode 100644 index 00000000..df166a6f --- /dev/null +++ b/apps/worker/src/metrics/registry.ts @@ -0,0 +1,67 @@ +import { Counter, Histogram, Gauge, Registry } from '@prometheus-io/client'; + +export const register = new Registry(); +register.setDefaultLabels({ app: 'when', service: 'worker' }); + +export const jobsTotal = new Counter({ + name: 'when_jobs_total', + help: 'Handler executions by return or escape (including durable suspension), not terminal workflow outcomes.', + labelNames: ['job_name', 'status'], + registers: [register] +}); + +export const jobDuration = new Histogram({ + name: 'when_job_duration_seconds', + help: 'Duration of each workflow handler execution, including executions that durably suspend.', + labelNames: ['job_name'], + registers: [register] +}); + +export const jobsActive = new Gauge({ + name: 'when_jobs_active', + help: 'Number of active workflow handler executions; durably suspended runs are excluded.', + labelNames: ['job_name'], + registers: [register] +}); + +export const emailsTotal = new Counter({ + name: 'when_emails_total', + help: 'Physical appointment SMTP send attempts by outcome, not unique email deliveries.', + labelNames: ['recipient_type', 'status', 'email_kind'], + registers: [register] +}); + +export const calendarSyncTotal = new Counter({ + name: 'when_calendar_sync_total', + help: 'Calendar scan callback outcomes, not proof that every appointment write succeeded.', + labelNames: ['status'], + registers: [register] +}); + +export const calendarSyncDuration = new Histogram({ + name: 'when_calendar_sync_duration_seconds', + help: 'Duration of each appointment calendar reconciliation attempt.', + labelNames: ['provider_type'], + registers: [register] +}); + +export const calendarRefreshTotal = new Counter({ + name: 'when_calendar_refresh_total', + help: 'Total number of calendar refreshes.', + labelNames: ['calendar_id', 'provider_type', 'status'], + registers: [register] +}); + +export const appointmentOperationsTotal = new Counter({ + name: 'when_appointment_operations_total', + help: 'Appointment operation outcomes, not committed changes.', + labelNames: ['action', 'actor', 'status'], + registers: [register] +}); + +export const operationFailuresTotal = new Counter({ + name: 'when_operation_failures_total', + help: 'Failed operation attempts by bounded operation and failure code.', + labelNames: ['operation', 'code'], + registers: [register] +}); diff --git a/apps/worker/src/services/metrics.test.ts b/apps/worker/src/metrics/workflows.test.ts similarity index 71% rename from apps/worker/src/services/metrics.test.ts rename to apps/worker/src/metrics/workflows.test.ts index e0140d4e..fc21f48f 100644 --- a/apps/worker/src/services/metrics.test.ts +++ b/apps/worker/src/metrics/workflows.test.ts @@ -1,54 +1,36 @@ +import { implementWorkflow } from '../services/workflow-registration.js'; import { afterEach, beforeEach, describe, expect, test, vi } from 'vitest'; import { OpenWorkflow, defineWorkflowSpec } from 'openworkflow'; import { BackendSqlite } from 'openworkflow/sqlite'; import * as jobs from '@when/jobs'; -import { - implementObservedWorkflow, - jobDuration, - jobsActive, - jobsTotal, - register -} from './metrics.js'; +import { jobDuration, jobsActive, jobsTotal, register } from './registry.js'; test('registry default labels are set correctly', async () => { - const json = await register.getMetricsAsJSON(); - // Default labels should be attached to registered metrics - const firstMetric = json.find((m) => m.name === 'process_resident_memory_bytes'); - expect(firstMetric).toBeDefined(); - if (firstMetric) { - const firstVal = firstMetric.values[0]; - expect(firstVal).toBeDefined(); - if (firstVal) { - expect(firstVal.labels).toMatchObject({ app: 'when', service: 'worker' }); - } + jobsActive.set({ job_name: 'test-job' }, 0); + try { + const json = await register.getMetricsAsJSON(); + expect(json.find((metric) => metric.name === 'when_jobs_active')?.values).toMatchObject([ + { labels: { app: 'when', service: 'worker', job_name: 'test-job' }, value: 0 } + ]); + } finally { + jobsActive.reset(); } }); -test('low-value default metrics are pruned', async () => { +test('only application metrics are registered', async () => { const json = await register.getMetricsAsJSON(); - const names = json.map((m) => m.name); - - // High-value metrics we keep - expect(names).toContain('process_resident_memory_bytes'); - expect(names).toContain('process_cpu_seconds_total'); - - // Low-value metrics we prune - expect(names).not.toContain('nodejs_active_handles'); - expect(names).not.toContain('nodejs_heap_space_size_total_bytes'); - expect(names).not.toContain('process_virtual_memory_bytes'); -}); - -test('custom worker metrics are registered', async () => { - const json = await register.getMetricsAsJSON(); - const names = json.map((m) => m.name); - - expect(names).toContain('when_jobs_total'); - expect(names).toContain('when_job_duration_seconds'); - expect(names).toContain('when_jobs_active'); - expect(names).toContain('when_emails_total'); - expect(names).toContain('when_calendar_sync_total'); - expect(names).toContain('when_calendar_sync_duration_seconds'); - expect(names).toContain('when_calendar_refresh_total'); + expect(json.map((metric) => metric.name).sort()).toEqual([ + 'when_appointment_operations_total', + 'when_calendar_refresh_total', + 'when_calendar_sync_duration_seconds', + 'when_calendar_sync_total', + 'when_emails_total', + 'when_job_duration_seconds', + 'when_job_oldest_active_seconds', + 'when_jobs_active', + 'when_jobs_total', + 'when_operation_failures_total' + ]); }); describe('native workflow handler metrics', () => { @@ -80,15 +62,19 @@ describe('native workflow handler metrics', () => { statuses: Partial>, executions: number ) { - const total = await jobsTotal.get(); + const snapshot = await register.getMetricsAsJSON(); + const totals = snapshot.find((metric) => metric.name === 'when_jobs_total')?.values ?? []; const active = await jobsActive.get(); const duration = await jobDuration.get(); - const counts = Object.fromEntries( - total.values.map(({ labels, value }) => [labels.status, value]) - ); + const counts = Object.fromEntries(totals.map(({ labels, value }) => [labels.status, value])); expect(counts).toEqual(statuses); - expect(total.values.every(({ labels }) => labels.job_name === jobName)).toBe(true); + expect(totals.every(({ labels }) => labels.job_name === jobName)).toBe(true); expect(active.values).toMatchObject([{ labels: { job_name: jobName }, value: 0 }]); + expect( + snapshot + .find((metric) => metric.name === 'when_job_oldest_active_seconds') + ?.values.find((sample) => sample.labels.job_name === jobName)?.value + ).toBe(0); expect( duration.values .filter(({ metricName }) => metricName === 'when_job_duration_seconds_count') @@ -100,7 +86,16 @@ describe('native workflow handler metrics', () => { const spec = defineWorkflowSpec<{ value: number }, { doubled: number }>({ name: 'observed-return' }); - implementObservedWorkflow(spec, async ({ input, step }) => { + implementWorkflow(spec, async ({ input, step }) => { + expect((await jobsActive.get()).values).toMatchObject([ + { labels: { job_name: spec.name }, value: 1 } + ]); + const snapshot = await register.getMetricsAsJSON(); + expect( + snapshot + .find((metric) => metric.name === 'when_job_oldest_active_seconds') + ?.values.find((sample) => sample.labels.job_name === spec.name)?.value + ).toBeGreaterThan(0); const doubled = await step.run({ name: 'double' }, () => input.value * 2); return { doubled }; }); @@ -118,7 +113,7 @@ describe('native workflow handler metrics', () => { test('counts an escaped root error without swallowing it', async () => { const spec = defineWorkflowSpec, void>({ name: 'observed-throw' }); const opaqueError = new Error('root handler failed'); - implementObservedWorkflow(spec, () => { + implementWorkflow(spec, () => { throw opaqueError; }); worker = client.newWorker({ concurrency: 1 }); @@ -138,7 +133,7 @@ describe('native workflow handler metrics', () => { name: 'observed-parent' }); client.implementWorkflow(child, () => 'sent'); - implementObservedWorkflow(parent, async ({ step }) => { + implementWorkflow(parent, async ({ step }) => { const childResult = await step.runWorkflow(child, {}, { name: 'delivery' }); return { childResult }; }); diff --git a/apps/worker/src/metrics/workflows.ts b/apps/worker/src/metrics/workflows.ts new file mode 100644 index 00000000..1a552b98 --- /dev/null +++ b/apps/worker/src/metrics/workflows.ts @@ -0,0 +1,50 @@ +import { Gauge } from '@prometheus-io/client'; +import type { WorkflowSpec } from '@when/jobs'; +import type { Workflow } from 'openworkflow'; +import { register, jobsTotal, jobDuration, jobsActive } from './registry.js'; + +const activeExecutions = new Map>(); + +new Gauge({ + name: 'when_job_oldest_active_seconds', + help: 'Age of the oldest currently executing handler by job name; zero when idle, excluding parked workflows.', + labelNames: ['job_name'], + registers: [register], + collect() { + const now = process.hrtime.bigint(); + for (const [job_name, executions] of activeExecutions) { + let oldest = now; + for (const execution of executions) { + if (execution.started < oldest) oldest = execution.started; + } + this.set({ job_name }, Number(now - oldest) / 1e9); + } + } +}); + +export function observeWorkflow( + spec: WorkflowSpec, + handler: Workflow['fn'] +): Workflow['fn'] { + const executions = activeExecutions.get(spec.name) ?? new Set<{ started: bigint }>(); + activeExecutions.set(spec.name, executions); + jobsActive.inc({ job_name: spec.name }, 0); + return async (args) => { + const execution = { started: process.hrtime.bigint() }; + executions.add(execution); + jobsActive.inc({ job_name: spec.name }); + const timer = jobDuration.startTimer({ job_name: spec.name }); + try { + const result = await handler(args); + jobsTotal.inc({ job_name: spec.name, status: 'returned' }); + return result; + } catch (err) { + jobsTotal.inc({ job_name: spec.name, status: 'escaped' }); + throw err; + } finally { + executions.delete(execution); + jobsActive.dec({ job_name: spec.name }); + timer(); + } + }; +} diff --git a/apps/worker/src/services/appointments.ts b/apps/worker/src/services/appointments.ts new file mode 100644 index 00000000..efe135ac --- /dev/null +++ b/apps/worker/src/services/appointments.ts @@ -0,0 +1,4 @@ +import { expireStalePending } from '@when/db'; +import { observeExpiry } from '../metrics/appointments.js'; + +export const expirePending = observeExpiry(expireStalePending); diff --git a/apps/worker/src/services/calendar-provider.ts b/apps/worker/src/services/calendar-provider.ts new file mode 100644 index 00000000..2e065ff7 --- /dev/null +++ b/apps/worker/src/services/calendar-provider.ts @@ -0,0 +1,14 @@ +import { + fetchBusyIntervals as fetch, + pushAppointment as push, + deleteAppointmentFromCalendar as remove +} from '@when/calendar'; +import { + observeBusyFetch, + observeCalendarWrite, + observeCalendarDelete +} from '../metrics/calendar-provider.js'; + +export const fetchBusyIntervals = observeBusyFetch(fetch); +export const pushAppointment = observeCalendarWrite(push); +export const deleteAppointmentFromCalendar = observeCalendarDelete(remove); diff --git a/apps/worker/src/services/calendar-scan.ts b/apps/worker/src/services/calendar-scan.ts new file mode 100644 index 00000000..9361f1bc --- /dev/null +++ b/apps/worker/src/services/calendar-scan.ts @@ -0,0 +1,4 @@ +import { scanOnce as scan } from '../calendar/sync.js'; +import { observeCalendarScan } from '../metrics/calendar.js'; + +export const scanOnce = observeCalendarScan(scan); diff --git a/apps/worker/src/services/calendar.ts b/apps/worker/src/services/calendar.ts new file mode 100644 index 00000000..373b8095 --- /dev/null +++ b/apps/worker/src/services/calendar.ts @@ -0,0 +1,6 @@ +import { refreshCalendar as refresh } from '../calendar/refresh-calendar.js'; +import { reconcileAppointment as reconcile } from '../calendar/reconcile.js'; +import { observeRefreshCalendar, observeReconciliation } from '../metrics/calendar.js'; + +export const refreshCalendar = observeRefreshCalendar(refresh); +export const reconcileAppointment = observeReconciliation(reconcile); diff --git a/apps/worker/src/services/email.ts b/apps/worker/src/services/email.ts new file mode 100644 index 00000000..ed25bf80 --- /dev/null +++ b/apps/worker/src/services/email.ts @@ -0,0 +1,11 @@ +import type { WhenConfiguration } from '@when/config'; +import { createMailer as createSmtpMailer } from '../email/smtp.js'; +import { observeMailer, observeAppointmentEmail } from '../metrics/email.js'; +import type { Logger } from './logger.js'; + +/** SMTP operation API shared by appointment and test-email workflows. */ +export function createMailer(config: WhenConfiguration, logger: Logger) { + return observeMailer(createSmtpMailer(config, logger)); +} + +export const sendAppointmentEmail = observeAppointmentEmail; diff --git a/apps/worker/src/services/health.test.ts b/apps/worker/src/services/health.test.ts index 5f791b16..c7c01850 100644 --- a/apps/worker/src/services/health.test.ts +++ b/apps/worker/src/services/health.test.ts @@ -68,8 +68,18 @@ test('GET /metrics returns 200 with metrics if successfully authenticated', asyn expect(res.headers.get('content-type')).toContain('text/plain'); const text = await res.text(); - // Should contain system metrics we keep - expect(text).toContain('process_resident_memory_bytes'); - // Should contain custom worker metrics expect(text).toContain('when_jobs_total'); }); + +test('authenticated JSON snapshots retain application metadata', async () => { + mockConfig.prometheus.enabled = true; + const response = await fetch(`${base}/metrics`, { + headers: { Authorization: 'Bearer test-token', Accept: 'application/json' } + }); + expect(response.status).toBe(200); + expect(response.headers.get('content-type')).toContain('application/json'); + const snapshot = (await response.json()) as Array<{ name: string; type: string }>; + expect(snapshot.find((metric) => metric.name === 'when_jobs_total')).toMatchObject({ + type: 'counter' + }); +}); diff --git a/apps/worker/src/services/health.ts b/apps/worker/src/services/health.ts index 4bc48baa..902e6ab4 100644 --- a/apps/worker/src/services/health.ts +++ b/apps/worker/src/services/health.ts @@ -1,6 +1,6 @@ import { createServer, type IncomingMessage, type ServerResponse, type Server } from 'node:http'; import type { WhenConfiguration } from '@when/config'; -import { register } from './metrics.js'; +import { exportMetrics } from '../metrics/export.js'; /** A tiny HTTP server exposing GET /healthz for container liveness checks and GET /metrics for scraping. */ export function createHealthServer(getConfig: () => WhenConfiguration): Server { @@ -36,9 +36,11 @@ export function createHealthServer(getConfig: () => WhenConfiguration): Server { } try { - const body = await register.metrics(); res.statusCode = 200; - res.setHeader('content-type', register.contentType); + const { contentType, body } = await exportMetrics( + req.headers.accept === 'application/json' + ); + res.setHeader('content-type', contentType); res.end(body); } catch (err) { res.statusCode = 500; diff --git a/apps/worker/src/services/metrics.ts b/apps/worker/src/services/metrics.ts deleted file mode 100644 index bf6cdcc0..00000000 --- a/apps/worker/src/services/metrics.ts +++ /dev/null @@ -1,111 +0,0 @@ -import { collectDefaultMetrics, Counter, Histogram, Gauge, Registry } from 'prom-client'; -import { getOpenWorkflow, type WorkflowSpec } from '@when/jobs'; -import type { Workflow } from 'openworkflow'; - -export const register = new Registry(); -register.setDefaultLabels({ app: 'when', service: 'worker' }); - -collectDefaultMetrics({ register }); - -// Prune low-value default metrics to keep the footprint minimal -const metricsToPrune = [ - 'nodejs_active_handles', - 'nodejs_active_handles_total', - 'nodejs_active_requests', - 'nodejs_active_requests_total', - 'nodejs_heap_space_size_total_bytes', - 'nodejs_heap_space_size_used_bytes', - 'nodejs_heap_space_size_available_bytes', - 'nodejs_heap_space_size_bytes_total', - 'nodejs_heap_space_size_bytes_used', - 'nodejs_heap_space_size_bytes_available', - 'nodejs_heap_space_size_bytes_required', - 'nodejs_eventloop_lag_seconds', - 'nodejs_eventloop_lag_min_seconds', - 'nodejs_eventloop_lag_max_seconds', - 'nodejs_eventloop_lag_mean_seconds', - 'nodejs_eventloop_lag_stddev_seconds', - 'nodejs_eventloop_lag_p50_seconds', - 'nodejs_eventloop_lag_p90_seconds', - 'nodejs_eventloop_lag_p99_seconds', - 'process_virtual_memory_bytes', - 'process_virtual_memory_max_bytes', - 'process_heap_bytes', - 'process_start_time_seconds', - 'process_open_fds', - 'process_max_fds' -]; - -for (const metric of metricsToPrune) { - register.removeSingleMetric(metric); -} - -export const jobsTotal = new Counter({ - name: 'when_jobs_total', - help: 'Handler executions by return or escape (including durable suspension), not terminal workflow outcomes.', - labelNames: ['job_name', 'status'], - registers: [register] -}); - -export const jobDuration = new Histogram({ - name: 'when_job_duration_seconds', - help: 'Duration of each workflow handler execution, including executions that durably suspend.', - labelNames: ['job_name'], - registers: [register] -}); - -export const jobsActive = new Gauge({ - name: 'when_jobs_active', - help: 'Number of active workflow handler executions; durably suspended runs are excluded.', - labelNames: ['job_name'], - registers: [register] -}); - -export const emailsTotal = new Counter({ - name: 'when_emails_total', - help: 'Physical SMTP send attempts by outcome, not unique email deliveries.', - labelNames: ['recipient_type', 'status', 'email_kind'], - registers: [register] -}); - -export const calendarSyncTotal = new Counter({ - name: 'when_calendar_sync_total', - help: 'Total number of calendar sync scans triggered.', - labelNames: ['status'], - registers: [register] -}); - -export const calendarSyncDuration = new Histogram({ - name: 'when_calendar_sync_duration_seconds', - help: 'Duration of calendar sync scan loops.', - labelNames: ['provider_type'], - registers: [register] -}); - -export const calendarRefreshTotal = new Counter({ - name: 'when_calendar_refresh_total', - help: 'Total number of calendar refreshes.', - labelNames: ['calendar_id', 'provider_type', 'status'], - registers: [register] -}); - -export function implementObservedWorkflow( - spec: WorkflowSpec, - handler: Workflow['fn'] -): void { - getOpenWorkflow().implementWorkflow(spec, async (args) => { - jobsActive.inc({ job_name: spec.name }); - const timer = jobDuration.startTimer({ job_name: spec.name }); - try { - const result = await handler(args); - jobsTotal.inc({ job_name: spec.name, status: 'returned' }); - return result; - } catch (err) { - jobsTotal.inc({ job_name: spec.name, status: 'escaped' }); - throw err; - } finally { - jobsActive.dec({ job_name: spec.name }); - timer(); - } - }); -} diff --git a/apps/worker/src/services/startup.ts b/apps/worker/src/services/startup.ts index 312770c3..e7ba3b61 100644 --- a/apps/worker/src/services/startup.ts +++ b/apps/worker/src/services/startup.ts @@ -9,7 +9,7 @@ import { } from '@when/jobs'; import { setLogger } from '@when/calendar'; import type { OpenWorkflow } from 'openworkflow'; -import { createMailer } from '../email/smtp.js'; +import { createMailer } from './email.js'; import { registerWorkflows } from '../workflows/index.js'; import { applyConfig } from './config-reload.js'; import { setWorkerContext, type WorkerContext } from './context.js'; diff --git a/apps/worker/src/services/video-chat-cleanup.ts b/apps/worker/src/services/video-chat-cleanup.ts index fa3ce132..ff336b0e 100644 --- a/apps/worker/src/services/video-chat-cleanup.ts +++ b/apps/worker/src/services/video-chat-cleanup.ts @@ -1,4 +1,4 @@ -import { deleteAppointmentFromCalendar } from '@when/calendar'; +import { deleteAppointmentFromCalendar } from './calendar-provider.js'; import { findCalendar } from '@when/config'; import { findAppointment, diff --git a/apps/worker/src/services/video-chat.ts b/apps/worker/src/services/video-chat.ts index bd1d087b..24210b5d 100644 --- a/apps/worker/src/services/video-chat.ts +++ b/apps/worker/src/services/video-chat.ts @@ -6,7 +6,8 @@ import { type Appointment, type CalendarEventReference } from '@when/db'; -import { getGoogleEvent, patchGoogleEvent, pushAppointment } from '@when/calendar'; +import { getGoogleEvent, patchGoogleEvent } from '@when/calendar'; +import { pushAppointment } from './calendar-provider.js'; import { getVideoChatAdapter, shouldAttachVideoChat, diff --git a/apps/worker/src/services/workflow-registration.ts b/apps/worker/src/services/workflow-registration.ts new file mode 100644 index 00000000..2dae69ec --- /dev/null +++ b/apps/worker/src/services/workflow-registration.ts @@ -0,0 +1,11 @@ +import { getOpenWorkflow, type WorkflowSpec } from '@when/jobs'; +import type { Workflow } from 'openworkflow'; +import { observeWorkflow } from '../metrics/workflows.js'; + +/** Public registration boundary for worker workflow handlers. */ +export function implementWorkflow( + spec: WorkflowSpec, + handler: Workflow['fn'] +): void { + getOpenWorkflow().implementWorkflow(spec, observeWorkflow(spec, handler)); +} diff --git a/apps/worker/src/workflows/deliver-appointment-email.test.ts b/apps/worker/src/workflows/deliver-appointment-email.test.ts index 2a89991c..a65345ce 100644 --- a/apps/worker/src/workflows/deliver-appointment-email.test.ts +++ b/apps/worker/src/workflows/deliver-appointment-email.test.ts @@ -7,7 +7,8 @@ import type { SendResult } from '../email/smtp.js'; import * as status from '../email/status.js'; import { setWorkerContext } from '../services/context.js'; import { createLogger } from '../services/logger.js'; -import { emailsTotal } from '../services/metrics.js'; +import { emailsTotal, operationFailuresTotal, register } from '../metrics/registry.js'; +import { observeMailer } from '../metrics/email.js'; import { deliverAppointmentEmail, runDeliverAppointmentEmail @@ -39,11 +40,18 @@ function directStep(before?: (config: StepConfig) => Promise) { let db: ReturnType; let send: ReturnType Promise>>; beforeEach(async () => { + emailsTotal.reset(); + operationFailuresTotal.reset(); db = openDb(':memory:'); await runMigrations(db); await db.insertInto('appointments').values(sampleAppointment).execute(); send = vi.fn(async () => ({ ok: true })); - setWorkerContext({ db, config: sampleConfig, logger: createLogger(), mailer: { send } }); + setWorkerContext({ + db, + config: sampleConfig, + logger: createLogger(), + mailer: observeMailer({ send }) + }); }); afterEach(async () => { vi.restoreAllMocks(); @@ -86,18 +94,14 @@ describe('delivery attempt boundaries', () => { }); test('records an observed failure inside the callback before throwing to the engine', async () => { - send.mockResolvedValue({ ok: false, reason: 'SMTP unavailable' }); - const increment = vi.spyOn(emailsTotal, 'inc'); + send.mockResolvedValue({ ok: false, reason: 'SMTP unavailable', code: 'unknown' }); + const step = directStep(); await expect(runDeliverAppointmentEmail(input, step, clock)).rejects.toThrow( 'SMTP unavailable' ); expect(step.configs.map((config) => config.name)).toEqual(['smtp']); - expect(increment).toHaveBeenCalledWith({ - recipient_type: 'guest', - email_kind: 'confirmed', - status: 'failure' - }); + const entries = await emailEntries(); expect(entries).toEqual([ expect.objectContaining({ @@ -119,7 +123,7 @@ describe('delivery attempt boundaries', () => { test.each([ { name: 'successful', result: { ok: true } }, - { name: 'failed', result: { ok: false, reason: 'SMTP unavailable' } } + { name: 'failed', result: { ok: false, reason: 'SMTP unavailable', code: 'unknown' } } ] as const)('captures the $name attempt time before recording its status', async ({ result }) => { const sentAt = '2026-02-01T12:01:00.000Z'; const writtenAt = '2026-02-01T12:10:00.000Z'; @@ -164,17 +168,34 @@ describe('delivery attempt boundaries', () => { } ); - test('a success-status error escapes without a provider-failure log or metric', async () => { + test('a success-status error escapes without a provider-failure log', async () => { const fault = new Error('local status write failed'); vi.spyOn(status, 'recordSendOutcome').mockRejectedValueOnce(fault); - const increment = vi.spyOn(emailsTotal, 'inc'); + const step = directStep(); await expect(runDeliverAppointmentEmail(input, step, clock)).rejects.toBe(fault); expect(step.configs.map((config) => config.name)).toEqual(['smtp', 'smtp:status']); expect(send).toHaveBeenCalledTimes(1); const entries = await emailEntries(); expect(entries).toEqual([]); - expect(increment).not.toHaveBeenCalledWith(expect.objectContaining({ status: 'failure' })); + const snapshot = await register.getMetricsAsJSON(); + expect(snapshot.find((metric) => metric.name === 'when_emails_total')?.values).toEqual([ + expect.objectContaining({ + labels: { + app: 'when', + service: 'worker', + recipient_type: 'guest', + email_kind: 'confirmed', + status: 'success' + }, + value: 1 + }) + ]); + expect( + snapshot + .find((metric) => metric.name === 'when_operation_failures_total') + ?.values.filter(({ labels }) => labels.operation === 'smtp_send') + ).toEqual([]); }); test('does not catch opaque errors from a durable call', async () => { @@ -188,5 +209,12 @@ describe('delivery attempt boundaries', () => { expect(send).not.toHaveBeenCalled(); const entries = await emailEntries(); expect(entries).toEqual([]); + const snapshot = await register.getMetricsAsJSON(); + expect(snapshot.find((metric) => metric.name === 'when_emails_total')?.values).toEqual([]); + expect( + snapshot + .find((metric) => metric.name === 'when_operation_failures_total') + ?.values.filter(({ labels }) => labels.operation === 'smtp_send') + ).toEqual([]); }); }); diff --git a/apps/worker/src/workflows/deliver-appointment-email.ts b/apps/worker/src/workflows/deliver-appointment-email.ts index 75c46608..d12af3e8 100644 --- a/apps/worker/src/workflows/deliver-appointment-email.ts +++ b/apps/worker/src/workflows/deliver-appointment-email.ts @@ -5,7 +5,8 @@ import { systemClock, type Clock } from '../email/clock.js'; import { recordSendOutcome } from '../email/status.js'; import { getWorkerContext } from '../services/context.js'; import { appendEmailJobLog } from '../services/job-log.js'; -import { implementObservedWorkflow, emailsTotal } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; +import { sendAppointmentEmail } from '../services/email.js'; export interface DeliverAppointmentEmailInput { appointmentId: string; @@ -53,14 +54,8 @@ export async function runDeliverAppointmentEmail( .executeTakeFirst(); if (!row) return null; - const result = await ctx.mailer.send(input.envelope); + const result = await sendAppointmentEmail(ctx.mailer, input.envelope, input.role, input.kind); const observedAt = clock.now().toISOString(); - const deliveryStatus = result.ok ? 'success' : 'failure'; - emailsTotal.inc({ - recipient_type: input.role, - email_kind: input.kind, - status: deliveryStatus - }); if (!result.ok) { await recordSendOutcome(ctx, result, observedAt); await appendEmailJobLog(ctx.db, input.appointmentId, 'failed', observedAt); @@ -76,7 +71,7 @@ export async function runDeliverAppointmentEmail( } export function registerDeliverAppointmentEmailWorkflow(): void { - implementObservedWorkflow(deliverAppointmentEmail, ({ input, step }) => + implementWorkflow(deliverAppointmentEmail, ({ input, step }) => runDeliverAppointmentEmail(input, step) ); } diff --git a/apps/worker/src/workflows/expire-pending-appointments.ts b/apps/worker/src/workflows/expire-pending-appointments.ts index addd7570..4849bbed 100644 --- a/apps/worker/src/workflows/expire-pending-appointments.ts +++ b/apps/worker/src/workflows/expire-pending-appointments.ts @@ -1,8 +1,8 @@ -import { expireStalePending } from '@when/db'; import { expirePendingAppointments, type ExpirePendingAppointmentsResult } from '@when/jobs'; import { systemClock, type Clock } from '../email/clock.js'; import { getWorkerContext } from '../services/context.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; +import { expirePending } from '../services/appointments.js'; interface ExpiryStep { run(config: { name: string }, fn: () => Promise): Promise; @@ -14,14 +14,14 @@ export async function runExpirePendingAppointments( ): Promise { await step.run({ name: 'expire-pending-appointments' }, async () => { const ctx = getWorkerContext(); - const count = await expireStalePending(ctx.db, clock.now().toISOString()); - if (count > 0) ctx.logger.info({ count }, 'expired stale pending requests'); + const count = await expirePending(ctx.db, clock.now().toISOString()); + if (count > 0) { + ctx.logger.info({ count }, 'expired stale pending requests'); + } }); return 'expired'; } export function registerExpirePendingAppointmentsWorkflow(): void { - implementObservedWorkflow(expirePendingAppointments, ({ step }) => - runExpirePendingAppointments(step) - ); + implementWorkflow(expirePendingAppointments, ({ step }) => runExpirePendingAppointments(step)); } diff --git a/apps/worker/src/workflows/generate-video-chat.integration.test.ts b/apps/worker/src/workflows/generate-video-chat.integration.test.ts index 6858bcc7..182b70fe 100644 --- a/apps/worker/src/workflows/generate-video-chat.integration.test.ts +++ b/apps/worker/src/workflows/generate-video-chat.integration.test.ts @@ -349,7 +349,7 @@ describe('durable background video generation with native concurrency one', () = test('approval while the original pending notice is parked stops its failed-request continuation', async () => { await db.updateTable('appointments').set({ status: 'pending' }).execute(); vi.mocked(patchGoogleEvent).mockRejectedValueOnce(new Error('Google PATCH HTTP 503')); - send.mockResolvedValueOnce({ ok: false, reason: 'temporary SMTP failure' }); + send.mockResolvedValueOnce({ ok: false, reason: 'temporary SMTP failure', code: 'unknown' }); const queue = openQueue(); try { const generation = await queue.client.runWorkflow(generateVideoChat, { @@ -840,7 +840,7 @@ describe('durable background video generation with native concurrency one', () = test('original SMTP exhaustion fails generation before any later provider retry', async () => { requestOutcome = 'pending'; - send.mockResolvedValue({ ok: false, reason: 'SMTP unavailable' }); + send.mockResolvedValue({ ok: false, reason: 'SMTP unavailable', code: 'unknown' }); const queue = openQueue(); try { const generation = await queue.client.runWorkflow(generateVideoChat, { diff --git a/apps/worker/src/workflows/generate-video-chat.ts b/apps/worker/src/workflows/generate-video-chat.ts index 330beb04..3fa387fb 100644 --- a/apps/worker/src/workflows/generate-video-chat.ts +++ b/apps/worker/src/workflows/generate-video-chat.ts @@ -11,7 +11,7 @@ import { type CalendarEventReference } from '@when/db'; import { getWorkerContext, type WorkerContext } from '../services/context.js'; -import { reconcileAppointment as syncCalendarForAppointment } from '../calendar/sync.js'; +import { reconcileAppointment as syncCalendarForAppointment } from '../services/calendar.js'; import { tryBookVideoChatEvent, publishVideoChat, @@ -28,7 +28,7 @@ import { removeUnusedVideoChat } from '../services/video-chat-cleanup.js'; import { systemClock, type Clock } from '../email/clock.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; import { notifyAppointment, type NotifyAppointmentInput, @@ -356,7 +356,5 @@ async function selectedVideoChatUrl( } export function registerGenerateVideoChatWorkflow(): void { - implementObservedWorkflow(generateVideoChat, ({ input, step }) => - runGenerateVideoChat(input, step) - ); + implementWorkflow(generateVideoChat, ({ input, step }) => runGenerateVideoChat(input, step)); } diff --git a/apps/worker/src/workflows/maintenance.integration.test.ts b/apps/worker/src/workflows/maintenance.integration.test.ts index 1bacbeba..99944a0a 100644 --- a/apps/worker/src/workflows/maintenance.integration.test.ts +++ b/apps/worker/src/workflows/maintenance.integration.test.ts @@ -21,6 +21,7 @@ import { fetchBusyIntervals, pushAppointment } from '@when/calendar'; import { sampleAppointment, sampleConfig } from '../email/__fixtures__/appointment.js'; import { setWorkerContext, type WorkerContext } from '../services/context.js'; import { createLogger } from '../services/logger.js'; +import { jobDuration, jobsActive, jobsTotal, register } from '../metrics/registry.js'; import { registerWorkflows } from './index.js'; const engine = vi.hoisted(() => ({ client: null as OpenWorkflow | null })); @@ -42,6 +43,9 @@ let worker: Worker; let ctx: WorkerContext; beforeEach(async () => { + jobsTotal.reset(); + jobDuration.reset(); + jobsActive.reset(); vi.useFakeTimers({ toFake: ['Date'] }); vi.setSystemTime(new Date(at)); vi.mocked(fetchBusyIntervals).mockReset().mockResolvedValue([]); @@ -130,6 +134,27 @@ test('producer-only enqueue and implementation registration persist no schedules await drain(1); const syncResult = await run.result({ timeoutMs: 500 }); expect(syncResult).toBe('requested'); + const snapshot = await register.getMetricsAsJSON(); + expect(snapshot.find((metric) => metric.name === 'when_jobs_total')?.values).toEqual([ + expect.objectContaining({ + labels: { app: 'when', service: 'worker', job_name: 'sync-calendars', status: 'returned' }, + value: 1 + }) + ]); + const duration = await jobDuration.get(); + expect( + duration.values.filter(({ metricName }) => metricName === 'when_job_duration_seconds_count') + ).toEqual([expect.objectContaining({ labels: { job_name: 'sync-calendars' }, value: 1 })]); + expect( + snapshot + .find((metric) => metric.name === 'when_jobs_active') + ?.values.filter(({ labels }) => labels.job_name === 'sync-calendars') + ).toEqual([ + expect.objectContaining({ + labels: { app: 'when', service: 'worker', job_name: 'sync-calendars' }, + value: 0 + }) + ]); const schedulesAfterDrain = await schedules(); expect(schedulesAfterDrain).toEqual([]); }); diff --git a/apps/worker/src/workflows/notify-appointment.test.ts b/apps/worker/src/workflows/notify-appointment.test.ts index b79c3929..e10f13b1 100644 --- a/apps/worker/src/workflows/notify-appointment.test.ts +++ b/apps/worker/src/workflows/notify-appointment.test.ts @@ -255,7 +255,7 @@ describe('notify appointment', () => { const notification = { ...input, kind: 'video-chat-added', videoChatUrl: uri } as const; send.mockImplementation(async (envelope) => envelope.to === sampleAppointment.guest_email - ? { ok: false, reason: 'guest SMTP down' } + ? { ok: false, reason: 'guest SMTP down', code: 'unknown' } : { ok: true } ); const first = runNotifyAppointment(notification, f.step, clock); @@ -294,7 +294,7 @@ describe('notify appointment', () => { test('SMTP failure escapes; replay reuses prepared envelopes and URI despite a changed row', async () => { const prepare = vi.spyOn(dispatch, 'prepareAppointmentEmails'); const f = nativeStep(); - send.mockResolvedValue({ ok: false, reason: 'SMTP down' }); + send.mockResolvedValue({ ok: false, reason: 'SMTP down', code: 'unknown' }); const first = runNotifyAppointment(input, f.step, clock); await expect(first).rejects.toThrow('SMTP down'); await Promise.allSettled(f.children); @@ -319,7 +319,7 @@ describe('notify appointment', () => { await db.updateTable('appointments').set({ guest_email: sampleConfig.user.email }).execute(); const f = nativeStep(); send - .mockResolvedValueOnce({ ok: false, reason: 'guest failed' }) + .mockResolvedValueOnce({ ok: false, reason: 'guest failed', code: 'unknown' }) .mockResolvedValue({ ok: true }); const first = runNotifyAppointment(input, f.step, clock); await expect(first).rejects.toThrow('guest failed'); diff --git a/apps/worker/src/workflows/notify-appointment.ts b/apps/worker/src/workflows/notify-appointment.ts index 47344144..0ce4450e 100644 --- a/apps/worker/src/workflows/notify-appointment.ts +++ b/apps/worker/src/workflows/notify-appointment.ts @@ -5,7 +5,7 @@ import { prepareAppointmentEmails } from '../email/dispatch.js'; import { systemClock, type Clock } from '../email/clock.js'; import { getWorkerContext } from '../services/context.js'; import { appendEmailJobLog } from '../services/job-log.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; import { deliverAppointmentEmail, type DeliverAppointmentEmailInput, @@ -71,7 +71,5 @@ export async function runNotifyAppointment( } export function registerNotifyAppointmentWorkflow(): void { - implementObservedWorkflow(notifyAppointment, ({ input, step }) => - runNotifyAppointment(input, step) - ); + implementWorkflow(notifyAppointment, ({ input, step }) => runNotifyAppointment(input, step)); } diff --git a/apps/worker/src/workflows/probe-calendar.ts b/apps/worker/src/workflows/probe-calendar.ts index d1416be5..6bac424c 100644 --- a/apps/worker/src/workflows/probe-calendar.ts +++ b/apps/worker/src/workflows/probe-calendar.ts @@ -1,9 +1,10 @@ import { testCalendar } from '@when/jobs'; import { findCalendar } from '@when/config'; import type { TestCalendarInput, TestCalendarResult } from '@when/jobs'; -import { refreshCalendar, refreshWindow } from '../calendar/refresh.js'; +import { refreshCalendar } from '../services/calendar.js'; +import { refreshWindow } from '../calendar/refresh-calendar.js'; import { getWorkerContext } from '../services/context.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; export async function runTestCalendar(input: TestCalendarInput): Promise { const ctx = getWorkerContext(); @@ -20,5 +21,5 @@ export async function runTestCalendar(input: TestCalendarInput): Promise runTestCalendar(input)); + implementWorkflow(testCalendar, ({ input }) => runTestCalendar(input)); } diff --git a/apps/worker/src/workflows/probe-provider.ts b/apps/worker/src/workflows/probe-provider.ts index dfe0f8cc..85ab51ad 100644 --- a/apps/worker/src/workflows/probe-provider.ts +++ b/apps/worker/src/workflows/probe-provider.ts @@ -8,7 +8,7 @@ import type { TestProviderResult } from '@when/jobs'; import { getWorkerContext, type WorkerContext } from '../services/context.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; function configuredAdapter(ctx: WorkerContext, name: string): ProviderAdapter { const provider = ctx.config.providers[name]; @@ -50,6 +50,6 @@ export async function runListProviderCalendars( } export function registerProbeProviderWorkflows(): void { - implementObservedWorkflow(testProvider, ({ input }) => runTestProvider(input)); - implementObservedWorkflow(listProviderCalendars, ({ input }) => runListProviderCalendars(input)); + implementWorkflow(testProvider, ({ input }) => runTestProvider(input)); + implementWorkflow(listProviderCalendars, ({ input }) => runListProviderCalendars(input)); } diff --git a/apps/worker/src/workflows/purge-appointment.ts b/apps/worker/src/workflows/purge-appointment.ts index 6e42474b..0f6d8f3d 100644 --- a/apps/worker/src/workflows/purge-appointment.ts +++ b/apps/worker/src/workflows/purge-appointment.ts @@ -1,10 +1,10 @@ import type { RetryPolicy } from 'openworkflow'; -import { deleteAppointmentFromCalendar } from '@when/calendar'; +import { deleteAppointmentFromCalendar } from '../services/calendar-provider.js'; import { findAppointment, listActiveAppointmentsForCalendarEvent } from '@when/db'; import { purgeAppointment } from '@when/jobs/specs'; import type { PurgeAppointmentInput, PurgeAppointmentResult } from '@when/jobs'; import { getWorkerContext } from '../services/context.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; import { cleanupStandaloneVideoChat } from '../services/video-chat-cleanup.js'; const CALENDAR_RETRY: Partial = { @@ -53,7 +53,5 @@ export async function runPurgeAppointment( } export function registerPurgeAppointmentWorkflow(): void { - implementObservedWorkflow(purgeAppointment, ({ input, step }) => - runPurgeAppointment(input, step) - ); + implementWorkflow(purgeAppointment, ({ input, step }) => runPurgeAppointment(input, step)); } diff --git a/apps/worker/src/workflows/reconcile-appointment.integration.test.ts b/apps/worker/src/workflows/reconcile-appointment.integration.test.ts index 46afc659..d95e810d 100644 --- a/apps/worker/src/workflows/reconcile-appointment.integration.test.ts +++ b/apps/worker/src/workflows/reconcile-appointment.integration.test.ts @@ -208,7 +208,7 @@ function failingMailer(failures: Record) { const role = envelope.to === config.user.email ? 'host' : 'guest'; counts[role] += 1; return counts[role] <= failures[role] - ? { ok: false, reason: `SMTP ${role} unavailable` } + ? { ok: false, reason: `SMTP ${role} unavailable`, code: 'unknown' } : { ok: true }; }); return counts; @@ -1059,7 +1059,7 @@ describe('appointment email reconciliation with native children', () => { test('a native SMTP retry rechecks eligibility after a queue restart', async () => { const directory = await mkdtemp(join(tmpdir(), 'when-email-eligibility-')); - send.mockResolvedValue({ ok: false, reason: 'temporary SMTP failure' }); + send.mockResolvedValue({ ok: false, reason: 'temporary SMTP failure', code: 'unknown' }); let queue = openQueue(join(directory, 'queue.sqlite')); try { const parent = await queue.client.runWorkflow(reconcileAppointment, input); diff --git a/apps/worker/src/workflows/reconcile-appointment.ts b/apps/worker/src/workflows/reconcile-appointment.ts index 2ff086ef..32ae9873 100644 --- a/apps/worker/src/workflows/reconcile-appointment.ts +++ b/apps/worker/src/workflows/reconcile-appointment.ts @@ -14,8 +14,8 @@ import { findAppointment, type Appointment } from '@when/db'; import { getWorkerContext, type WorkerContext } from '../services/context.js'; import { videoChatResource, wantsGeneratedVideoChat } from '../services/video-chat.js'; import { removeUnusedVideoChat } from '../services/video-chat-cleanup.js'; -import { reconcileAppointment as syncCalendarForAppointment } from '../calendar/sync.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { reconcileAppointment as syncCalendarForAppointment } from '../services/calendar.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; import { notifyAppointment, type NotifyAppointmentInput, @@ -169,7 +169,7 @@ async function enqueueVideoChat( } export function registerReconcileAppointmentWorkflow(): void { - implementObservedWorkflow(reconcileAppointment, ({ input, step }) => + implementWorkflow(reconcileAppointment, ({ input, step }) => runReconcileAppointment(input, step) ); } diff --git a/apps/worker/src/workflows/refresh-calendars.ts b/apps/worker/src/workflows/refresh-calendars.ts index 84820c67..34964260 100644 --- a/apps/worker/src/workflows/refresh-calendars.ts +++ b/apps/worker/src/workflows/refresh-calendars.ts @@ -1,7 +1,8 @@ import { refreshCalendars, type RefreshCalendarsResult } from '@when/jobs'; -import { refreshCycle, type RefreshOptions } from '../calendar/refresh.js'; +import { refreshCycle } from '../calendar/refresh.js'; +import type { RefreshOptions } from '../calendar/refresh-calendar.js'; import { getWorkerContext } from '../services/context.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; interface RefreshStep { run(config: { name: string }, fn: () => Promise): Promise; @@ -18,5 +19,5 @@ export async function runRefreshCalendars( } export function registerRefreshCalendarsWorkflow(): void { - implementObservedWorkflow(refreshCalendars, ({ step }) => runRefreshCalendars(step)); + implementWorkflow(refreshCalendars, ({ step }) => runRefreshCalendars(step)); } diff --git a/apps/worker/src/workflows/sync-calendars.ts b/apps/worker/src/workflows/sync-calendars.ts index f04e03f6..d4d81028 100644 --- a/apps/worker/src/workflows/sync-calendars.ts +++ b/apps/worker/src/workflows/sync-calendars.ts @@ -1,7 +1,7 @@ import { syncCalendars, type SyncCalendarsResult } from '@when/jobs'; -import { scanOnce } from '../calendar/sync.js'; +import { scanOnce } from '../services/calendar-scan.js'; import { getWorkerContext } from '../services/context.js'; -import { calendarSyncTotal, implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; interface SyncStep { run(config: { name: string }, fn: () => Promise): Promise; @@ -10,17 +10,11 @@ interface SyncStep { export async function runSyncCalendars(step: SyncStep): Promise { await step.run({ name: 'scan-calendars' }, async () => { const ctx = getWorkerContext(); - try { - await scanOnce(ctx); - calendarSyncTotal.inc({ status: 'success' }); - } catch (error) { - calendarSyncTotal.inc({ status: 'failure' }); - throw error; - } + await scanOnce(ctx); }); return 'requested'; } export function registerSyncCalendarsWorkflow(): void { - implementObservedWorkflow(syncCalendars, ({ step }) => runSyncCalendars(step)); + implementWorkflow(syncCalendars, ({ step }) => runSyncCalendars(step)); } diff --git a/apps/worker/src/workflows/test-email.test.ts b/apps/worker/src/workflows/test-email.test.ts index f86beddd..b27e2a09 100644 --- a/apps/worker/src/workflows/test-email.test.ts +++ b/apps/worker/src/workflows/test-email.test.ts @@ -51,7 +51,7 @@ describe('runTestEmail', () => { }); test('throws when the mailer reports failure', async () => { - setContext({ ok: false, reason: 'SMTP 535 auth failed' }); + setContext({ ok: false, reason: 'SMTP 535 auth failed', code: 'auth' }); const observedAt = '2026-02-01T12:01:00.000Z'; const clock = { now: () => new Date(observedAt) }; await expect(runTestEmail({ to: 'me@example.com' }, clock)).rejects.toThrow( diff --git a/apps/worker/src/workflows/test-email.ts b/apps/worker/src/workflows/test-email.ts index b09e5491..e48f5ac5 100644 --- a/apps/worker/src/workflows/test-email.ts +++ b/apps/worker/src/workflows/test-email.ts @@ -7,7 +7,7 @@ import { emailTheme } from '../email/theme.js'; import { recordSendOutcome } from '../email/status.js'; import { systemClock, type Clock } from '../email/clock.js'; import { testEmailMessage } from '../email/builders/test-email.js'; -import { implementObservedWorkflow } from '../services/metrics.js'; +import { implementWorkflow } from '../services/workflow-registration.js'; export async function runTestEmail( input: TestEmailInput, @@ -25,5 +25,5 @@ export async function runTestEmail( } export function registerTestEmailWorkflow(): void { - implementObservedWorkflow(testEmail, ({ input }) => runTestEmail(input)); + implementWorkflow(testEmail, ({ input }) => runTestEmail(input)); } diff --git a/docs/architecture.md b/docs/architecture.md index 1eeaf6ed..8fc8c175 100644 --- a/docs/architecture.md +++ b/docs/architecture.md @@ -49,6 +49,14 @@ commands. Worker stop is not queue draining. See [updates](deployment.md#updates) before deploying changed workflow graphs. +## Instrumentation + +Prometheus code lives in each app's metrics area. Public appointment APIs and +worker service facades wire the observers. HTTP routes explicitly record known +outcomes through those metrics modules; auth uses its native hooks. Domain +implementations do not import Prometheus or record metrics. +See [metrics](metrics.md) for what the counters mean. + ## Time Use native `Temporal` on the server and `temporal-polyfill/fns/*` in the browser. diff --git a/docs/config.md b/docs/config.md index 7d5bdc7b..4dc2c786 100644 --- a/docs/config.md +++ b/docs/config.md @@ -382,11 +382,12 @@ URL; see the [proxy requirements](deployment.md#reverse-proxy). ## `prometheus` -| Field | Default | Meaning | -| --------- | ------------------------- | ----------------------------------------- | -| `enabled` | `false` | Enable metrics collection and `/metrics`. | -| `token` | `${WHEN_METRICS_TOKEN:-}` | Bearer token required for scraping. | +| Field | Default | Meaning | +| --------- | ------------------------- | -------------------------------------------------- | +| `enabled` | `false` | Expose `/metrics`; instrumentation remains active. | +| `token` | `${WHEN_METRICS_TOKEN:-}` | Bearer token required for scraping. | When disabled, `/metrics` returns 404. When enabled without a non-empty token, it returns 500, not public metrics. Scrape with `Authorization: Bearer `. -See [operating endpoints](deployment.md#inspect-logs). +See [operating endpoints](deployment.md#inspect-logs) and the +[metrics reference](metrics.md) for collection health, action counts and job semantics. diff --git a/docs/metrics.md b/docs/metrics.md new file mode 100644 index 00000000..ac19d55c --- /dev/null +++ b/docs/metrics.md @@ -0,0 +1,90 @@ +# Metrics + +One scrape, at web's `/metrics`. Web fetches the worker over private HTTP and +returns both. No database queries. No public worker port. + +Enable `prometheus.enabled` and set `prometheus.token` in +[`when.yaml`](config.md#prometheus). Send `Authorization: Bearer ` when +scraping. Turning the endpoint off does not stop the application counters. + +## Is it up? + +Prometheus `up` checks the web endpoint. `when_worker_scrape_success` is 1 if web +collected the worker's metrics, 0 otherwise. Web waits up to two seconds. If the +worker fails, the response is still HTTP 200, with web metrics only. Old worker +samples are not kept. + +That checks reachability, not whether jobs are making progress or email works. + +Application metrics carry `app="when"` and `service="web"|"worker"`; the +scrape-success flag has only `app`. There are no Node collectors or background +sampling timers. Use host or container monitoring for CPU and memory. + +## Appointments + +`when_appointment_operations_total{action,actor,status}` counts operation outcomes: + +- `create`, `cancel`, `reschedule`: host or guest. +- `accept`, `decline`: host. +- `expire`: system. + +Status is `success`, `rejected` or `error`. Bulk actions count each operation. +Expiry counts one invocation, even if there were no rows to expire. Rescheduling +counts once, not as another creation. + +These are not committed-row counts. If a write succeeds but enqueueing fails, +the operation counts as an error. Use the database for saved appointment totals. + +Booking attempts, logins and ICS requests keep their own counters. These are +not unique-user counts. Booking failures use `invalid_input`, `slot_taken` or +`error`; an error is not necessarily a database failure. Booking counts explicit +validation, availability and creation outcomes, not every HTTP failure. + +## Jobs + +| Metric | What it measures | +| ------------------------------------------ | ---------------------------------------------------------------------- | +| `when_jobs_active{job_name}` | Handlers executing now. Zero when idle. | +| `when_job_oldest_active_seconds{job_name}` | How long the oldest active handler has been executing. Zero when idle. | +| `when_job_duration_seconds{job_name}` | Duration of each handler execution. | +| `when_jobs_total{job_name,status}` | Executions that `returned` or `escaped`. | + +Waiting workflows aren't active handlers. A handler can escape normally to wait +for a child workflow, so `escaped` does **not** mean failed. Durations exclude +parked time; they don't measure the workflow's full lifetime. + +These signals show activity without reading the queue database. They don't tell +you the backlog or how many workflows finished or failed. Use queue history for +that. + +## Failures + +`when_operation_failures_total{operation,code}` groups failed attempts: + +| Operation | Codes | +| ----------------------------------- | ------------------------------------------------------------------------------ | +| `worker_scrape` | `unauthorized`, `http_error`, `timeout`, `transport_error`, `invalid_snapshot` | +| `smtp_send` | `auth`, `timeout`, `connection`, `rejected`, `unknown` | +| `calendar_refresh` | `provider_error` | +| `calendar_write`, `calendar_delete` | `not_configured`, `provider_error` | + +Retries are new attempts. SMTP failures include test emails; `when_emails_total` +counts appointment sends only. A successful send is not proof of inbox delivery. +Calendar provider errors aren't split further. Write/delete failures include +calendar calls made by reconciliation, video booking, cleanup and purge. Details +belong in logs and admin history, not labels. + +Calendar refresh counters report import outcomes. Calendar sync counters report +scan outcomes, not every remote write. Sync duration measures one appointment's +reconciliation, not the whole scan. + +Counters reset on restart. Use Prometheus rates or increases, not raw totals as +an audit trail. + +## Code placement + +Prometheus code lives in web's `src/lib/server/metrics/` and worker's `src/metrics/`. +Public operation facades and startup wire the observers. HTTP routes call typed +outcome recorders at known decision points, rather than wrapping handlers or +inferring outcomes from response codes. Domain implementations do not record +metrics. Lint rejects direct Prometheus and registry imports outside those areas. diff --git a/pnpm-lock.yaml b/pnpm-lock.yaml index ae487984..8d2e4b0e 100644 --- a/pnpm-lock.yaml +++ b/pnpm-lock.yaml @@ -131,6 +131,9 @@ importers: '@internationalized/date': specifier: 3.12.2 version: 3.12.2 + '@prometheus-io/client': + specifier: 0.16.1 + version: 0.16.1 '@when/calendar': specifier: workspace:* version: link:../../packages/calendar @@ -164,9 +167,6 @@ importers: pino: specifier: 10.3.1 version: 10.3.1 - prom-client: - specifier: 15.1.3 - version: 15.1.3 takumi-js: specifier: 2.2.0 version: 2.2.0(preact@10.24.3) @@ -255,6 +255,9 @@ importers: apps/worker: dependencies: + '@prometheus-io/client': + specifier: 0.16.1 + version: 0.16.1 '@when/calendar': specifier: workspace:* version: link:../../packages/calendar @@ -285,9 +288,6 @@ importers: pino: specifier: 10.3.1 version: 10.3.1 - prom-client: - specifier: 15.1.3 - version: 15.1.3 ts-ics: specifier: 2.4.4 version: 2.4.4 @@ -1051,6 +1051,10 @@ packages: '@polka/url@1.0.0-next.29': resolution: {integrity: sha512-wwQAWhWSuHaag8c4q/KN/vCoeOJYshAIvMQwD4GpSb3OiZklFfvAgmj0VCBBImRpuF/aFgIRzllXlVX93Jevww==} + '@prometheus-io/client@0.16.1': + resolution: {integrity: sha512-XkFPsGFGoSs/UMg/vh0QLDpanl/tsrOV5PLHdpGe8Ho+ir/Llhytr15j6y8ZwLrpIGzK9gTVVpIalA6C4UjUZw==} + engines: {node: ^22 || ^24 || >=26} + '@rgrove/parse-xml@5.0.0': resolution: {integrity: sha512-SgHFyisNAkS2ZbM8SCriUm1N0bxLiz0POKvpDeAtrnLrXaYG1PawNwu1rSjmE/vcVHbZzYWNgVP6xkep6R4uXg==} engines: {node: '>=22.12.0'} @@ -2178,10 +2182,6 @@ packages: process-warning@5.0.0: resolution: {integrity: sha512-a39t9ApHNx2L4+HBnQKqxxHNs1r7KF+Intd8Q/g1bUh6q0WIp9voPXJ/x0j+ZL45KF1pJd9+q2jLIRMfvEshkA==} - prom-client@15.1.3: - resolution: {integrity: sha512-6ZiOBfCywsD4k1BN9IX0uZhF+tJkV8q8llP64G5Hajs4JOeVLPCwpPVcpXy3BwYiUGgyJzsJJQeOIv7+hDSq8g==} - engines: {node: ^16 || ^18 || >=20} - pump@3.0.4: resolution: {integrity: sha512-VS7sjc6KR7e1ukRFhQSY5LM2uBWAUPiOPa/A3mkKmiMwSmRFUITt0xuj+/lesgnCv+dPIEYlkzrcyXgquIHMcA==} @@ -2996,6 +2996,11 @@ snapshots: '@polka/url@1.0.0-next.29': {} + '@prometheus-io/client@0.16.1': + dependencies: + '@opentelemetry/api': 1.9.1 + tdigest: 0.1.2 + '@rgrove/parse-xml@5.0.0': {} '@rolldown/binding-android-arm64@1.0.3': @@ -3992,11 +3997,6 @@ snapshots: process-warning@5.0.0: {} - prom-client@15.1.3: - dependencies: - '@opentelemetry/api': 1.9.1 - tdigest: 0.1.2 - pump@3.0.4: dependencies: end-of-stream: 1.4.5