DEV Community

Daniel Pertu
Daniel Pertu

Posted on

249 calls into the logger that only writes to a console, 21 into the one that leaves the machine

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, not logError, so it never collides with the
console-only logError in 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';
Enter fullscreen mode Exit fullscreen mode

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';
Enter fullscreen mode Exit fullscreen mode

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}`);
  }
}
Enter fullscreen mode Exit fullscreen mode

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 logWebhook and logPayment, 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
Enter fullscreen mode Exit fullscreen mode

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');
}
Enter fullscreen mode Exit fullscreen mode

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;
}
Enter fullscreen mode Exit fullscreen mode

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 });
Enter fullscreen mode Exit fullscreen mode

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.