fix(logging): stop 4xx scanner traffic reading as errors, and mark alertable failures

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,

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,

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:<code>]` 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<string, unknown>, error?: Error) {
+        this.error(`[alert:${code}] ${message}`, data, error);
+    }
 }
 
 // Default singleton instance

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);
+}

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<string, unknown>) => {
+  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)');
+  });
+});

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<string, unknown>;
+    expect(line).toMatchObject({ level: 'ERROR', message: 'boom', data: { a: 1 } });
+  });
+
+  it('alert() is an ERROR line whose message starts with an [alert:<code>] 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<string, unknown>;
+    expect(line.level).toBe('ERROR');
+    expect(String(line.message).startsWith('[alert:email-quota-exceeded] ')).toBe(true);
+    expect(line.message).toContain('daily quota used up');
+  });
+});

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();
+  });
+});