Structured Logging

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.

// 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.

// 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.

// 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)`);

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.