diff --git a/.changeset/log-otp-verification-failures.md b/.changeset/log-otp-verification-failures.md new file mode 100644 index 00000000..e160c25b --- /dev/null +++ b/.changeset/log-otp-verification-failures.md @@ -0,0 +1,14 @@ +--- +'ePDS': patch +--- + +Failed sign-in code entries now show up in the server logs, split by reason. + +**Affects:** Operators + +**Operators:** the auth service now logs its own 4xx client errors — most usefully the sign-in code failures that the browser posts straight to `/api/auth/sign-in/email-otp`, which previously reached no log at all. + +- Each failure is logged at `warn` (visible at the default `info` level, no `LOG_LEVEL` change needed) under the `auth:better-auth` logger name, with the message `better-auth API error` and a `message` field carrying the reason verbatim: `OTP expired`, `Invalid OTP`, or `Too many attempts`. +- Counting `OTP expired` vs `Invalid OTP` over time separates users whose code genuinely lapsed (late email delivery) from users retyping a stale code, so a rise in `OTP expired` points at delivery delay rather than user error. +- Only 4xx errors are logged here; 3xx redirects are filtered out and 5xx errors are already logged by the framework, so this adds no duplicate 5xx noise. +- The email address is not included: the framework hands this logging hook the instance-wide context, not the per-request body, so the address is not reliably available at that point. diff --git a/packages/auth-service/src/__tests__/log-better-auth-api-error.test.ts b/packages/auth-service/src/__tests__/log-better-auth-api-error.test.ts new file mode 100644 index 00000000..d39d2094 --- /dev/null +++ b/packages/auth-service/src/__tests__/log-better-auth-api-error.test.ts @@ -0,0 +1,105 @@ +/** + * Tests for logBetterAuthApiError — the bridge that surfaces better-auth's + * 4xx client errors (notably "OTP expired" vs "Invalid OTP") in our pino logs. + * + * These are exactly the errors better-auth throws from its email-otp verify + * endpoint (better-auth 1.4.18 dist/plugins/email-otp/routes.mjs), which the + * browser posts to directly and which were previously logged nowhere. + */ +import { describe, it, expect, vi } from 'vitest' +import { APIError } from 'better-auth/api' +import { logBetterAuthApiError } from '../better-auth.js' + +/** Minimal stand-in for the pino logger — only `warn` is exercised. */ +function makeLogger() { + return { warn: vi.fn() } as unknown as Parameters< + typeof logBetterAuthApiError + >[1] +} + +describe('logBetterAuthApiError', () => { + it('logs an expired-OTP error at warn with the reason and the error object', () => { + const log = makeLogger() + const error = new APIError('BAD_REQUEST', { message: 'OTP expired' }) + logBetterAuthApiError(error, log) + + expect(log.warn).toHaveBeenCalledOnce() + expect(log.warn).toHaveBeenCalledWith( + expect.objectContaining({ + err: error, + status: 'BAD_REQUEST', + statusCode: 400, + message: 'OTP expired', + }), + 'better-auth API error', + ) + }) + + it('logs an invalid-OTP error at warn, distinct from expiry', () => { + const log = makeLogger() + logBetterAuthApiError( + new APIError('BAD_REQUEST', { message: 'Invalid OTP' }), + log, + ) + + expect(log.warn).toHaveBeenCalledWith( + expect.objectContaining({ statusCode: 400, message: 'Invalid OTP' }), + 'better-auth API error', + ) + }) + + it('logs a 403 too-many-attempts error at warn', () => { + const log = makeLogger() + logBetterAuthApiError( + new APIError('FORBIDDEN', { message: 'Too many attempts' }), + log, + ) + + expect(log.warn).toHaveBeenCalledWith( + expect.objectContaining({ + status: 'FORBIDDEN', + statusCode: 403, + message: 'Too many attempts', + }), + 'better-auth API error', + ) + }) + + it('falls back to error.message when the body has no message', () => { + const log = makeLogger() + const err = new APIError('BAD_REQUEST') + err.message = 'bare message' + logBetterAuthApiError(err, log) + + expect(log.warn).toHaveBeenCalledWith( + expect.objectContaining({ message: 'bare message' }), + 'better-auth API error', + ) + }) + + it('ignores 5xx errors (already logged by better-auth itself)', () => { + const log = makeLogger() + logBetterAuthApiError( + new APIError('INTERNAL_SERVER_ERROR', { message: 'boom' }), + log, + ) + + expect(log.warn).not.toHaveBeenCalled() + }) + + it('ignores 3xx redirects', () => { + const log = makeLogger() + logBetterAuthApiError(new APIError('FOUND'), log) + + expect(log.warn).not.toHaveBeenCalled() + }) + + it('ignores non-APIError values', () => { + const log = makeLogger() + logBetterAuthApiError(new Error('some other failure'), log) + logBetterAuthApiError('a string', log) + logBetterAuthApiError(undefined, log) + + expect(log.warn).not.toHaveBeenCalled() + }) +}) diff --git a/packages/auth-service/src/better-auth.ts b/packages/auth-service/src/better-auth.ts index 19e1de18..ddf94634 100644 --- a/packages/auth-service/src/better-auth.ts +++ b/packages/auth-service/src/better-auth.ts @@ -5,13 +5,15 @@ * - Email OTP plugin (for future migration from custom OTP implementation) * - Social providers (Google, GitHub — only when env vars are set) * - Session lifetime from env vars + * - An onAPIError hook that surfaces 4xx client errors in our logs + * (see logBetterAuthApiError below) * * The instance is mounted at /api/auth/* alongside the existing custom routes. - * No existing behavior is changed — this is a foundation-only step. */ import type { EpdsDb } from '@certified-app/shared' import { createLogger } from '@certified-app/shared' import { betterAuth } from 'better-auth' +import { APIError } from 'better-auth/api' import { generateRandomString } from 'better-auth/crypto' import { getMigrations } from 'better-auth/db' import { emailOTP } from 'better-auth/plugins' @@ -22,8 +24,53 @@ import { ensurePdsUrl } from './lib/pds-url.js' export type BetterAuthInstance = ReturnType +/** The logger type used across this module — avoids a direct pino dependency. */ +type BetterAuthLogger = ReturnType + const logger = createLogger('auth:better-auth') +/** + * Surface better-auth 4xx client errors in our own logs. + * + * The main OAuth login flow posts straight from the browser to + * /api/auth/sign-in/email-otp, handled by better-auth's node handler. On + * verification failure better-auth throws an `APIError` whose message is the + * exact reason — "OTP expired", "Invalid OTP" or "Too many attempts" — but + * these never reach our logs because we set neither `logger` nor `onAPIError`. + * This is the only place that distinguishes a genuinely-late email (expired) + * from a user retyping a stale code (invalid), so we log it at `warn` (visible + * at prod's default `info` level) to make the split countable over time. + * + * Only 4xx `APIError`s are logged here. 3xx redirects (e.g. status "FOUND") + * are filtered by better-auth before this runs, and 5xx errors are already + * logged by better-auth's own error handler, so we skip them to avoid noise + * and double-logging. Non-`APIError` values are ignored for the same reason. + * + * The email address is deliberately not logged: better-auth invokes + * `onAPIError.onError` with the instance-wide auth context, not the per-request + * endpoint context, so the request body (and hence the email) is not available + * here without unsafe assumptions. + */ +export function logBetterAuthApiError( + error: unknown, + log: BetterAuthLogger, +): void { + if (!(error instanceof APIError)) return + + const statusCode = error.statusCode + if (statusCode < 400 || statusCode >= 500) return + + log.warn( + { + err: error, + status: error.status, + statusCode, + message: error.body?.message ?? error.message, + }, + 'better-auth API error', + ) +} + const AUTH_FLOW_COOKIE = 'epds_auth_flow' /** @@ -158,6 +205,14 @@ export function createBetterAuth( baseURL: `https://${authHostname}`, basePath: '/api/auth', + // Route better-auth's 4xx client errors (notably "OTP expired" vs + // "Invalid OTP") into our pino logs; see logBetterAuthApiError above. + onAPIError: { + onError(error) { + logBetterAuthApiError(error, logger) + }, + }, + session: { expiresIn: sessionExpiresIn, updateAge: sessionUpdateAge,