---
title: 'Logging Setup'
source: 'https://academia.sh/en/courses/server-fundamentals/logging-setup'
course: 'Server-Side Fundamentals'
language: en
updated: '2026-08-19T05:19:37+00:00'
license: 'CC BY-SA 4.0'
---

# Logging Setup

Log lines are produced as JSON objects; the request context is carried through asynchronous local storage, deep layers record the request id without taking it as a parameter, the level threshold determines the line count, and every line belonging to a single request is gathered with a query.

This lesson's log lines were in JSON, and each one carried a request id, but that id was only
written by hand in two places. In a real application, the same request passes through the
chain's links, the handler, the domain layer, and the data layer; every layer produces its own
record. Does every function have to take the id as a parameter for it to appear on every line?

This lesson sets up three things: the shape of the log line, carrying the request context across
layers, and querying the lines afterward. The measurement will show that the records of three
concurrent requests do not get mixed up.

## Why the Line Is an Object

A free-text log line is read by a person, not by a machine. Extracting the ISBN from the line
"Loan request rejected, ISBN 978-0262033848" requires writing a pattern, and the pattern breaks
every time the message changes.

A **structured log record** solves this problem with named fields. Each line is an independent
JSON object; there is no separator between lines, and the file is processed line by line. The
fields a record has to carry fall into four groups:

- **When**: a timestamp in ISO 8601 format. Fixed length, sortable, and carries a time zone.
- **How important**: the level. Determines whether the record is written, based on the threshold.
- **What happened**: the event name. Not a free sentence but a fixed identifier — because it
  will be queried.
- **In what context**: the request id and fields specific to the event.

## Carrying the Context

Passing the request id to every function as a parameter works, but it comes at a high cost: the
signatures of functions that have nothing to do with logging change, and the chain breaks the
moment a function in the middle of it forgets to pass the parameter along.

The runtime provides **asynchronous local storage** for exactly this. A value is bound to a
specific call tree; every read made from within that tree — no matter how many `await` steps
later — sees the same value. Because concurrent requests have separate trees, the values never
mix.

```js
// src/setup/log.mjs — produces JSON log lines; reads the request context from async local storage
import { AsyncLocalStorage } from "node:async_hooks";

const LEVELS = { error: 0, warning: 1, info: 2, verbose: 3 };

export const requestStore = new AsyncLocalStorage();

export const createLog = (thresholdName) => {
  const threshold = LEVELS[thresholdName] ?? LEVELS.info;
  const write = (level, event, fields = {}) => {
    if (LEVELS[level] > threshold) return;                // level threshold: below it, nothing is written
    const context = requestStore.getStore() ?? {};         // request id never passed by hand
    console.log(JSON.stringify({
      at: new Date().toISOString(), level, event, ...context, ...fields,
    }));
  };
  return Object.fromEntries(
    Object.keys(LEVELS).map((l) => [l, (event, fields) => write(l, event, fields)]));
};
```

Levels are defined by their numeric counterparts; the comparison runs on these numbers. When the
threshold is `info`, `verbose` records are never written at all — they are not written to a file
and filtered out afterward, they are not even produced. This distinction is about cost: no
serialization happens for a record below the threshold.

The server runs every request in its own context. The `checkShelf` function in the data layer
does not take the request id, does not know it, and does not pass it along; even so, the lines
it produces carry the id.

```js
// src/http/server.mjs — each request runs in its own context; deep layers do not carry the id
import { createServer } from "node:http";
import { setTimeout as wait } from "node:timers/promises";
import { createLog, requestStore } from "../setup/log.mjs";

const log = createLog(process.env.LIBRARY_LOG_LEVEL ?? "info");
const ON_SHELF = new Set(["978-0262033848"]);
let counter = 0;

// Deep function in the data layer: does NOT take the request id as a parameter.
const checkShelf = async (isbn) => {
  log.verbose("shelf_query", { isbn });
  await wait(150);                                   // delay standing in for a store access
  const found = ON_SHELF.has(isbn);
  log.info("shelf_result", { isbn, found });
  return found;
};

createServer((req, res) => {
  res.sendDate = false;
  const context = { requestId: `r-${++counter}` };
  requestStore.run(context, async () => {               // context spans this request's whole chain
    const start = process.hrtime.bigint();
    const url = new URL(req.url, "http://local");
    log.info("request_received", { method: req.method, path: url.pathname });

    let status = 404, body = { error: "path_not_found" };
    if (url.pathname === "/loans") {
      const found = await checkShelf(url.searchParams.get("isbn") ?? "");
      status = found ? 201 : 409;
      body = found ? { loan: "granted" } : { error: "shelf_empty" };
      if (!found) log.warning("loan_rejected", { reason: "shelf_empty" });
    } else if (url.pathname === "/books") {
      status = 200;
      body = { bookCount: ON_SHELF.size };
    }

    const text = JSON.stringify({ ...body, requestId: context.requestId });
    res.writeHead(status, { "content-type": "application/json; charset=utf-8",
      "content-length": Buffer.byteLength(text), "x-request-id": context.requestId });
    res.end(text);

    const duration = Number(process.hrtime.bigint() - start) / 1e6;
    log.info("request_finished", { status, durationMs: Number(duration.toFixed(1)) });
  });
}).listen(8438, "127.0.0.1", () => log.info("server_started", { port: 8438 }));
```

The request id is also present in the response: both in the `x-request-id` header and in the
body. The number a member gives when asking for support leads straight to the log.

## Measurement

The measurement runs the server with two different thresholds. In each round, three requests are
sent close to concurrently: a loan for a book that is on the shelf, a quick catalog request, and
a loan for a book that is not on the shelf. The filtering is done with `jq`, a filter that
operates on a stream of JSON.

```bash
#!/usr/bin/env bash
# Opens the server with two level thresholds; collects the log lines of three near-simultaneous requests and queries them.
run() {  # $1 = log level, $2 = output file
  LIBRARY_LOG_LEVEL="$1" node src/http/server.mjs > "$2" 2>&1 & s=$!
  sleep 0.7
  curl -sS -o /dev/null 'http://127.0.0.1:8438/loans?isbn=978-0262033848' & p1=$!
  sleep 0.05
  curl -sS -o /dev/null 'http://127.0.0.1:8438/books' & p2=$!
  sleep 0.05
  curl -sS -o /dev/null 'http://127.0.0.1:8438/loans?isbn=978-0000000000' & p3=$!
  wait "$p1" "$p2" "$p3"
  sleep 0.2
  kill "$s"; wait "$s" 2>/dev/null
}

run info log-info.jsonl
run verbose log-verbose.jsonl

echo "--- log (threshold=info), in time order ---"
cat log-info.jsonl

echo "--- every line for a single request: r-1 ---"
jq -c 'select(.requestId == "r-1")' log-info.jsonl

echo "--- line count by level ---"
for file in log-info.jsonl log-verbose.jsonl; do
  printf '%-24s %s\n' "$file" \
    "$(jq -r .level "$file" | sort | uniq -c | tr '\n' ' ' | tr -s ' ')"
done

rm -f log-info.jsonl log-verbose.jsonl
```

```
--- log (threshold=info), in time order ---
{"at":"2026-08-18T04:20:15.331Z","level":"info","event":"server_started","port":8438}
{"at":"2026-08-18T04:20:16.028Z","level":"info","event":"request_received","requestId":"r-1","method":"GET","path":"/loans"}
{"at":"2026-08-18T04:20:16.083Z","level":"info","event":"request_received","requestId":"r-2","method":"GET","path":"/books"}
{"at":"2026-08-18T04:20:16.085Z","level":"info","event":"request_finished","requestId":"r-2","status":200,"durationMs":2}
{"at":"2026-08-18T04:20:16.144Z","level":"info","event":"request_received","requestId":"r-3","method":"GET","path":"/loans"}
{"at":"2026-08-18T04:20:16.179Z","level":"info","event":"shelf_result","requestId":"r-1","isbn":"978-0262033848","found":true}
{"at":"2026-08-18T04:20:16.180Z","level":"info","event":"request_finished","requestId":"r-1","status":201,"durationMs":152.3}
{"at":"2026-08-18T04:20:16.295Z","level":"info","event":"shelf_result","requestId":"r-3","isbn":"978-0000000000","found":false}
{"at":"2026-08-18T04:20:16.295Z","level":"warning","event":"loan_rejected","requestId":"r-3","reason":"shelf_empty"}
{"at":"2026-08-18T04:20:16.296Z","level":"info","event":"request_finished","requestId":"r-3","status":409,"durationMs":151.8}
--- every line for a single request: r-1 ---
{"at":"2026-08-18T04:20:16.028Z","level":"info","event":"request_received","requestId":"r-1","method":"GET","path":"/loans"}
{"at":"2026-08-18T04:20:16.179Z","level":"info","event":"shelf_result","requestId":"r-1","isbn":"978-0262033848","found":true}
{"at":"2026-08-18T04:20:16.180Z","level":"info","event":"request_finished","requestId":"r-1","status":201,"durationMs":152.3}
--- line count by level ---
log-info.jsonl           9 info 1 warning
log-verbose.jsonl        9 info 2 verbose 1 warning
```

Timestamps and duration fields change on every run; the order of the lines relative to one
another can also shift depending on timing.

## What the Measurement Shows

**The lines are interleaved.** Between the first request's `request_received` line and its
`shelf_result` line sit three lines belonging to the second and third requests. In a log read in
time order, a single request's flow is not visible; this is the unavoidable consequence of an
application that runs concurrently in a single process.

**The ids did not mix up.** The `checkShelf` function was called by two of the three requests,
each call waited a hundred and fifty milliseconds, and other requests' code ran during that
wait. Even so, one `shelf_result` line carries `r-1`, the other `r-3`. The function never took
that id from any parameter.

**The query reconstructs the flow.** When the `jq` filter selects the lines belonging to a
single id, the request's own story emerges: received, shelf checked, finished. This is
structured logging's real payoff — the log is written in time order and reordered on demand.

**The duration measurement is part of the record.** The `durationMs` field on the
`request_finished` line shows the second request finishing in about two milliseconds, while the
loan requests took just over a hundred and fifty milliseconds. Because the same field carries the
same name on every line, querying for slow requests is a single filter expression.

**The threshold determines the line count.** At the `info` threshold, the file holds ten lines;
at `verbose`, `shelf_query` records are added and the count rises to twelve. Because the
threshold comes from configuration, the level of detail can be changed without rebuilding the
release.

## Where the Log Is Written

The server writes its log to standard output; it does not open a file, rotate one, or compress
one. This is not a gap, it is a deliberate boundary: the application's job is to **produce** the
record, not to store it.

The reasoning was measured in an earlier lesson. The application runs as multiple processes, and
processes are mortal; each process writing to its own file would scatter a single request's
trail across several files, and a dead process's file would end up orphaned. Once written to
standard output, the collecting work belongs to the layer that runs the process: the output of
every process merges into a single stream.

The name and the reasoning for this separation come back up in this section's last lesson, among
the portability principles.

## Summary

- A structured log record writes each line as an independent JSON object; the timestamp is in
  ISO 8601 format, the event name is a fixed identifier, and the context is carried in named
  fields.
- The level threshold comparison is numeric, and a record below the threshold is never produced;
  in the measurement, ten lines were written at the `info` threshold and twelve at the `verbose`
  threshold.
- Asynchronous local storage binds the request context to the call tree; even though the
  function in the data layer does not take the request id as a parameter, the lines it produces
  carry the correct id.
- Concurrent requests' lines interleave in time order; a single request's flow is only
  reconstructed by filtering on its id.
- The log is written to standard output; the work of collecting and storing it is left to the
  layer that runs the process, because processes are numerous and mortal.

## Next Step

This lesson's server had error handling squeezed into a single branch: a book not on the shelf
produced `409`. In a real application, errors come from two separate sources — the user's
mistaken request and the application's own defect — and the two cannot be handled the same way.
The next lesson sets up a shared error response: which error maps to which status code, which
fields the response body carries, and what test verifies that the body does not leak internal
detail?