--- title: Logging source: 'https://academia.sh/en/courses/nodejs/logging' course: 'The Node.js Runtime' language: en updated: '2026-08-17T18:09:51+00:00' license: 'CC BY-SA 4.0' --- # Logging Structured records instead of free text, level thresholds, carrying optional fields, writing the log to standard output, and inspecting records with tools. 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. ```js // 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; } ``` ```js // 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 }); ``` ```sh 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. ```sh 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: ```js // 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. ```js // 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 }) }); ``` ```sh 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: ```sh 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: ```sh 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.