From a01317c9b9febcc8df501b9ac44707f30d4c4e72 Mon Sep 17 00:00:00 2001 From: pcarter Date: Sat, 18 Apr 2026 20:19:38 -0700 Subject: [PATCH] logging better and more --- app/api/client-events/route.ts | 59 ++++++++++++----- app/api/health/route.ts | 17 ++++- app/api/history/[id]/route.ts | 74 ++++++++++++++------- app/api/history/route.ts | 44 ++++++++----- app/api/settings/route.ts | 116 +++++++++++++++++++++++---------- app/api/shares/[id]/route.ts | 34 ++++++++-- app/api/shares/route.ts | 61 ++++++++++++----- lib/log.ts | 13 ++++ tests/unit.test.ts | 108 ++++++++++++++++++++++++++---- 9 files changed, 399 insertions(+), 127 deletions(-) diff --git a/app/api/client-events/route.ts b/app/api/client-events/route.ts index 2629230..b184ca5 100644 --- a/app/api/client-events/route.ts +++ b/app/api/client-events/route.ts @@ -1,45 +1,72 @@ import { auth } from '@/auth'; -import logger from '@/lib/log'; -import { getRequestId, jsonResponse, PRIVATE_NO_STORE } from '@/lib/request'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; +import { getRequestId, jsonResponse, PRIVATE_NO_STORE, readContentLength } from '@/lib/request'; import { LIMITS, validateClientEventRequest } from '@/lib/validation'; export async function POST(req: Request) { const requestId = getRequestId(req); const start = Date.now(); + const requestBytes = readContentLength(req); + let detailFields: Record = {}; + const ctx: LogFields = { + requestId, + user: null, + status: null, + requestBytes, + bodyBytes: null, + clientEvent: null, + clientLevel: null, + detailCount: 0, + error: null, + }; try { - const contentLength = Number(req.headers.get('content-length') ?? 0); - if (contentLength > LIMITS.clientEventBodyBytes) { + if (requestBytes !== null && requestBytes > LIMITS.clientEventBodyBytes) { + ctx.status = 413; + ctx.error = 'event too large'; return jsonResponse({ error: 'event too large' }, { status: 413 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } const session = await auth(); if (!session?.user?.email) { + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; - const parsed = validateClientEventRequest(await req.json()); + const body = await req.json(); + if (body && typeof body === 'object' && !Array.isArray(body)) { + ctx.bodyBytes = JSON.stringify(body).length; + } + if (typeof ctx.bodyBytes === 'number' && ctx.bodyBytes > LIMITS.clientEventBodyBytes) { + ctx.status = 413; + ctx.error = 'event too large'; + return jsonResponse({ error: 'event too large' }, { status: 413 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } + + const parsed = validateClientEventRequest(body); if (!parsed.ok) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start, error: parsed.error }, 'client.event.invalid'); + ctx.status = parsed.status; + ctx.error = parsed.error; return jsonResponse({ error: parsed.error }, { status: parsed.status }, { requestId, cacheControl: PRIVATE_NO_STORE }); } - const fields = { - requestId, - user: session.user.email, - durationMs: Date.now() - start, - ...parsed.value.details, - }; - if (parsed.value.level === 'info') logger.info(fields, parsed.value.event); - else if (parsed.value.level === 'warn') logger.warn(fields, parsed.value.event); - else logger.error(fields, parsed.value.event); + detailFields = parsed.value.details; + ctx.status = 204; + ctx.clientEvent = parsed.value.event; + ctx.clientLevel = parsed.value.level; + ctx.detailCount = Object.keys(detailFields).length; return new Response(null, { status: 204, headers: { 'X-Request-Id': requestId, 'Cache-Control': PRIVATE_NO_STORE }, }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'client.event.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('client.event', start, { ...ctx, ...detailFields }); } } diff --git a/app/api/health/route.ts b/app/api/health/route.ts index 04060db..f0f8a5f 100644 --- a/app/api/health/route.ts +++ b/app/api/health/route.ts @@ -1,5 +1,5 @@ import { query } from '@/lib/db'; -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { getRequestId, jsonResponse } from '@/lib/request'; export const runtime = 'nodejs'; @@ -7,13 +7,24 @@ export const runtime = 'nodejs'; export async function GET(req: Request) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + status: null, + ok: null, + error: null, + }; try { await query('SELECT 1'); - logger.info({ requestId, durationMs: Date.now() - start, ok: true }, 'health.check'); + ctx.status = 200; + ctx.ok = true; return jsonResponse({ ok: true }, {}, { requestId, cacheControl: 'no-store' }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, ok: false, error: String(error).slice(0, 200) }, 'health.check'); + ctx.status = 503; + ctx.ok = false; + ctx.error = String(error).slice(0, 200); return jsonResponse({ ok: false, error: 'database unavailable' }, { status: 503 }, { requestId, cacheControl: 'no-store' }); + } finally { + logRouteOutcome('health.check', start, ctx); } } diff --git a/app/api/history/[id]/route.ts b/app/api/history/[id]/route.ts index 5ebf149..4bfbae6 100644 --- a/app/api/history/[id]/route.ts +++ b/app/api/history/[id]/route.ts @@ -1,24 +1,40 @@ import { auth } from '@/auth'; import { query } from '@/lib/db'; -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { getRequestId, jsonResponse, PRIVATE_NO_STORE } from '@/lib/request'; export async function GET(req: Request, { params }: { params: Promise<{ id: string }> }) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + user: null, + status: null, + id: null, + idValid: null, + found: null, + updatedAt: null, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, durationMs: Date.now() - start }, 'history.get.unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; const { id } = await params; + ctx.id = id; if (!/^[a-z0-9-]{8,80}$/i.test(id)) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start }, 'history.get.invalid'); + ctx.status = 400; + ctx.idValid = false; + ctx.error = 'Invalid id'; return jsonResponse({ error: 'Invalid id' }, { status: 400 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.idValid = true; const result = await query( 'SELECT id, iv, ciphertext, updated_at FROM chat_histories WHERE id = $1 AND user_email = $2 LIMIT 1', @@ -26,58 +42,72 @@ export async function GET(req: Request, { params }: { params: Promise<{ id: stri ); const row = result.rows[0]; if (!row) { - logger.warn({ requestId, user: session.user.email, id, durationMs: Date.now() - start }, 'history.get.missing'); + ctx.status = 404; + ctx.found = false; + ctx.error = 'Not found'; return jsonResponse({ error: 'Not found' }, { status: 404 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } - logger.info({ - requestId, - user: session.user.email, - id, - durationMs: Date.now() - start, - updatedAt: row.updated_at, - }, 'history.get'); + ctx.status = 200; + ctx.found = true; + ctx.updatedAt = row.updated_at; return jsonResponse(row, {}, { requestId, cacheControl: PRIVATE_NO_STORE }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'history.get.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('history.get', start, ctx); } } export async function DELETE(req: Request, { params }: { params: Promise<{ id: string }> }) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + user: null, + status: null, + id: null, + idValid: null, + deletedRows: null, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, durationMs: Date.now() - start }, 'history.delete.unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; const { id } = await params; + ctx.id = id; if (!/^[a-z0-9-]{8,80}$/i.test(id)) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start }, 'history.delete.invalid'); + ctx.status = 400; + ctx.idValid = false; + ctx.error = 'Invalid id'; return jsonResponse({ error: 'Invalid id' }, { status: 400 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.idValid = true; const result = await query( 'DELETE FROM chat_histories WHERE id = $1 AND user_email = $2', [id, session.user.email], ); - logger.info({ - requestId, - user: session.user.email, - id, - durationMs: Date.now() - start, - deleted: result.rowCount ?? 0, - }, 'history.delete'); + ctx.status = 204; + ctx.deletedRows = result.rowCount ?? 0; return new Response(null, { status: 204, headers: { 'X-Request-Id': requestId, 'Cache-Control': PRIVATE_NO_STORE }, }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'history.delete.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('history.delete', start, ctx); } } diff --git a/app/api/history/route.ts b/app/api/history/route.ts index 4f6f60e..7a08e8f 100644 --- a/app/api/history/route.ts +++ b/app/api/history/route.ts @@ -1,6 +1,6 @@ import { auth } from '@/auth'; import { query } from '@/lib/db'; -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { getRequestId, jsonResponse, PRIVATE_NO_STORE, readContentLength } from '@/lib/request'; import { LIMITS, validateHistorySaveRequest } from '@/lib/validation'; @@ -22,33 +22,45 @@ function getFieldType(value: unknown): string | null { export async function GET(req: Request) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + user: null, + status: null, + rows: null, + topId: null, + topUpdatedAt: null, + newestAt: null, + oldestAt: null, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, durationMs: Date.now() - start }, 'history.list.unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; const result = await query( 'SELECT id, iv, ciphertext, updated_at FROM chat_histories WHERE user_email = $1 ORDER BY updated_at DESC LIMIT 50', [session.user.email], ); const rows = result.rows; - logger.info({ - requestId, - user: session.user.email, - durationMs: Date.now() - start, - rows: rows.length, - topId: rows[0]?.id ?? null, - topUpdatedAt: rows[0]?.updated_at ?? null, - newestAt: rows[0]?.updated_at ?? null, - oldestAt: rows[rows.length - 1]?.updated_at ?? null, - }, 'history.list'); + ctx.status = 200; + ctx.rows = rows.length; + ctx.topId = rows[0]?.id ?? null; + ctx.topUpdatedAt = rows[0]?.updated_at ?? null; + ctx.newestAt = rows[0]?.updated_at ?? null; + ctx.oldestAt = rows[rows.length - 1]?.updated_at ?? null; return jsonResponse(rows, {}, { requestId, cacheControl: PRIVATE_NO_STORE }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'history.list.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('history.list', start, ctx); } } @@ -152,10 +164,6 @@ export async function POST(req: Request) { ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } finally { - const fields = { ...ctx, durationMs: Date.now() - start }; - const status = typeof ctx.status === 'number' ? ctx.status : 500; - if (status >= 500) logger.error(fields, 'history.save'); - else if (status >= 400) logger.warn(fields, 'history.save'); - else logger.info(fields, 'history.save'); + logRouteOutcome('history.save', start, ctx); } } diff --git a/app/api/settings/route.ts b/app/api/settings/route.ts index a4e8c2d..6ec0818 100644 --- a/app/api/settings/route.ts +++ b/app/api/settings/route.ts @@ -1,6 +1,6 @@ import { auth } from '@/auth'; import { query } from '@/lib/db'; -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { getRequestId, jsonResponse, PRIVATE_NO_STORE, readContentLength } from '@/lib/request'; import { LIMITS, validateSettingsRequest } from '@/lib/validation'; @@ -22,6 +22,10 @@ function hasOwn(input: Record, key: string): boolean { return Object.prototype.hasOwnProperty.call(input, key); } +function isPlainObject(value: unknown): value is Record { + return !!value && typeof value === 'object' && !Array.isArray(value); +} + function isMissingGirlModeColumn(error: unknown): boolean { if (!error || typeof error !== 'object') return false; const candidate = error as { code?: string; message?: string }; @@ -29,7 +33,7 @@ function isMissingGirlModeColumn(error: unknown): boolean { return candidate.code === '42703' && message.includes('girl_mode'); } -async function getSettingsRow(email: string, requestId: string): Promise<{ row?: SettingsRow; legacySchema: boolean }> { +async function getSettingsRow(email: string): Promise<{ row?: SettingsRow; legacySchema: boolean }> { try { const result = await query( 'SELECT system_prompt, save_history, key_jwk, girl_mode FROM user_settings WHERE email = $1', @@ -38,7 +42,6 @@ async function getSettingsRow(email: string, requestId: string): Promise<{ row?: return { row: result.rows[0] as SettingsRow | undefined, legacySchema: false }; } catch (error) { if (!isMissingGirlModeColumn(error)) throw error; - logger.warn({ requestId, user: email }, 'settings.get.legacy_schema'); const result = await query( 'SELECT system_prompt, save_history, key_jwk FROM user_settings WHERE email = $1', [email], @@ -47,7 +50,7 @@ async function getSettingsRow(email: string, requestId: string): Promise<{ row?: } } -async function upsertSettingsRow(email: string, patch: SettingsPatch, requestId: string): Promise<{ legacySchema: boolean }> { +async function upsertSettingsRow(email: string, patch: SettingsPatch): Promise<{ legacySchema: boolean }> { try { await query( `INSERT INTO user_settings (email, system_prompt, save_history, key_jwk, girl_mode) @@ -62,7 +65,6 @@ async function upsertSettingsRow(email: string, patch: SettingsPatch, requestId: return { legacySchema: false }; } catch (error) { if (!isMissingGirlModeColumn(error)) throw error; - logger.warn({ requestId, user: email }, 'settings.put.legacy_schema'); await query( `INSERT INTO user_settings (email, system_prompt, save_history, key_jwk) VALUES ($1, COALESCE($2, ''), COALESCE($3, FALSE), $4) @@ -79,25 +81,34 @@ async function upsertSettingsRow(email: string, patch: SettingsPatch, requestId: export async function GET(req: Request) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + user: null, + status: null, + hasKey: null, + saveHistory: null, + girlMode: null, + legacySchema: null, + newUser: null, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, route: 'settings.get', durationMs: Date.now() - start }, 'unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; - const { row, legacySchema } = await getSettingsRow(session.user.email, requestId); - logger.info({ - requestId, - user: session.user.email, - durationMs: Date.now() - start, - hasKey: !!row?.key_jwk, - saveHistory: row?.save_history ?? false, - girlMode: legacySchema ? null : (row?.girl_mode ?? false), - legacySchema, - newUser: !row, - }, 'settings.get'); + const { row, legacySchema } = await getSettingsRow(session.user.email); + ctx.status = 200; + ctx.hasKey = !!row?.key_jwk; + ctx.saveHistory = row?.save_history ?? false; + ctx.girlMode = legacySchema ? null : (row?.girl_mode ?? false); + ctx.legacySchema = legacySchema; + ctx.newUser = !row; return jsonResponse({ systemPrompt: row?.system_prompt ?? '', saveHistory: row?.save_history ?? false, @@ -105,32 +116,66 @@ export async function GET(req: Request) { keyJwk: row?.key_jwk ?? null, }, {}, { requestId, cacheControl: PRIVATE_NO_STORE }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'settings.get.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('settings.get', start, ctx); } } export async function PUT(req: Request) { const requestId = getRequestId(req); const start = Date.now(); + const requestBytes = readContentLength(req); + const ctx: LogFields = { + requestId, + user: null, + status: null, + requestBytes, + bodyBytes: null, + hasSystemPromptField: null, + hasSaveHistoryField: null, + hasGirlModeField: null, + hasKeyJwkField: null, + systemPromptChars: null, + keyJwkChars: null, + saveHistory: null, + girlMode: null, + hasKey: null, + legacySchema: null, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, route: 'settings.put', durationMs: Date.now() - start }, 'unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; - const contentLength = readContentLength(req); - if (contentLength !== null && contentLength > LIMITS.settingsBodyBytes) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start, contentLength }, 'settings.put.too_large'); + if (requestBytes !== null && requestBytes > LIMITS.settingsBodyBytes) { + ctx.status = 413; + ctx.error = 'Request too large'; return jsonResponse({ error: 'Request too large' }, { status: 413 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } const body = await req.json(); + if (isPlainObject(body)) { + ctx.bodyBytes = JSON.stringify(body).length; + ctx.hasSystemPromptField = hasOwn(body, 'systemPrompt'); + ctx.hasSaveHistoryField = hasOwn(body, 'saveHistory'); + ctx.hasGirlModeField = hasOwn(body, 'girlMode'); + ctx.hasKeyJwkField = hasOwn(body, 'keyJwk'); + ctx.systemPromptChars = typeof body.systemPrompt === 'string' ? body.systemPrompt.length : null; + ctx.keyJwkChars = typeof body.keyJwk === 'string' ? body.keyJwk.length : null; + } const parsed = validateSettingsRequest(body); if (!parsed.ok) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start, error: parsed.error }, 'settings.put.invalid'); + ctx.status = parsed.status; + ctx.error = parsed.error; return jsonResponse({ error: parsed.error }, { status: parsed.status }, { requestId, cacheControl: PRIVATE_NO_STORE }); } @@ -142,22 +187,25 @@ export async function PUT(req: Request) { keyJwk: hasOwn(input, 'keyJwk') ? parsed.value.keyJwk : null, }; - const { legacySchema } = await upsertSettingsRow(session.user.email, patch, requestId); - logger.info({ - requestId, - user: session.user.email, - durationMs: Date.now() - start, - saveHistory: patch.saveHistory, - girlMode: legacySchema ? null : patch.girlMode, - hasKey: !!patch.keyJwk, - legacySchema, - }, 'settings.put'); + ctx.systemPromptChars = patch.systemPrompt === null ? ctx.systemPromptChars : patch.systemPrompt.length; + ctx.keyJwkChars = patch.keyJwk === null ? ctx.keyJwkChars : patch.keyJwk.length; + ctx.saveHistory = patch.saveHistory; + ctx.girlMode = patch.girlMode; + ctx.hasKey = patch.keyJwk === null ? null : patch.keyJwk.length > 0; + + const { legacySchema } = await upsertSettingsRow(session.user.email, patch); + ctx.status = 204; + ctx.girlMode = legacySchema ? null : patch.girlMode; + ctx.legacySchema = legacySchema; return new Response(null, { status: 204, headers: { 'X-Request-Id': requestId, 'Cache-Control': PRIVATE_NO_STORE }, }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'settings.put.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('settings.put', start, ctx); } } diff --git a/app/api/shares/[id]/route.ts b/app/api/shares/[id]/route.ts index 65b69f2..12bce9c 100644 --- a/app/api/shares/[id]/route.ts +++ b/app/api/shares/[id]/route.ts @@ -1,4 +1,4 @@ -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { textResponse, getRequestId } from '@/lib/request'; import { getSharedChat } from '@/lib/share'; import { isShareId } from '@/lib/validation'; @@ -8,17 +8,38 @@ const SHARE_CACHE = 'public, max-age=300, stale-while-revalidate=3600'; export async function GET(req: Request, { params }: { params: Promise<{ id: string }> }) { const requestId = getRequestId(req); const start = Date.now(); + const ctx: LogFields = { + requestId, + status: null, + id: null, + idValid: null, + found: null, + model: null, + msgs: null, + error: null, + }; try { const { id } = await params; + ctx.id = id; if (!isShareId(id)) { - logger.warn({ requestId, id, durationMs: Date.now() - start }, 'share.get.invalid'); + ctx.status = 404; + ctx.idValid = false; + ctx.error = 'Not found'; return textResponse('Not found', { status: 404 }, { requestId, cacheControl: SHARE_CACHE }); } + ctx.idValid = true; const share = await getSharedChat(id); - logger.info({ requestId, id, found: !!share, durationMs: Date.now() - start }, 'share.get'); - if (!share) return textResponse('Not found', { status: 404 }, { requestId, cacheControl: SHARE_CACHE }); + ctx.found = !!share; + if (!share) { + ctx.status = 404; + ctx.error = 'Not found'; + return textResponse('Not found', { status: 404 }, { requestId, cacheControl: SHARE_CACHE }); + } + ctx.status = 200; + ctx.model = share.model; + ctx.msgs = share.messages.length; return textResponse(JSON.stringify(share), { status: 200, headers: { 'Content-Type': 'application/json; charset=utf-8' }, @@ -27,7 +48,10 @@ export async function GET(req: Request, { params }: { params: Promise<{ id: stri cacheControl: SHARE_CACHE, }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'share.get.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return textResponse('Internal Server Error', { status: 500 }, { requestId, cacheControl: SHARE_CACHE }); + } finally { + logRouteOutcome('share.get', start, ctx); } } diff --git a/app/api/shares/route.ts b/app/api/shares/route.ts index 35177f0..c490f62 100644 --- a/app/api/shares/route.ts +++ b/app/api/shares/route.ts @@ -1,24 +1,40 @@ import { NextRequest } from 'next/server'; import { auth } from '@/auth'; import { query } from '@/lib/db'; -import logger from '@/lib/log'; +import { logRouteOutcome, type LogFields } from '@/lib/log'; import { getRequestId, jsonResponse, PRIVATE_NO_STORE, readContentLength } from '@/lib/request'; import { LIMITS, validateShareRequest } from '@/lib/validation'; export async function POST(req: NextRequest) { const requestId = getRequestId(req); const start = Date.now(); + const requestBytes = readContentLength(req); + const ctx: LogFields = { + requestId, + user: null, + status: null, + requestBytes, + bodyBytes: null, + model: null, + msgs: null, + hasSystemPrompt: null, + shareId: null, + insertAttempts: 0, + error: null, + }; try { const session = await auth(); if (!session?.user?.email) { - logger.warn({ requestId, durationMs: Date.now() - start }, 'share.create.unauthenticated'); + ctx.status = 401; + ctx.error = 'Unauthorized'; return jsonResponse({ error: 'Unauthorized' }, { status: 401 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.user = session.user.email; - const contentLength = readContentLength(req); - if (contentLength !== null && contentLength > LIMITS.shareBodyBytes) { - logger.warn({ requestId, user: session.user.email, contentLength, durationMs: Date.now() - start }, 'share.create.too_large'); + if (requestBytes !== null && requestBytes > LIMITS.shareBodyBytes) { + ctx.status = 413; + ctx.error = 'Request too large'; return jsonResponse( { error: 'Chat too large to share. Try removing image attachments first.' }, { status: 413 }, @@ -28,8 +44,15 @@ export async function POST(req: NextRequest) { const body = await req.json(); const bodyBytes = JSON.stringify(body).length; + ctx.bodyBytes = bodyBytes; + if (body && typeof body === 'object' && !Array.isArray(body)) { + ctx.model = typeof body.model === 'string' ? body.model : null; + ctx.msgs = Array.isArray(body.messages) ? body.messages.length : null; + ctx.hasSystemPrompt = typeof body.systemPrompt === 'string' ? body.systemPrompt.length > 0 : null; + } if (bodyBytes > LIMITS.shareBodyBytes) { - logger.warn({ requestId, user: session.user.email, bodyBytes, durationMs: Date.now() - start }, 'share.create.too_large'); + ctx.status = 413; + ctx.error = 'Request too large'; return jsonResponse( { error: 'Chat too large to share. Try removing image attachments first.' }, { status: 413 }, @@ -39,12 +62,17 @@ export async function POST(req: NextRequest) { const parsed = validateShareRequest(body); if (!parsed.ok) { - logger.warn({ requestId, user: session.user.email, durationMs: Date.now() - start, error: parsed.error }, 'share.create.invalid'); + ctx.status = parsed.status; + ctx.error = parsed.error; return jsonResponse({ error: parsed.error }, { status: parsed.status }, { requestId, cacheControl: PRIVATE_NO_STORE }); } + ctx.model = parsed.value.model; + ctx.msgs = parsed.value.messages.length; + ctx.hasSystemPrompt = Boolean(parsed.value.systemPrompt); let id = ''; for (let attempt = 0; attempt < 3; attempt++) { + ctx.insertAttempts = attempt + 1; id = crypto.randomUUID().replace(/-/g, ''); const result = await query( `INSERT INTO shared_chats (id, created_by, model, system_prompt, messages) @@ -57,22 +85,19 @@ export async function POST(req: NextRequest) { } if (!id) { - logger.error({ requestId, user: session.user.email, durationMs: Date.now() - start }, 'share.create.collision'); + ctx.status = 503; + ctx.error = 'Could not create share'; return jsonResponse({ error: 'Could not create share' }, { status: 503 }, { requestId, cacheControl: PRIVATE_NO_STORE }); } - logger.info({ - requestId, - user: session.user.email, - id, - model: parsed.value.model, - msgs: parsed.value.messages.length, - bodyBytes, - durationMs: Date.now() - start, - }, 'share.create'); + ctx.status = 200; + ctx.shareId = id; return jsonResponse({ id }, {}, { requestId, cacheControl: PRIVATE_NO_STORE }); } catch (error) { - logger.error({ requestId, durationMs: Date.now() - start, error: String(error).slice(0, 200) }, 'share.create.failed'); + ctx.status = 500; + ctx.error = String(error).slice(0, 200); return jsonResponse({ error: 'Internal Server Error' }, { status: 500 }, { requestId, cacheControl: PRIVATE_NO_STORE }); + } finally { + logRouteOutcome('share.create', start, ctx); } } diff --git a/lib/log.ts b/lib/log.ts index 01fd881..f12992e 100644 --- a/lib/log.ts +++ b/lib/log.ts @@ -25,4 +25,17 @@ const logger = pino({ }, }); +export type LogFields = Record; + +export function logByStatus(event: string, fields: LogFields) { + const status = typeof fields.status === 'number' ? fields.status : 500; + if (status >= 500) logger.error(fields, event); + else if (status >= 400) logger.warn(fields, event); + else logger.info(fields, event); +} + +export function logRouteOutcome(event: string, startedAt: number, fields: LogFields) { + logByStatus(event, { ...fields, durationMs: Date.now() - startedAt }); +} + export default logger; diff --git a/tests/unit.test.ts b/tests/unit.test.ts index c6d6c42..95a25d0 100644 --- a/tests/unit.test.ts +++ b/tests/unit.test.ts @@ -428,8 +428,8 @@ test('history-loaded chats persist across refreshes and clear correctly', () => 'history item route should support fetching one saved chat by id for refresh restore', ); assert.ok( - historyItemRouteSource.includes("}, 'history.get');"), - 'history item route should log successful direct history fetches', + historyItemRouteSource.includes("logRouteOutcome('history.get', start, ctx);"), + 'history item route should emit the canonical history.get log for direct history fetches', ); }); @@ -449,12 +449,12 @@ test('history drawer still loads the latest 50 saved chats', () => { 'history list endpoint should return the latest 50 saved chats first', ); assert.ok( - historyRouteSource.includes('topUpdatedAt: rows[0]?.updated_at ?? null'), + historyRouteSource.includes('ctx.topUpdatedAt = rows[0]?.updated_at ?? null;'), 'history list logs should include the updated_at timestamp of the top visible row', ); assert.ok( - historyRouteSource.includes("}, 'history.list');"), - 'history list endpoint should continue logging the visible latest-history window', + historyRouteSource.includes("logRouteOutcome('history.list', start, ctx);"), + 'history list endpoint should continue emitting the canonical history.list log for the visible latest-history window', ); }); @@ -514,6 +514,7 @@ test('history save logs meaningful failure details before and after the network test('history save route emits one wide canonical history.save log per POST attempt', () => { const source = readFileSync(join(import.meta.dirname, '../app/api/history/route.ts'), 'utf8'); + const logSource = readFileSync(join(import.meta.dirname, '../lib/log.ts'), 'utf8'); assert.ok( source.includes('const ctx: Record = {'), 'history save route should collect request/save metadata in one canonical logging context', @@ -548,16 +549,18 @@ test('history save route emits one wide canonical history.save log per POST atte 'history save route should log whether the request resolved as an update', ); assert.ok( - source.includes("if (status >= 500) logger.error(fields, 'history.save');"), - 'history save route should emit error-level canonical logs for 5xx outcomes', + logSource.includes('export function logByStatus(') && + logSource.includes('if (status >= 500) logger.error(fields, event);'), + 'route logging should centralize 5xx/error log-level routing in the shared logger helper', ); assert.ok( - source.includes("else if (status >= 400) logger.warn(fields, 'history.save');"), - 'history save route should emit warn-level canonical logs for 4xx outcomes', + logSource.includes("else if (status >= 400) logger.warn(fields, event);"), + 'route logging should centralize 4xx/warn log-level routing in the shared logger helper', ); assert.ok( - source.includes("else logger.info(fields, 'history.save');"), - 'history save route should emit info-level canonical logs for successful saves', + logSource.includes('export function logRouteOutcome(') && + source.includes("logRouteOutcome('history.save', start, ctx);"), + 'history save route should emit its canonical history.save log through the shared route helper', ); assert.ok( !source.includes("'history.save.invalid'") && @@ -567,6 +570,89 @@ test('history save route emits one wide canonical history.save log per POST atte ); }); +test('route verbs use canonical thick logging across settings, history, shares, and health', () => { + const historySource = readFileSync(join(import.meta.dirname, '../app/api/history/route.ts'), 'utf8'); + const historyItemSource = readFileSync(join(import.meta.dirname, '../app/api/history/[id]/route.ts'), 'utf8'); + const settingsSource = readFileSync(join(import.meta.dirname, '../app/api/settings/route.ts'), 'utf8'); + const sharesSource = readFileSync(join(import.meta.dirname, '../app/api/shares/route.ts'), 'utf8'); + const shareGetSource = readFileSync(join(import.meta.dirname, '../app/api/shares/[id]/route.ts'), 'utf8'); + const clientEventsSource = readFileSync(join(import.meta.dirname, '../app/api/client-events/route.ts'), 'utf8'); + const healthSource = readFileSync(join(import.meta.dirname, '../app/api/health/route.ts'), 'utf8'); + + assert.ok( + historySource.includes("logRouteOutcome('history.list', start, ctx);"), + 'history GET should emit one canonical history.list log line per request', + ); + assert.ok( + !historySource.includes("'history.list.failed'") && + !historySource.includes("'history.list.unauthenticated'"), + 'history list logging should use the canonical history.list event instead of fragmented sub-events', + ); + assert.ok( + historyItemSource.includes("logRouteOutcome('history.get', start, ctx);") && + historyItemSource.includes("logRouteOutcome('history.delete', start, ctx);"), + 'history item GET/DELETE should emit canonical history.get and history.delete logs', + ); + assert.ok( + !historyItemSource.includes("'history.get.failed'") && + !historyItemSource.includes("'history.get.invalid'") && + !historyItemSource.includes("'history.get.missing'") && + !historyItemSource.includes("'history.get.unauthenticated'") && + !historyItemSource.includes("'history.delete.failed'") && + !historyItemSource.includes("'history.delete.invalid'") && + !historyItemSource.includes("'history.delete.unauthenticated'"), + 'history item routes should collapse invalid, missing, auth, and failure outcomes into the canonical verb logs', + ); + assert.ok( + settingsSource.includes("logRouteOutcome('settings.get', start, ctx);") && + settingsSource.includes("logRouteOutcome('settings.put', start, ctx);"), + 'settings GET/PUT should emit canonical settings.get and settings.put logs', + ); + assert.ok( + !settingsSource.includes("'settings.get.failed'") && + !settingsSource.includes("'settings.put.failed'") && + !settingsSource.includes("'settings.put.invalid'") && + !settingsSource.includes("'settings.put.too_large'") && + !settingsSource.includes("'settings.get.legacy_schema'") && + !settingsSource.includes("'settings.put.legacy_schema'"), + 'settings route logging should keep schema fallback and validation details inside the canonical verb logs', + ); + assert.ok( + sharesSource.includes("logRouteOutcome('share.create', start, ctx);"), + 'share creation should emit one canonical share.create log line per request', + ); + assert.ok( + !sharesSource.includes("'share.create.failed'") && + !sharesSource.includes("'share.create.invalid'") && + !sharesSource.includes("'share.create.too_large'") && + !sharesSource.includes("'share.create.unauthenticated'") && + !sharesSource.includes("'share.create.collision'"), + 'share creation logging should fold auth, validation, size, and collision outcomes into the canonical share.create event', + ); + assert.ok( + shareGetSource.includes("logRouteOutcome('share.get', start, ctx);"), + 'shared chat fetches should emit one canonical share.get log line per request', + ); + assert.ok( + !shareGetSource.includes("'share.get.failed'") && + !shareGetSource.includes("'share.get.invalid'"), + 'share fetch logging should keep invalid and failed outcomes on the canonical share.get event', + ); + assert.ok( + clientEventsSource.includes("logRouteOutcome('client.event', start, { ...ctx, ...detailFields });"), + 'client event ingestion should emit one canonical client.event log line per POST', + ); + assert.ok( + !clientEventsSource.includes("'client.event.failed'") && + !clientEventsSource.includes("'client.event.invalid'"), + 'client event ingestion should keep validation and failure outcomes on the canonical client.event event', + ); + assert.ok( + healthSource.includes("logRouteOutcome('health.check', start, ctx);"), + 'health checks should emit one canonical health.check log line per request', + ); +}); + // ── settings validation ──────────────────────────────────────────────────────── test('validateSettingsRequest: validates and defaults girlMode', () => { -- 2.51.2