From 220e8338f5d04cc18fa377d28be47c129bb268ab Mon Sep 17 00:00:00 2001 From: "nekomimi.pet" Date: Thu, 24 Sep 2026 06:54:48 -0400 Subject: [PATCH] log reaper db error codes, stop logging 404 probes as failures --- apps/main-app/src/lib/private-site-reaper.ts | 17 ++++++++- apps/main-app/src/routes/xrpc.ts | 37 ++++++++++++++----- .../observability/src/middleware/elysia.ts | 6 ++- .../src/middleware/route-metrics.test.ts | 37 ++++++++++++++++++- 4 files changed, 85 insertions(+), 12 deletions(-) diff --git a/apps/main-app/src/lib/private-site-reaper.ts b/apps/main-app/src/lib/private-site-reaper.ts index b12c0f3..050cf8f 100644 --- a/apps/main-app/src/lib/private-site-reaper.ts +++ b/apps/main-app/src/lib/private-site-reaper.ts @@ -14,6 +14,17 @@ const errorKind = (error: unknown): string => { return error.constructor.name || 'Error' } +/** + * Bun's SQL client raises PostgresError both for server errors (SQLSTATE, e.g. + * `40P01`) and for client-side failures (e.g. `ERR_POSTGRES_CONNECTION_CLOSED`), + * so the class alone cannot tell a dropped connection from a bad query. Only a + * short code-shaped value is logged; messages can echo query text. + */ +export const errorCode = (error: unknown): string | undefined => { + const code = (error as { code?: unknown } | null)?.code + return typeof code === 'string' && /^[A-Z0-9_]{1,64}$/.test(code) ? code : undefined +} + /** * Claims work in the primary database before deleting objects. A failed pass * deliberately leaves a `deleting` row, which is invisible to every serving @@ -35,6 +46,7 @@ export const reapExpiredPrivateSites = async (): Promise<{ sites: number; files: logger.error('[PrivateSite] Failed to reap private site', undefined, { siteId, errorKind: errorKind(error), + errorCode: errorCode(error), }), ) sites = result.sites @@ -44,7 +56,10 @@ export const reapExpiredPrivateSites = async (): Promise<{ sites: number; files: logger.info('[PrivateSite] Reaped private sites', { sites, files }) } } catch (error) { - logger.error('[PrivateSite] Reaper pass failed', undefined, { errorKind: errorKind(error) }) + logger.error('[PrivateSite] Reaper pass failed', undefined, { + errorKind: errorKind(error), + errorCode: errorCode(error), + }) } return { sites, files } diff --git a/apps/main-app/src/routes/xrpc.ts b/apps/main-app/src/routes/xrpc.ts index a920bae..fcd0c92 100644 --- a/apps/main-app/src/routes/xrpc.ts +++ b/apps/main-app/src/routes/xrpc.ts @@ -582,6 +582,16 @@ const deleteSiteForDid = async (did: DidString, input: { siteRkey: string }) => export const xrpcRoutes = () => { const authByRequest = new WeakMap() const router = new XRPCRouter() + // Every method actually registered, aliases included, so request logging can + // tell our own 404s from probes for methods we never serve. + const servedNsids = new Set() + for (const method of ['addQuery', 'addProcedure'] as const) { + const register = router[method].bind(router) as (schema: { nsid: string }, config: unknown) => void + ;(router as any)[method] = (schema: { nsid: string }, config: unknown) => { + servedNsids.add(schema.nsid) + register(schema, config) + } + } const registeredNsids = [ XRPC_NSIDS.addSite, XRPC_NSIDS.getStatus, @@ -997,14 +1007,16 @@ export const xrpcRoutes = () => { const authorization = xrpcRequest.headers.get('authorization') const origin = xrpcRequest.headers.get('origin') ?? '-' const authScheme = authorization ? authorization.split(' ')[0] : '-' - logger.info('[XRPC] Incoming', { - method: xrpcRequest.method, - rawNsid, - nsid, - origin, - hasAuth: Boolean(authorization), - scheme: authScheme, - }) + if (servedNsids.has(nsid)) { + logger.info('[XRPC] Incoming', { + method: xrpcRequest.method, + rawNsid, + nsid, + origin, + hasAuth: Boolean(authorization), + scheme: authScheme, + }) + } if (isLocalDev) { console.log('[XRPC] Incoming', { method: xrpcRequest.method, @@ -1023,7 +1035,14 @@ export const xrpcRoutes = () => { const response = await router.fetch(xrpcRequest) - if (!response.ok) { + // Relays and crawlers probe wisp.place as if it were a PDS (for example + // com.atproto.sync.subscribeRepos). A 404 for a method we never serve is + // expected traffic, not a failure worth a warning. + const unservedMethod = response.status === 404 && !servedNsids.has(nsid) + + if (unservedMethod) { + // Intentionally quiet; the metrics middleware still counts the 404. + } else if (!response.ok) { let responseData: unknown try { responseData = await response.clone().json() diff --git a/packages/@wispplace/observability/src/middleware/elysia.ts b/packages/@wispplace/observability/src/middleware/elysia.ts index 6c2931e..9cd2cd5 100644 --- a/packages/@wispplace/observability/src/middleware/elysia.ts +++ b/packages/@wispplace/observability/src/middleware/elysia.ts @@ -40,7 +40,11 @@ export function observabilityMiddleware(service: string) { const startTime = (request as any).__startTime || Date.now() const duration = Date.now() - startTime const url = new URL(request.url) - const statusCode = normalizeStatus(set.status, 500) + // Elysia has not applied the error's status to `set` yet (an unmatched + // route still reads 200 here), so prefer the status the error carries. + const errorStatus = normalizeStatus((error as { status?: unknown } | undefined)?.status, 0) + const setStatus = normalizeStatus(set.status, 0) + const statusCode = errorStatus >= 400 ? errorStatus : setStatus >= 400 ? setStatus : 500 metricsCollector.recordRequest( route || redactSecretPath(url.pathname), diff --git a/packages/@wispplace/observability/src/middleware/route-metrics.test.ts b/packages/@wispplace/observability/src/middleware/route-metrics.test.ts index 46b4c1d..bae5c73 100644 --- a/packages/@wispplace/observability/src/middleware/route-metrics.test.ts +++ b/packages/@wispplace/observability/src/middleware/route-metrics.test.ts @@ -1,7 +1,7 @@ import { describe, expect, test } from 'bun:test' import { Elysia } from 'elysia' import { Hono } from 'hono' -import { metricsCollector } from '../core' +import { logCollector, metricsCollector } from '../core' import { observabilityMiddleware as elysiaObservabilityMiddleware } from './elysia' import { observabilityMiddleware as honoObservabilityMiddleware } from './hono' @@ -32,4 +32,39 @@ describe('observability route labels', () => { const [metric] = metricsCollector.getMetrics({ service }) expect(metric?.path).toBe('/sites/:did/*') }) + + test('records an unmatched Elysia route as 404 and does not log it', async () => { + const service = 'elysia-not-found-test' + const middleware = elysiaObservabilityMiddleware(service) + const app = new Elysia() + .onBeforeHandle(middleware.beforeHandle) + .onAfterHandle(middleware.afterHandle) + .onError(middleware.onError) + .get('/', () => 'ok') + + const response = await app.handle(new Request('http://localhost/.env')) + + expect(response.status).toBe(404) + const [metric] = metricsCollector.getMetrics({ service }) + expect(metric?.statusCode).toBe(404) + expect(logCollector.getLogs({ service }).some((log) => log.message.includes('Request failed'))).toBe(false) + }) + + test('records a thrown Elysia handler error as 500 and logs it', async () => { + const service = 'elysia-handler-error-test' + const middleware = elysiaObservabilityMiddleware(service) + const app = new Elysia() + .onBeforeHandle(middleware.beforeHandle) + .onAfterHandle(middleware.afterHandle) + .onError(middleware.onError) + .get('/boom', () => { + throw new Error('boom') + }) + + await app.handle(new Request('http://localhost/boom')) + + const [metric] = metricsCollector.getMetrics({ service }) + expect(metric?.statusCode).toBe(500) + expect(logCollector.getLogs({ service }).some((log) => log.message === 'Request failed: GET /boom')).toBe(true) + }) }) -- 2.54.0