Logging

The Error Handling Strategy lesson mentioned recording failures a few times, but where and in what form was never settled. A free-text line — error: could not open file — is not enough for someone looking for the failure: which file, which request, which process, how many times?

This lesson settles the log format. Term choice: the log is the sequence of records a process produces; logging is the work of producing those records.

Structured Records

A log line addresses two readers at once: the person looking at it during a failure, and a program that filters, counts, and generates alerts from records. What satisfies both is each line being a record parsable on its own.

The measurement file’s format is useful here too: one JSON object per line. The line-based tools from the Shell Programming course work directly with this format.

// log.mjs
const LEVELS = { verbose: 20, info: 30, warn: 40, error: 50 };

export function createLogger({
  level = 'info',
  service,
  output = process.stdout,
  clock = () => new Date().toISOString(),   // can be fixed in tests
  fixedFields = {},
} = {}) {
  const threshold = LEVELS[level] ?? LEVELS.info;

  function write(levelName, message, fields = {}) {
    if (LEVELS[levelName] < threshold) return;
    output.write(JSON.stringify({
      time: clock(),
      level: levelName,
      service,
      message,
      ...fixedFields,
      ...fields,
    }) + '\n');
  }

  const logger = {};
  for (const name of Object.keys(LEVELS)) {
    logger[name] = (message, fields) => write(name, message, fields);
  }
  // A child logger that carries its own fields on every line it produces
  logger.child = (extraFields) => createLogger({
    level, service, output, clock,
    fixedFields: { ...fixedFields, ...extraFields },
  });
  return logger;
}

// try-log.mjs
import { createLogger } from './log.mjs';

const logger = createLogger({
  level: process.env.MEASUREMENTS_LOG_LEVEL ?? 'info',
  service: 'measurement-collector',
  clock: () => '2024-02-07T09:12:44.000Z',      // fixed so the example output does not change
});

logger.verbose('configuration read', { file: '.env' });
logger.info('request received', { route: '/measurement', method: 'POST', records: 12 });
logger.warn('threshold exceeded', { node: 'edge-03', value: 24.6 });
logger.error('could not open measurement file', { code: 'ENOENT', path: 'missing.ndjson' });

const requestLogger = logger.child({ requestId: 'r-0007' });
requestLogger.info('response written', { status: 201, duration_ms: 3 });

node try-log.mjs

{"time":"2024-02-07T09:12:44.000Z","level":"info","service":"measurement-collector","message":"request received","route":"/measurement","method":"POST","records":12}
{"time":"2024-02-07T09:12:44.000Z","level":"warn","service":"measurement-collector","message":"threshold exceeded","node":"edge-03","value":24.6}
{"time":"2024-02-07T09:12:44.000Z","level":"error","service":"measurement-collector","message":"could not open measurement file","code":"ENOENT","path":"missing.ndjson"}
{"time":"2024-02-07T09:12:44.000Z","level":"info","service":"measurement-collector","message":"response written","requestId":"r-0007","status":201,"duration_ms":3}

The timestamp was fixed in the example; in a real run, every line carries its own moment. Supplying the clock from outside is not a convenience, it is a testability requirement — the Test lesson uses this hook.

The message text is fixed, variable information goes into separate fields. This separation makes searching possible: searching "message":"request received" finds every request; if the file name were embedded in the message, every line would differ.

Level Threshold

Four levels are ordered by numeric weight, and records below the threshold never get written. The threshold comes from configuration, so log volume adjusts without changing code.

MEASUREMENTS_LOG_LEVEL=error node try-log.mjs

{"time":"2024-02-07T09:12:44.000Z","level":"error","service":"measurement-collector","message":"could not open measurement file","code":"ENOENT","path":"missing.ndjson"}

The meaning of each level is fixed by convention; a meaningless order makes the threshold useless:

• error — the operation could not complete, someone needs to look.
• warn — the operation completed, but something unexpected happened.
• info — milestones in the service’s normal flow.
• verbose — detail needed for diagnosis; off during normal operation.

The most common mistake is writing everything at the error level. A real failure becomes invisible in the noise, and the level distinction loses its meaning.

Carrying Optional Fields

In a concurrently running service, log lines arrive interleaved; collecting the lines from one request needs a shared field. The child method returns a logger that adds the given fields to every line it produces.

In the output’s last line above, requestId was added this way. When an id is generated at the start of a request and a child logger is created from it, every record from that request carries the same value and is gathered with one search.

Carrying the id in a header from the client makes it possible to trace a request across multiple services. An incoming id is not trusted directly: its form gets validated, or it is written alongside a self-generated id as a second field.

Writing an Error to the Log

The most important record written to the log is the error record, and it is also the most often written wrong. Putting the error object directly into a field creates two problems. First, an Error object’s name, message, and stack fields are not enumerable; serialization skips them, leaving an empty object. Second, spreading the whole object (...error) defeats the masking from the Configuration Management lesson — a connection error might carry the connection string in one of its fields.

The right way is to explicitly choose which fields get written:

// log-error.mjs
export function errorFields(error, { stackTrace = false } = {}) {
  const fields = { errorName: error.name, errorMessage: error.message };
  if (error.code !== undefined) fields.errorCode = error.code;

  const chain = [];
  let cause = error.cause;
  while (cause instanceof Error && chain.length < 5) {
    chain.push(cause.code ?? cause.name);
    cause = cause.cause;
  }
  if (chain.length > 0) fields.causeChain = chain;

  if (stackTrace && typeof error.stack === 'string') {
    fields.stackTrace = error.stack.split('\n')[0];
  }
  return fields;
}

The cause chain built in the Error Handling Strategy lesson pays off here: the codes underneath a wrapped error are gathered into a single array field.

// try-log-error.mjs
import { readFile } from 'node:fs/promises';
import { createLogger } from './log.mjs';
import { errorFields } from './log-error.mjs';
import { OperationalError } from './error-types.mjs';

const logger = createLogger({
  service: 'measurement-collector',
  clock: () => '2024-02-07T09:12:44.000Z',
});

try {
  await readFile('missing.ndjson', 'utf8');
} catch (underlying) {
  const error = new OperationalError('could not open measurement file', {
    code: 'MEASUREMENT_FILE_MISSING', status: 503, cause: underlying,
  });
  logger.error('request could not be fulfilled', { ...errorFields(error), route: '/summary' });
}

logger.error('unexpected type', { ...errorFields(new TypeError('value must be finite'), { stackTrace: true }) });

node try-log-error.mjs

{"time":"2024-02-07T09:12:44.000Z","level":"error","service":"measurement-collector","message":"request could not be fulfilled","errorName":"OperationalError","errorMessage":"could not open measurement file","errorCode":"MEASUREMENT_FILE_MISSING","causeChain":["ENOENT"],"route":"/summary"}
{"time":"2024-02-07T09:12:44.000Z","level":"error","service":"measurement-collector","message":"unexpected type","errorName":"TypeError","errorMessage":"value must be finite","stackTrace":"TypeError: value must be finite"}

The first record carries the ENOENT code from the bottom of the chain; someone looking for the failure reads the cause all the way down to the file system from a single line.

The stack trace is not written by default, for two reasons: it spans multiple lines and breaks the one-record-per-line contract, and it carries file paths and directory structure into the log. The example takes only the trace’s first line. Where the whole trace is needed, line breaks are escaped and it is written as a single JSON string — not as raw text.

Operational errors and programmer errors are separated in the log too. An operational error is an expected condition, and the warn level is often enough; a programmer error is always written at the error level with its full trace, because someone has to look.

Where the Log Is Written

The log is written to standard output. The process does not open its own file, does not rotate its own files, does not keep its own archive.

The reasoning is the same principle from the Shell Programming course: where output goes is decided by whoever calls the command, not the command itself. The supervisor that starts the process routes the output to a file, a collector, or a pipeline; the process does not know which. The same build runs unchanged across different operating setups.

The rule that diagnostic messages go to standard error meets an exception here: the structured log does not mix with data, because the service’s “data” is HTTP responses, not standard output. For command-line tools, the situation flips — the tool from the Command-Line Applications lesson writes its log to standard error, because standard output is the report itself.

One detail: writing is synchronous when standard output connects to a file, and can run asynchronously when it connects to a pipe. In the second case, a hard exit with process.exit can drop unwritten lines — the concrete counterpart of the warning from the Process Object lesson.

Inspecting Records

The gain from the structured format is that it needs no special tool:

node try-log.mjs > log.ndjson
grep -o '"level":"[a-z]*"' log.ndjson | sort | uniq -c | sort -rn

   2 "level":"info"
   1 "level":"warn"
   1 "level":"error"

When a field needs extracting, a short filter is enough:

grep '"level":"error"' log.ndjson | node -e "
const lines = require('node:fs').readFileSync(0, 'utf8').trim().split('\n');
for (const line of lines) { const parsed = JSON.parse(line); console.log(parsed.code, '|', parsed.message); }
"

ENOENT | could not open measurement file

In the second example, readFileSync(0, 'utf8') reads file descriptor 0 — standard input. The descriptor numbers from the Shell Programming course work directly here.

One last rule: personal data and secrets never go into the log. The admin key masked in the Configuration Management lesson can leak in as a field on an error object. Choosing fields explicitly — instead of spreading the whole error object — prevents this leak.

Summary

• A log line addresses both a person and a program; the one-JSON-object-per-line format satisfies both readers.
• The message text stays fixed, variable information goes into separate fields; this is what makes searching possible.
• Levels are ordered by numeric weight and the threshold comes from configuration; writing everything at the error level makes the distinction meaningless.
• A child logger adds the given fields to every line it produces, letting a request’s records be gathered.
• An error object is never written directly: its fields are chosen explicitly, the cause chain reduces to codes, and the stack trace is added only when requested.
• The log is written to standard output; the file, rotation, and archive are the job of the supervisor that starts the process.

Next Step

The measurement collector’s pieces have multiplied: the summarizer, configuration, error classes, the log, the server. That these work correctly has been checked by hand so far, by looking at output. The next lesson automates that check: it writes unit and integration tests with the runtime’s built-in test runner and shows what a failing test looks like and what the coverage report says.