The Three Signals of Observability

The previous course split the system into five processes and measured how every boundary gave birth to a new failure mode. The question left standing at its close was this: no tool was ever built for seeing where a request slows down or gets lost. This lesson builds the three parts of that tool and counts what each part can and cannot answer.

The three signals are these. A log is the text record of individual events. A metric is events reduced to a pre-chosen aggregate. A trace is the record that holds a job’s steps together with their durations, and each step is a span. All three measure, but each answers a different question; this lesson shows that not as a claim but as a step count.

Monitoring categories and alert thresholds were established in the Performance Anti-Patterns and Monitoring course; the category list is not repeated here. This course’s subject is the production side: how a signal is born in application code, which field it carries, and which it does not.

The Service Producing Three Signals

The setup continues as the previous course left it: catalog, membership, loan, notification, and fee are separate processes. The loan service calls the membership, catalog, and notification services; the membership service calls the fee service. The single source file below takes on all of their roles and produces all three signals on every request.

TL1 — all three signals are produced inside the process handling the request, with no extra collector process involved. Rationale: what gets measured is not how the signal travels, but which field it carries at the point where it is born. The question of wiring to a collector is handled separately in the fifth lesson.

// service.mjs — <name> <port> [downstream...]; every request produces all three signals; long-lived process
import { createServer } from "node:http";
import { appendFileSync, writeFileSync } from "node:fs";
const [name, port, ...downstream] = process.argv.slice(2);
writeFileSync(`log-${name}.txt`, ""); writeFileSync(`trace-${name}.txt`, "");
const metrics = { requests: 0, errors: 0, duration: 0 };  // metrics: totals only, no id
let localSeq = 0;                                  // the trace number is meaningful only in this process
const wait = (ms) => new Promise((c) => setTimeout(c, ms));

createServer(async (req, res) => {
  const u = new URL(req.url, "http://y");
  if (u.pathname === "/metrics") { res.end(JSON.stringify({ name, ...metrics, duration: Math.round(metrics.duration) })); return; }
  const member = u.searchParams.get("member"), copy = Number(u.searchParams.get("copy"));
  const t0 = performance.now(), no = ++localSeq;
  metrics.requests += 1;
  await wait(name === "catalog" && copy % 5 === 0 ? 100 : 5);  // every fifth copy is on a slow shelf
  let status = name === "fee" && member === "4023" ? 402 : 200;   // unpaid fee
  for (const p of downstream) {
    const y = await fetch(`http://127.0.0.1:${p}/work?member=${member}&copy=${copy}`);
    if (y.status !== 200) status = y.status;
  }
  const duration = performance.now() - t0;
  metrics.duration += duration; if (status !== 200) metrics.errors += 1;
  appendFileSync(`log-${name}.txt`,
    `[${new Date().toISOString()}] ${name}: member ${member} copy ${copy} request took ` +
    `${Math.round(duration)} ms, result ${status}\n`);
  appendFileSync(`trace-${name}.txt`, `${no} ${name} ${Math.round(duration)}\n`);
  res.statusCode = status; res.end(JSON.stringify({ name, status }));
}).listen(Number(port));

This first version of the three signals is deliberately plain. The log line is a flat sentence. The metric is three totals. The span carries only a number that increases within its own process. The next four lessons close these three gaps one at a time.

The source of slowness and errors is fixed: the catalog service spends a hundred milliseconds on every copy whose number is a multiple of five, every request from member 4023 comes back from the fee service with a 402, and that status climbs through membership up to the loan service. The client sends requests to the loan endpoint in sequence, picking members from a four-member rotation.

// run.mjs — <request count>; sends requests to the loan endpoint in sequence
const n = Number(process.argv[2]);
const MEMBER = ["4021", "4022", "4023", "4024"];      // 4023 is the member with an unpaid fee
for (let i = 1; i <= n; i += 1) {
  await fetch(`http://127.0.0.1:9101/work?member=${MEMBER[(i - 1) % 4]}&copy=${i}`);
}
console.log(`${n} requests sent`);

Same Question, Three Signals

The query tool tries to answer three questions with three signals. The questions are real ones: where did this request slow down, how many requests failed, and which user was affected.

A step is one pass the query makes over a record store: reading a file or an endpoint is a step, parsing plain text is a step, filtering is a step, trying to join two stores is a step. The counter lives in the code, it is not a guess. Steps are counted even for a question that goes unanswered — the work spent before giving up is also a cost.

// query.mjs — tries to answer three questions with three signals; every store pass is one step
import { readFileSync, statSync } from "node:fs";
const SERVICES = ["loan", "membership", "catalog", "fee", "notification"];
const PORT = { loan: 9101, membership: 9102, catalog: 9103, fee: 9104, notification: 9105 };
const RE = /member (\d+) copy (\d+) request took ([\d.]+) ms, result (\d+)/;
let step = 0; const count = () => { step += 1; };
const lines = (prefix, s) => { count(); return readFileSync(`${prefix}-${s}.txt`, "utf8").split("\n").filter(Boolean); };
const parseLog = () => {                       // plain text: one parsing pass per service
  const o = {};
  for (const s of SERVICES) o[s] = lines("log", s).map((l) => { const m = l.match(RE); return m && { member: m[1], duration: +m[3], status: +m[4] }; });
  for (const s of SERVICES) count();
  return o;
};
const readTrace = () => { const o = {}; for (const s of SERVICES) o[s] = lines("trace", s).map((l) => { const [no, , duration] = l.split(" "); return { no: +no, duration: +duration }; }); return o; };
const readMetrics = async () => { const o = {}; for (const s of SERVICES) { count(); o[s] = await (await fetch(`http://127.0.0.1:${PORT[s]}/metrics`)).json(); } return o; };
const print = (question, signal, answer) => console.log(`${question.padEnd(12)}${signal.padEnd(9)}${String(step).padStart(5)}  ${answer}`);

console.log(`${"question".padEnd(12)}${"signal".padEnd(9)}${"step".padStart(5)}  answer`);
const metrics = await readMetrics(); const baseStep = step;

// S1 — where did this request slow down (target: the slowest request at the loan endpoint)
const THRESHOLD = 60;                                // above 60 ms counts as a slow request
step = 0; const g = parseLog(); count();
const slow = g.loan.filter((r) => r.duration > THRESHOLD).length; count();
print("S1 where", "log", `unanswered (${slow} loan records above ${THRESHOLD} ms; no shared id with downstream records)`);
step = baseStep; count();
print("S1 where", "metric", `unanswered (no per-request breakdown; only the service average)`);
step = 0; const trace = readTrace(); count();
const slowSpans = trace.loan.filter((a) => a.duration > THRESHOLD).length; count();
print("S1 where", "trace", `partial (${slowSpans} spans above ${THRESHOLD} ms; which downstream leg is unclear)`);

// S2 — how many requests failed
step = 0; const g2 = parseLog(); count();
print("S2 errors", "log", `${g2.loan.filter((r) => r.status !== 200).length} requests`);
step = baseStep; count(); print("S2 errors", "metric", `${metrics.loan.errors} requests`);
step = 0; readTrace(); count(); print("S2 errors", "trace", `unanswered (no status field in the trace record)`);

// S3 — which user was affected
step = 0; const g3 = parseLog(); count();
print("S3 who", "log", `member ${[...new Set(g3.loan.filter((r) => r.status !== 200).map((r) => r.member))].join(",")}`);
step = baseStep; count(); print("S3 who", "metric", `unanswered (total counter, carries no id)`);
step = 0; readTrace(); count(); print("S3 who", "trace", `unanswered (no id field in the span)`);

const bytes = (prefix) => SERVICES.reduce((t, s) => t + statSync(`${prefix}-${s}.txt`).size, 0);
const records = (prefix) => SERVICES.reduce((t, s) => t + lines(prefix, s).length, 0);
const avg = (prefix) => Math.round(bytes(prefix) / records(prefix));   // bytes per record: robust to digit-count noise
const metricBytes = SERVICES.reduce((t, s) => t + JSON.stringify(metrics[s]).length, 0);
console.log(`\nvolume: log ${records("log")} records x avg. ${avg("log")} bytes, ` +
  `trace ${records("trace")} spans x avg. ${avg("trace")} bytes, ` +
  `metric ${SERVICES.length * 4} fields (independent of request count) / ${metricBytes} bytes`);

The block below brings up the five processes, sends twenty requests and asks the three questions, then sends a hundred and eighty more requests and reprints only the volume line.

node service.mjs fee 9104 &
node service.mjs catalog 9103 &
node service.mjs notification 9105 &
node service.mjs membership 9102 9104 &
node service.mjs loan 9101 9102 9103 9105 &
sleep 1

node run.mjs 20
node query.mjs
node run.mjs 180
node query.mjs | tail -1
pkill -f "node service.mjs"

20 requests sent
question    signal    step  answer
S1 where    log         12  unanswered (4 loan records above 60 ms; no shared id with downstream records)
S1 where    metric       6  unanswered (no per-request breakdown; only the service average)
S1 where    trace        7  partial (4 spans above 60 ms; which downstream leg is unclear)
S2 errors   log         11  5 requests
S2 errors   metric       6  5 requests
S2 errors   trace        6  unanswered (no status field in the trace record)
S3 who      log         11  member 4023
S3 who      metric       6  unanswered (total counter, carries no id)
S3 who      trace        6  unanswered (no id field in the span)

volume: log 100 records x avg. 86 bytes, trace 100 spans x avg. 13 bytes, metric 20 fields (independent of request count) / 292 bytes
180 requests sent
volume: log 1000 records x avg. 87 bytes, trace 1000 spans x avg. 14 bytes, metric 20 fields (independent of request count) / 305 bytes

Five of Nine Attempts Came Back Empty

The table has nine rows and five are unanswered. The ones that are answered: the metric gives the error count in six steps, the log in eleven; only the log gives the affected member, also in eleven steps. No signal fully answers the first question.

The difference is not signal quality but which field it carries. The metric gives the cheapest answer because the question it can answer was already chosen when the metric was written: the errors counter is the “how many requests failed” question, frozen into code. For the same reason it cannot answer “which member” — there is no id inside the total, and none can be recovered afterward. The log is the opposite: every event has its own line, so it answers the id question, but because it is a flat sentence, every query needs five separate parsing passes and the regular expression depends on the line format.

Volume

The last two lines are the third measure. Twenty external requests produced a hundred log records and a hundred spans across five processes; two hundred external requests produced a thousand records and a thousand spans. The ratio is fixed: five records per external request, because the call amplification is five and every process writes its own record. The average size per record is eighty-six to eighty-seven bytes for the log, thirteen to fourteen bytes for the trace; the roughly sixfold gap comes from the log carrying a fresh timestamp and sentence pattern on every line.

The metric sits outside this growth. Five services, four fields per service: twenty fields, no matter how many requests come in. The total payload grew from 292 to 305 bytes; the entire increase comes from the digit count of the accumulated duration total, not from the record count. The metric’s cost grows with the field count, not the request count; the log’s and the trace’s cost grow with the request count. This is also why the three signals are kept together: they answer the same question at different costs and different resolutions.

Summary

• The log records individual events, the metric records pre-chosen totals, the trace records a job’s steps as spans; all three were born from the same request in the same process.
• Five of nine attempts stayed unanswered: the metric could not answer the id question, the trace could not answer the status or id question, and no signal fully answered “where did this request slow down.”
• The metric spent the fewest steps (6), the log the most (11–12); the gap comes from plain text needing one parsing pass per service.
• The metric chooses its question when it is written: the errors counter makes one question cheap and closes off the id question permanently.
• Volume follows two different laws: 20 requests produced 100 records, 200 requests produced 1000; the metric stayed at 20 fields in both cases and grew only by its digit count.

Next Step

Three of the five unanswered questions share a single cause: there is no field in the records that identifies the request. Nothing connects the line the loan service writes to the line the catalog service writes, because the lines are written as sentences and a sentence carries only what that one process knows. The next lesson takes the log out of being a flat sentence, splits it into fields, and attaches to the request an id that crosses the process boundary. What gets measured is clear: how many of the same question’s filtering and parsing steps drop away, how many services a request becomes traceable across, and how many call sites are left without the id carried through them.