---
title: 'Structured Logging'
source: 'https://academia.sh/en/courses/observability/structured-logging'
course: 'Observability and Reliability'
language: en
updated: '2026-08-23T07:00:29+00:00'
license: 'CC BY-SA 4.0'
---

# Structured Logging

Turning the flat-sentence log into a field-based record and attaching to the request a correlation id that crosses the process boundary: how many parsing and filtering steps the same question takes to answer, how many services a request becomes traceable across, and counting the call sites left without the id carried through them.

The previous lesson left five questions unanswered, and three of them shared a single cause: no
field in the records identifies the request. The log line was a sentence, the sentence carried
only what that one process knew, and nothing joined one service's line to another's. This lesson
makes two changes: the record stops being a sentence and splits into fields, and the request
gets a **correlation id** that crosses the process boundary. Both changes have a cost, and both
are measured.

**Structured logging** means the record is made of named fields instead of free text. A
**correlation id** is a value given to an external request and carried through every internal
request it produces. The second is useless without the first: the id is ultimately a field
itself, and it needs to be a value that can be filtered by name, not a string that has to be
hunted for inside a free-text sentence.

## Records Split into Fields

The logger is hand-written and has a single job: merge the fixed fields with the call-time
fields and append them as a single line.

```js
// logger.mjs — field-based logger; every record is a single line, every field stands under its own name
import { appendFileSync } from "node:fs";
export const logger = (file, fixed) => (fields) =>
  appendFileSync(file, JSON.stringify({ ...fixed, ...fields }) + "\n");
```

The service writes **two** records on every request: the previous lesson's flat sentence and its
field-based counterpart. Both describe the same fact, from the same run, with the same values;
the only difference is format, so the step difference this lesson measures is purely a
difference in format.

**TL2 — the correlation id is generated by the service that first receives the external
request; if a header already carries an id, it is not regenerated, it is carried through as
is.** Rationale: the id must have a single point of generation, otherwise the same request picks
up a new id at every service and joining still cannot be done. Here the generation rule is tied
to the copy number, so the ids in the measurement stay independent of the run.

```js
// service2.mjs — <name> <port> [downstream...]; writes two log formats for the same request
import { createServer } from "node:http";
import { writeFileSync, appendFileSync } from "node:fs";
import { logger } from "./logger.mjs";
const [name, port, ...downstream] = process.argv.slice(2);
const NOTIFICATION = "9205";
writeFileSync(`plain-${name}.txt`, ""); writeFileSync(`fields-${name}.txt`, "");
const writeFields = logger(`fields-${name}.txt`, { service: name });
let counter = 0;
const wait = (ms) => new Promise((c) => setTimeout(c, ms));
const url = (p, u) => `http://127.0.0.1:${p}/work?member=${u.get("member")}&copy=${u.get("copy")}`;
const call = (p, u, correlationId) => fetch(url(p, u), { headers: { "x-correlation": correlationId } });
const notify = (p, u) => fetch(url(p, u));      // old helper: never took a header parameter

createServer(async (req, res) => {
  const u = new URL(req.url, "http://y").searchParams;
  const member = u.get("member"), copy = Number(u.get("copy"));
  const correlationId = req.headers["x-correlation"] ?? `${name}-${copy}`;   // generated when no id is present
  const t0 = performance.now(); counter += 1;
  await wait(name === "catalog" && copy % 5 === 0 ? 45 : 5);
  let status = name === "fee" && member === "4023" ? 402 : 200;
  for (const p of downstream) {
    const y = p === NOTIFICATION ? await notify(p, u) : await call(p, u, correlationId);
    if (y.status !== 200) status = y.status;
  }
  const duration = Math.round(performance.now() - t0);
  appendFileSync(`plain-${name}.txt`, `${name}: member ${member} copy ${copy} request took ` +
    `${duration} ms, result ${status}\n`);
  writeFields({ correlationId, member, copy, duration, status });
  res.statusCode = status; res.end("done");
}).listen(Number(port));
```

The id crosses the boundary in a single line: `call` adds the header. Next to it, `notify` is an
old helper that never took a header parameter, and the notification call is made through it.
This is not a staged mistake, it is the typical outcome of adding an id: the id gets added to a
client helper, but a call path that does not use that helper survives in the system. The
measurement's job is to count that path.

## Measurement

The query tool asks two questions in two formats. The step definition is the same as the
previous lesson: reading a file, parsing, filtering, or trying to join two stores are each one
step. In plain text every service has its own line pattern, so parsing takes one pass per
service; in the field-based record the format is uniform, so parsing takes a single pass.

```js
// query2.mjs — the same questions in two log formats; a step is one store pass
import { readFileSync } from "node:fs";
const SERVICES = ["loan", "membership", "catalog", "fee", "notification"];
const CALLS = [["loan", "membership"], ["loan", "catalog"], ["loan", "notification"], ["membership", "fee"]];
const RE = /member (\d+) copy (\d+) request took (\d+) ms, result (\d+)/;
let step = 0; const count = () => { step += 1; };
const line = (prefix, s) => { count(); return readFileSync(`${prefix}-${s}.txt`, "utf8").split("\n").filter(Boolean); };
const readPlain = () => {                       // every service has its own line pattern: one parsing pass per service
  const o = {};
  for (const s of SERVICES) o[s] = line("plain", s).map((l) => { const m = l.match(RE); return m && { member: m[1], copy: +m[2], duration: +m[3], status: +m[4] }; });
  for (const s of SERVICES) count();
  return o;
};
const readFields = () => {                      // field-based: uniform format, a single parsing pass
  const o = {}; for (const s of SERVICES) o[s] = line("fields", s);
  count(); for (const s of SERVICES) o[s] = o[s].map((l) => JSON.parse(l));
  return o;
};
const print = (question, format, answer) => console.log(`${question.padEnd(11)}${format.padEnd(13)}${String(step).padStart(5)}  ${answer}`);
console.log(`${"question".padEnd(11)}${"format".padEnd(13)}${"step".padStart(5)}  answer`);

// S3 — which member was affected (both formats can answer)
step = 0; const plain = readPlain(); count();
print("S3 who", "plain text", `member ${[...new Set(plain.loan.filter((r) => r.status !== 200).map((r) => r.member))].join(",")}`);
step = 0; const fields = readFields(); count();
print("S3 who", "field-based", `member ${[...new Set(fields.loan.filter((r) => r.status !== 200).map((r) => r.member))].join(",")}`);

// S1 — where did this request slow down; target: the request for copy number 5
const TARGET = "loan-5";
step = 0; readPlain(); count(); count();
print("S1 where", "plain text", "unanswered (no id field in the line, services cannot be joined)");
step = 0; const fields2 = readFields(); count();
const path = SERVICES.filter((s) => fields2[s].some((r) => r.correlationId === TARGET));
const longest = path.filter((s) => s !== "loan").sort((x, y) =>
  fields2[y].find((r) => r.correlationId === TARGET).duration - fields2[x].find((r) => r.correlationId === TARGET).duration)[0];
count(); print("S1 where", "field-based", `${TARGET}: ${path.join(" ")} (${path.length}/${SERVICES.length} services), longest downstream ${longest}`);

console.log(`\n${"call site".padEnd(26)}${"id".padEnd(8)}records with id`);
let carrying = 0;
for (const [upper, lower] of CALLS) {
  const set = new Set(fields[upper].map((r) => r.correlationId));
  const shared = fields[lower].filter((r) => set.has(r.correlationId)).length;
  if (shared > 0) carrying += 1;
  console.log(`${`${upper} -> ${lower}`.padEnd(26)}${(shared > 0 ? "yes" : "no").padEnd(8)}${shared}/${fields[lower].length}`);
}
console.log(`call sites carrying id ${carrying}/${CALLS.length}, not carrying ${CALLS.length - carrying}; ` +
  `a request is traceable across ${path.length}/${SERVICES.length} services`);
const bytes = (prefix) => Math.round(SERVICES.reduce((t, s) => t + readFileSync(`${prefix}-${s}.txt`, "utf8").length, 0) / 100);
console.log(`avg. bytes per record: plain text ${bytes("plain")} bytes, field-based ${bytes("fields")} bytes (100 records)`);
```

```bash
cat > run.mjs <<'EOF'
const MEMBER = ["4021", "4022", "4023", "4024"];      // 4023 is the member with an unpaid fee
for (let i = 1; i <= 20; i += 1)
  await fetch(`http://127.0.0.1:9201/work?member=${MEMBER[(i - 1) % 4]}&copy=${i}`);
EOF
node service2.mjs fee 9204 &
node service2.mjs catalog 9203 &
node service2.mjs notification 9205 &
node service2.mjs membership 9202 9204 &
node service2.mjs loan 9201 9202 9203 9205 &
sleep 1

node run.mjs
node query2.mjs
pkill -f "node service2.mjs"
```

```
question   format        step  answer
S3 who     plain text      11  member 4023
S3 who     field-based      7  member 4023
S1 where   plain text      12  unanswered (no id field in the line, services cannot be joined)
S1 where   field-based      8  loan-5: loan membership catalog fee (4/5 services), longest downstream catalog

call site                 id      records with id
loan -> membership        yes     20/20
loan -> catalog           yes     20/20
loan -> notification      no      0/20
membership -> fee         yes     20/20
call sites carrying id 3/4, not carrying 1; a request is traceable across 4/5 services
avg. bytes per record: plain text 59 bytes, field-based 101 bytes (100 records)
```

## Four Steps and One Blind Spot

The first comparison is an ordinary win. The same question took eleven steps in plain text,
seven in the field-based record. All four steps of the difference come from parsing: because
every service has its own line pattern in plain text, the regular expression has to run once per
service, while the field-based record's uniform format needs only a single pass. This gap grows
with the number of services — with twenty services instead of five, plain text would spend
twenty-five steps and the field-based record twenty-two, and the gap would widen to nineteen.
The fragility of parsing is here too: when a line pattern changes, the regular expression
silently stops matching, while when a field name changes, the record openly loses that field.

The second comparison is this lesson's real point. The question no signal in the previous lesson
could answer got answered in eight steps by the field-based record: the `loan-5` id shows up in
four services, and the longest of the downstream legs is catalog. Plain text is still unanswered
on the same question — the problem was never a lack of durations, it was a lack of the field
that would tie those durations together.

The third table shows the limit of the win. Three of the four call sites carry the id, one does
not; none of the notification service's twenty records carries the loan request's id. The
measured result is that a request is traceable across **four** of five services. Adding an id
costs a single line, but its coverage is measured in call paths, and a single skipped call site
leaves an entire service off the map. Notification was not picked at random here: "why did this
notification not go out" is the most frequently asked question in this system, and exactly that
service is left in the blind spot.

The last line gives the cost. The field-based record is 101 bytes per record, plain text 59:
because the field names get rewritten on every line, the volume grows by roughly seventy
percent. In exchange, query steps went down and a question that could not be answered became
answerable. That is the measured trade-off — bytes on the write side, steps on the read side.

## Summary

- The field-based record answered the same question in 7 steps instead of 11; the entire gap
  comes from parsing and grows with the number of services.
- The correlation id turned the previous lesson's unanswerable question into one answered in 8
  steps: the `loan-5` id was traced across four services, and the longest downstream leg turned
  out to be catalog.
- 3 of 4 call sites carry the id; the one that does not leaves the notification service entirely
  off the map, and a request is traceable across 4 of 5 services.
- A skipped call site is the natural residue of adding an id: the id gets added to a client
  helper, and an old call path that does not use that helper silently stays without it.
- The cost sits on the write side: the rise from 59 to 101 bytes per record comes from the field
  names repeating on every line.

## Next Step

The log is now split into fields, and a request's path is traceable across four services. But
every query still starts by reading and filtering every record: a hundred records were read for
twenty requests, a thousand will be read for two hundred. The previous lesson's metric signal
sat outside this cost, because the question it could answer was already chosen when the metric
was written. The next lesson looks at that choice itself: the same fact is measured with three
separate types — counter, gauge, and histogram — the question each type can and cannot answer is
counted, and the histogram's memory cost and percentile error are compared against its bucket
count.