diff --git a/app/entry.server.tsx b/app/entry.server.tsx index b34f3e429..4f28d4b63 100644 --- a/app/entry.server.tsx +++ b/app/entry.server.tsx @@ -2,9 +2,15 @@ import type { EntryContext } from "react-router"; import { ServerRouter } from "react-router"; import { isbot } from "isbot"; import { renderToReadableStream } from "react-dom/server"; +import { logRouteError } from "../server/lib/route-error-logging"; export const streamTimeout = 5_000; +/** Replaces React Router's default, which logs every 4xx a scanner provokes as an error. */ +export function handleError(error: unknown, { request }: { request: Request }) { + logRouteError(error, request); +} + export default async function handleRequest( request: Request, responseStatusCode: number, diff --git a/server/lib/email/providers/resend.ts b/server/lib/email/providers/resend.ts index 4b41adb3a..92c89273f 100644 --- a/server/lib/email/providers/resend.ts +++ b/server/lib/email/providers/resend.ts @@ -153,7 +153,13 @@ export class ResendProvider implements EmailProvider { } const kind = classifyResendError(res.status, errName, errMsg); - logger.error('[email] ResendProvider delivery failed', { status: res.status, kind, error: errMsg }); + const failure = { status: res.status, kind, error: errMsg }; + // The kind goes in the message too: log alert rules can match message text but + // not the data object. A used-up quota needs a human; a suppressed recipient is + // expected and must not read as an error. + if (kind === 'quota_exceeded') logger.alert('email-quota-exceeded', '[email] ResendProvider delivery failed (quota_exceeded)', failure); + else if (kind === 'suppressed') logger.warn('[email] ResendProvider delivery failed (suppressed)', failure); + else logger.error(`[email] ResendProvider delivery failed (${kind})`, failure); const retryAfterSeconds = kind === 'rate_limited' ? readRetryAfterSeconds(res.headers) : undefined; return { ok: false, error: errMsg, kind, diff --git a/server/lib/logger.ts b/server/lib/logger.ts index 3c1466e7d..1db0a99cb 100644 --- a/server/lib/logger.ts +++ b/server/lib/logger.ts @@ -38,7 +38,13 @@ class Logger { // Cloudflare Workers console.log handles objects by stringifying them // In production, we want a single line JSON string for aggregators. - console.info(JSON.stringify(payload)); + // The console method sets the NATIVE level in Workers Logs, so an ERROR + // must go through console.error or anything filtering on that level + // (alert rules included) sees it as info. + const line = JSON.stringify(payload); + if (level === LogLevel.ERROR) console.error(line); + else if (level === LogLevel.WARN) console.warn(line); + else console.info(line); } debug(message: string, data?: unknown) { @@ -62,6 +68,16 @@ class Logger { } : undefined, }); } + + /** + * An ERROR that needs a human. The `[alert:]` prefix is part of the + * message on purpose: Workers Logs alert rules can match message text but + * not the `data` object, so the code has to live in the message. Use it only + * for conditions that call for action, never for expected traffic. + */ + alert(code: string, message: string, data?: Record, error?: Error) { + this.error(`[alert:${code}] ${message}`, data, error); + } } // Default singleton instance diff --git a/server/lib/route-error-logging.ts b/server/lib/route-error-logging.ts new file mode 100644 index 000000000..1f32b0b60 --- /dev/null +++ b/server/lib/route-error-logging.ts @@ -0,0 +1,26 @@ +import { isRouteErrorResponse } from 'react-router'; +import { logger } from './logger'; + +/** + * React Router's default handleError console.errors EVERY error it sees, a 404 + * for an unmatched route or a 405 for a POST to a page included. Internet + * scanners probe paths that do not exist all day, so those expected 4xx answers + * filled Workers Logs with `error` stack traces and made an error-level alert + * useless. + * + * Only a genuine failure is worth an error line: a 5xx, or something thrown that + * is not a response at all. A client that already hung up is not a failure. + */ +export function shouldLogRouteError(error: unknown, request: Request): boolean { + if (request.signal.aborted) return false; + if (isRouteErrorResponse(error)) return error.status >= 500; + if (error instanceof Response) return error.status >= 500; + return true; +} + +export function logRouteError(error: unknown, request: Request): void { + if (!shouldLogRouteError(error, request)) return; + // Path only: a query string can carry one-shot secrets such as a reset token. + const path = new URL(request.url).pathname; + logger.error('Unhandled route error', { method: request.method, path }, error instanceof Error ? error : undefined); +} diff --git a/tests/unit/email/resend-failure-logging.spec.ts b/tests/unit/email/resend-failure-logging.spec.ts new file mode 100644 index 000000000..e121fd60e --- /dev/null +++ b/tests/unit/email/resend-failure-logging.spec.ts @@ -0,0 +1,42 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { ResendProvider } from '../../../server/lib/email/providers/resend'; +import { logger } from '../../../server/lib/logger'; +import { recordingFetch } from '../helpers/fetch-mock'; + +afterEach(() => vi.restoreAllMocks()); + +const send = (status: number, body: Record) => { + vi.stubGlobal('fetch', recordingFetch(async () => new Response(JSON.stringify(body), { status }))); + return new ResendProvider({ apiKey: 're_test' }).sendEmail({ from: 'a@x.com', to: 'b@y.com', subject: 's', html: 'h' }); +}; + +/** + * Alert rules can match the log message but not the data object, so the failure + * kind has to be in the message, and only a failure that needs a human is an alert. + */ +describe('Resend delivery failure logging', () => { + it('raises an alert when the sending quota is used up', async () => { + const alert = vi.spyOn(logger, 'alert').mockImplementation(() => undefined); + const res = await send(429, { name: 'daily_quota_exceeded', message: 'You have exceeded your daily sending quota' }); + expect(res).toMatchObject({ ok: false, kind: 'quota_exceeded' }); + expect(alert).toHaveBeenCalledTimes(1); + expect(alert.mock.calls[0]![0]).toBe('email-quota-exceeded'); + }); + + it('logs a suppressed recipient as a warning: it is expected, not an error', async () => { + const error = vi.spyOn(logger, 'error').mockImplementation(() => undefined); + const alert = vi.spyOn(logger, 'alert').mockImplementation(() => undefined); + const warn = vi.spyOn(logger, 'warn').mockImplementation(() => undefined); + await send(403, { name: 'validation_error', message: 'The recipient is suppressed' }); + expect(warn).toHaveBeenCalledTimes(1); + expect(error).not.toHaveBeenCalled(); + expect(alert).not.toHaveBeenCalled(); + }); + + it('names the failure kind in the message of any other failure', async () => { + const error = vi.spyOn(logger, 'error').mockImplementation(() => undefined); + await send(500, { name: 'application_error', message: 'boom' }); + expect(error).toHaveBeenCalledTimes(1); + expect(String(error.mock.calls[0]![0])).toContain('(transient)'); + }); +}); diff --git a/tests/unit/logging/logger-levels.spec.ts b/tests/unit/logging/logger-levels.spec.ts new file mode 100644 index 000000000..557ed4e4a --- /dev/null +++ b/tests/unit/logging/logger-levels.spec.ts @@ -0,0 +1,39 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { logger } from '../../../server/lib/logger'; + +afterEach(() => vi.restoreAllMocks()); + +/** + * Cloudflare Workers Logs takes its native `level` from the console method. + * The logger wrote every level through console.info, so an ERROR looked like an + * info line to anything that filters on the native level, alert rules included. + */ +describe('logger console routing', () => { + it('writes each level through the matching console method', () => { + const info = vi.spyOn(console, 'info').mockImplementation(() => undefined); + const warn = vi.spyOn(console, 'warn').mockImplementation(() => undefined); + const error = vi.spyOn(console, 'error').mockImplementation(() => undefined); + logger.info('i'); + logger.warn('w'); + logger.error('e'); + expect(info).toHaveBeenCalledTimes(1); + expect(warn).toHaveBeenCalledTimes(1); + expect(error).toHaveBeenCalledTimes(1); + }); + + it('still emits one parsable JSON line carrying the level and message', () => { + const error = vi.spyOn(console, 'error').mockImplementation(() => undefined); + logger.error('boom', { a: 1 }); + const line = JSON.parse(String(error.mock.calls[0]![0])) as Record; + expect(line).toMatchObject({ level: 'ERROR', message: 'boom', data: { a: 1 } }); + }); + + it('alert() is an ERROR line whose message starts with an [alert:] marker', () => { + const error = vi.spyOn(console, 'error').mockImplementation(() => undefined); + logger.alert('email-quota-exceeded', 'daily quota used up', { status: 429 }); + const line = JSON.parse(String(error.mock.calls[0]![0])) as Record; + expect(line.level).toBe('ERROR'); + expect(String(line.message).startsWith('[alert:email-quota-exceeded] ')).toBe(true); + expect(line.message).toContain('daily quota used up'); + }); +}); diff --git a/tests/unit/logging/route-error-logging.spec.ts b/tests/unit/logging/route-error-logging.spec.ts new file mode 100644 index 000000000..289e16259 --- /dev/null +++ b/tests/unit/logging/route-error-logging.spec.ts @@ -0,0 +1,55 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; +import { logger } from '../../../server/lib/logger'; +import { logRouteError, shouldLogRouteError } from '../../../server/lib/route-error-logging'; + +afterEach(() => vi.restoreAllMocks()); + +const req = (url = 'https://x.test/read-document?token=SECRET', init: RequestInit = { method: 'POST' }) => + new Request(url, init); + +/** The shape React Router throws for an unmatched route (404) or a wrong method (405). */ +const routeError = (status: number) => ({ + status, statusText: 'x', internal: true, data: 'Error: No route matches URL', +}); + +describe('shouldLogRouteError', () => { + it.each([404, 405, 400, 422])('does not log a %i route error (scanner and client noise)', (status) => { + expect(shouldLogRouteError(routeError(status), req())).toBe(false); + }); + + it('logs a 5xx route error', () => { + expect(shouldLogRouteError(routeError(500), req())).toBe(true); + }); + + it('logs an ordinary thrown Error', () => { + expect(shouldLogRouteError(new Error('Network connection lost.'), req())).toBe(true); + }); + + it('does not log a Response with a 4xx status', () => { + expect(shouldLogRouteError(new Response('nope', { status: 404 }), req())).toBe(false); + }); + + it('does not log when the client already aborted the request', () => { + const ctrl = new AbortController(); + ctrl.abort(); + expect(shouldLogRouteError(new Error('aborted'), new Request('https://x.test/', { signal: ctrl.signal }))).toBe(false); + }); +}); + +describe('logRouteError', () => { + it('logs a real error with the method and the path only, never the query string', () => { + const spy = vi.spyOn(logger, 'error').mockImplementation(() => undefined); + logRouteError(new Error('boom'), req()); + expect(spy).toHaveBeenCalledTimes(1); + const text = JSON.stringify(spy.mock.calls); + expect(text).toContain('/read-document'); + expect(text).toContain('POST'); + expect(text).not.toContain('SECRET'); + }); + + it('logs nothing for a 404', () => { + const spy = vi.spyOn(logger, 'error').mockImplementation(() => undefined); + logRouteError(routeError(404), req()); + expect(spy).not.toHaveBeenCalled(); + }); +});