Logging and error observability

Why this matters

A user reports: "I tried to save a maintenance record at about 2pm and it said something went wrong." You have the server. What can you actually find out?

If your answer is "I'd add a console.log and ask them to try again", you have no observability. Today you fix that: every request gets an ID, every request produces one structured line, and every error is traceable from the message the user saw back to the exact server-side cause — with no password, token, or session ID anywhere in the output.

That last constraint is not decoration. Logs get copied to laptops, shipped to third-party services, and read by people who never touch the database. A credential in a log file is a credential you have quietly given away.

Structured logs beat sentences

Most beginner logging is prose:

User logged in and then created equipment, took a while

You cannot filter that, count it, or sort it. A structured log is one machine-readable object per event — in practice, one JSON object per line:

{"time":"2026-08-03T14:02:11.482Z","level":"info","msg":"request","requestId":"6f1c...","method":"POST","path":"/equipment","status":201,"durationMs":37}

Now the questions become answerable: every status of 500 in the last hour, the slowest paths, whether a spike is one caller or many. The format costs you nothing to produce and turns your logs from a diary into data.

Three fields carry most of the value: what happened (msg, level), which request (requestId), and the outcome (status, durationMs).

Levels give you a volume control: debug for development detail, info for normal events, warn for handled problems worth noticing, error for a failed operation. Logging everything at one level means you either drown or miss things.

Request IDs tie the story together

One request produces several log lines — arrival, a slow query, a failure — and under concurrency they interleave with everyone else's. A request ID is a unique value generated when the request arrives and attached to every line it causes.

Two habits make it powerful:

• Return it to the client, in a response header and in error bodies. When a user pastes "error ref 6f1c8b2a", you grep one string and have their exact request.
• Accept an incoming one. If the caller already sent X-Request-Id, reuse it rather than generating a new one, so a trace survives across services.

Safe error messages: two audiences

An error has two readers with opposite needs.

The client needs enough to act and nothing more. Stack traces, SQL text, file paths, and library versions tell an attacker how your system is built and where its edges are.

The log needs everything: the stack, the failing query name, the actor ID.

So: log the detail, return the reference.

{"error":"Something went wrong","requestId":"6f1c8b2a"}

Expected failures are different. 400 name is required and 403 insufficient permissions are designed responses — specific on purpose, because the caller can fix them. It is only the unexpected 500 that becomes deliberately vague outward.

Redaction: what must never be logged

Write this list down and treat it as absolute.

• Passwords, in any form, including inside a whole request body
• Session IDs, API keys, tokens, Authorization and Cookie headers
• Full payment details and government identifiers
• More personal data than the log's purpose requires — an email address to debug a login is defensible; the user's entire profile on every request is not

The single most common leak is one line:

console.log('login attempt', req.body);   // NEVER — this prints the password

It looks harmless in development and writes plaintext passwords to your terminal, your log files, and any log service you later attach. Log req.body.email, or a count of fields — never the body of a credential-bearing request.

The systematic defence is a redaction function applied by the logger itself, so no future console.log decides the policy:

// src/logger.ts
const SECRET_KEYS = new Set([
  'password', 'passwordHash', 'password_hash', 'token', 'sid',
  'authorization', 'cookie', 'sessionId',
]);

function redact(value: unknown): unknown {
  if (Array.isArray(value)) return value.map(redact);
  if (value && typeof value === 'object') {
    return Object.fromEntries(
      Object.entries(value as Record<string, unknown>).map(([k, v]) =>
        SECRET_KEYS.has(k.toLowerCase()) ? [k, '[redacted]'] : [k, redact(v)],
      ),
    );
  }
  return value;
}

export function log(level: 'info' | 'warn' | 'error', msg: string, fields = {}) {
  process.stdout.write(
    JSON.stringify({ time: new Date().toISOString(), level, msg, ...redact(fields) as object }) + '\n',
  );
}

Deny-listing keys is imperfect — it catches password and misses pwd — so keep both defences: the redactor as a safety net, and the discipline of never handing whole request bodies to the logger. (Maintained loggers such as pino provide a redact option that does this job for you; the version above exists so you can see exactly what is happening.)

Walkthrough: request IDs and one line per request

Middleware first. It runs before your routes, and res.on('finish') fires once the response has been sent — which is when the status and duration are finally known.

// src/middleware/request-log.ts
import { randomUUID } from 'node:crypto';
import type { Request, Response, NextFunction } from 'express';
import { log } from '../logger.js';

export function requestLogger(req: Request, res: Response, next: NextFunction) {
  const requestId = (req.header('x-request-id') ?? randomUUID()).slice(0, 36);
  const started = Date.now();

  req.requestId = requestId;
  res.setHeader('X-Request-Id', requestId);

  res.on('finish', () => {
    log(res.statusCode >= 500 ? 'error' : 'info', 'request', {
      requestId,
      method: req.method,
      path: req.route?.path ?? req.path,
      status: res.statusCode,
      durationMs: Date.now() - started,
    });
  });

  next();
}

Register it before your routes:

app.use(requestLogger);

Then the error handler — four parameters, and registered last, after every route:

// src/middleware/error-handler.ts
import type { Request, Response, NextFunction } from 'express';
import { AppError, STATUS_FOR } from '../errors.js';
import { log } from '../logger.js';

export function errorHandler(
  err: unknown,
  req: Request,
  res: Response,
  next: NextFunction,
) {
  if (err instanceof AppError) {
    return res.status(STATUS_FOR[err.code]).json({ error: err.message });
  }
  log('error', 'unhandled', {
    requestId: req.requestId,
    message: err instanceof Error ? err.message : String(err),
    stack: err instanceof Error ? err.stack : undefined,
  });
  res.status(500).json({ error: 'Something went wrong', requestId: req.requestId });
}

app.use(errorHandler);   // after all routes

Two housekeeping notes. STATUS_FOR — the code-to-status map from Day 50 — moves next to AppError in errors.ts now that two files need it. And req.requestId needs the same Express.Request declaration you added for req.actor on Day 52; add the property beside it.

Express recognises a middleware with four parameters as the error handler; that is why next is present even though it is unused. (Express 5 forwards rejected promises from async handlers automatically. On Express 4 you must catch and call next(error) yourself.)

Now force a failure. Add a temporary route:

router.get('/boom', () => { throw new Error('database connection lost'); });

curl -i http://localhost:3000/boom

HTTP/1.1 500 Internal Server Error
X-Request-Id: 6f1c8b2a-6b0e-4b2f-9a11-2f0c9a8b7d10
{"error":"Something went wrong","requestId":"6f1c8b2a-6b0e-4b2f-9a11-2f0c9a8b7d10"}

And in the server terminal, two lines sharing that ID — one with the real cause, one with the outcome:

{"time":"2026-08-03T14:02:11.470Z","level":"error","msg":"unhandled","requestId":"6f1c8b2a-...","message":"database connection lost","stack":"Error: database connection lost\n    at ..."}
{"time":"2026-08-03T14:02:11.482Z","level":"error","msg":"request","requestId":"6f1c8b2a-...","method":"GET","path":"/boom","status":500,"durationMs":12}

That is the whole point of today: the user gave you eight characters, and you have the stack.

Your turn

1. Create src/logger.ts with the log function and redact. Run the two-minute experiment.
2. Add requestLogger before your routes. Confirm every response carries X-Request-Id.
3. Log method, path, status, and durationMs on one line per request. Use the route pattern (/equipment/:id) rather than the raw path where you can, so IDs do not fragment your data.
4. Add the error handler last, with four parameters. Confirm AppError still produces its normal 400 / 403 / 404 / 409 responses with their specific messages.
5. Add a temporary /boom route, call it, and confirm you can go from the client requestId to the stack trace in the logs. Remove the route afterwards.
6. Log in through POST /auth/login and inspect every log line produced. If the password, the session ID, or the Cookie header appears anywhere, fix it now.
7. Search the whole project for accidental leaks: grep -rn "console.log" src/. Replace or delete each one; a stray console.log(req.body) on an auth route is exactly the bug you are hunting.
8. Save a short log excerpt covering one success and one failure in docs/log-sample.md, with the IDs left intact and any secrets confirmed absent.

Common pitfalls

• Logging the whole request body. One line, every password. The most common real-world leak in this list.
• Logging inside the route before the response exists. You get the path but no status or duration. res.on('finish') is where the outcome is known.
• Returning stack traces to the client. It leaks your internals to anyone probing. Detail in the log, reference in the response.
• Registering the error handler before the routes. Express walks middleware in order, so it never runs. It goes last, always.
• One log line per request with no ID. Under any concurrency you cannot tell which lines belong together.

Verify it yourself

Open today's reference, the OWASP Top 10, and find the entry covering security logging and monitoring failures.

1. OWASP lists events that should be logged — failed logins among them. Which of those does your API not yet record? Add one, and make sure it logs the email, never the password.
2. Find what OWASP says about sensitive data in logs. Does it agree with this lesson's absolute list? Note any item this lesson omitted.

Add both answers to docs/threat-model.md from yesterday. Failed logins that nobody records are brute-force attempts nobody notices.