There are two logging modules in this codebase. lib/logger.ts writes to the
console. lib/error-monitoring.ts sends to Sentry. Counting call sites across
app, lib, components and scripts:
| module | function | call sites |
|---|---|---|
| logger | logError |
89 |
| logger | logDatabaseError |
45 |
| logger | logInfo |
34 |
| logger | logPayment |
33 |
| logger | logDebug |
18 |
| logger | logJob |
7 |
| logger | logValidationError |
7 |
| logger | logScoringOperation |
7 |
| logger | logScoringError |
5 |
| logger | logWebhook |
4 |
| error-monitoring | logWebhookError |
8 |
| error-monitoring | logAuthError |
6 |
| error-monitoring | captureError |
4 |
| error-monitoring | logPaymentError |
3 |
249 against 21. An eleven to one ratio between "write this down" and "wake
somebody up", which is roughly the ratio I would choose on purpose, and was not
chosen on purpose at all.
The rename
The Sentry module's main export is captureError. The doc comment explains why
it is not called logError:
Named
captureError, notlogError, so it never collides with the
console-onlylogErrorin lib/logger.ts. Both used to be importable under the
same name, which made "which logger is this?" a per-import-line question.
That is the entire bug: two functions with the same name, different
destinations, and an import line at the top of the file as the only way to tell
which one you were reading. In a 500 line webhook handler that imports both
modules, the reviewer has to scroll to the imports to know whether a given
failure leaves the machine.
Both are imported in our Stripe handler, which is what forced the issue:
import { logPaymentError, logWebhookError } from '@/lib/error-monitoring';
import { logWebhook, logPayment, logDebug, logError } from '@/lib/logger';
Four names from one module and two from the other, and now you can tell them
apart without looking up. logError is console. captureError and the
log*Error wrappers are Sentry. The convention is not beautiful but it is
checkable.
Which calls survive production
lib/logger.ts has one module level flag and the entire policy hangs off it:
const isDevelopment = process.env.NODE_ENV === 'development';
logDebug, logInfo and logScoringOperation are development only and print
nothing in production. logError, logJob and logScoringError always print.
In between sit the interesting ones, which print in both environments but drop
their details in production:
export function logWebhook(eventType: string, details?: unknown) {
if (isDevelopment) {
console.log(`[WEBHOOK] ${eventType}`, details);
} else {
console.log(`[WEBHOOK] ${eventType}`);
}
}
The rule is not "quieter in production". It is that the dropped details are
customer data: a webhook payload, a payment description, the full game state
behind a validation error, the SQL behind a database error. The event happened and
stays in the log; what it happened to does not.
The exception proves it. logJob keeps its details in both environments, and the
comment says exactly why:
Unlike
logWebhookandlogPayment, which drop their details in production
because those details are customer data, the details here are job counters
(rows scanned, rows deleted, duration) with nothing personal in them, so they
are kept in both environments. Anything user-identifying belongs in a different
logger.
logJob only exists because logInfo is development only. A nightly job that
deletes tens of thousands of rows has to stay visible in the platform logs, and
routing its summary through the dev-only logger silenced the one place anybody
would look to answer what last night's run actually did.
The prefixes are a poor structured logger
Every function stamps a bracketed prefix: [DEBUG], [INFO], [ERROR],
[WEBHOOK], [PAYMENT], [JOB], [VALIDATION ERROR], [SCORING ERROR],
[DATABASE ERROR], [SCORING]. In a log drain you grep for the bracket and get
a channel.
I am not going to pretend this is good. They are substrings of a message, not
fields, so nothing can aggregate them, the two-word ones have a space in the
middle, and [ERROR] and [DATABASE ERROR] both match a naive grep for
ERROR]. A real structured logger would make every one of those a queryable
attribute. The reason it has survived is that the honest alternative is adding a
logging dependency to a project whose actual logging requirement is "be findable
in the Vercel dashboard at 2am", and the prefix meets it.
One thing it does buy us, and this is checkable from outside. Those prefixes
belong to server code, so none of them should ever ship to a browser. Open
https://cogniprep.app/games and run this:
const srcs = [...document.querySelectorAll('script[src]')].map((s) => s.src);
let bytes = 0, hits = 0;
for (const u of srcs) {
const t = await (await fetch(u)).text();
bytes += t.length;
if (/\[(DEBUG|INFO|SCORING|PAYMENT)\]/.test(t)) hits++;
}
console.log(srcs.length, bytes, hits);
// 28 2262173 0
Twenty eight chunks, about 2.26 MB of JavaScript, zero of those prefixes. The
import boundary holds on that page.
The hole, and the field with the wrong name
error-monitoring.ts is 80 lines. captureError opens a Sentry scope, attaches
the context as extras, promotes userId to the Sentry user, sets the level, and
captures. The four wrappers do nothing but add a category:
export function logWebhookError(error: Error | unknown, context: { eventType?: string; signature?: string }) {
captureError(error, { ...context, category: 'webhook' }, 'error');
}
Typed context per channel is the good part: a webhook error is encouraged to
carry an event type and an auth error an action, so the reports are comparable.
The hole is one line in the shared interface:
interface ErrorContext {
userId?: string;
email?: string;
customerId?: string;
[key: string]: any;
}
That index signature means any caller can attach anything, nothing is redacted
on the way out, and the only thing standing between an error report and a
customer's data is the discipline of 21 call sites. Every one of them is
currently fine. "Currently fine, enforced by nothing" is not a property, it is a
coincidence with good manners.
And then there is the field that is already being misused. logWebhookError
declares signature?: string, which reads as "the webhook signature header we
rejected", and one call site does pass exactly that on a verification failure.
Two others pass something else entirely:
logWebhookError(new Error('Rate limit check failed'), { signature: identifier });
logWebhookError(new Error('Webhook rate limit exceeded'), { signature: identifier });
identifier is the rate limit client identifier. It is not a signature, it has
nothing to do with signatures, and it is in Sentry under a key that says it is
one. Nobody noticed because the type is string and so is the thing being
handed to it. A field name is documentation that the compiler will not check, and
an optional field with a plausible type is the easiest place in a codebase to put
the wrong value.
Both fixes are small: name the field after what it carries, and replace the index
signature with a union of the keys we actually allow. Neither is done yet, which
is the real reason I wrote this down.
If you want the half of this that is observable from a browser, the snippet
above runs on https://cogniprep.app/games and takes a few seconds. The other side, the one you have to
take my word for, is that a message sent from https://cogniprep.app/help
produces no log line at all unless something fails, and the line it produces
then names the route rather than anything you typed.
Top comments (0)
Some comments may only be visible to logged-in visitors. Sign in to view all comments.