Post-Incident Analysis

The previous lesson left this behind: every gap it measured was learned not when it was written, but when a failure touched it. Learning itself, though, is not yet a mechanism.

Root-cause analysis and the causal-chain model were built in M21/K05 Testing Process and Automation Infrastructure and are not repeated here. The subject here is narrower: rebuilding the incident from telemetry. This lesson asks a real incident six questions, counts which signal answers each and in how many steps, then applies the resulting actions to the code and asks the same questions again. A step was defined earlier in this course: one pass over a signal store, or a join matching two stores through a key.

The Incident

The notification service takes 200 ms instead of 5 ms from request 80 through request 140. RS17 — what the notification call site writes changes with three flags; each corresponds to an action coming out of this incident. With the flags off, the system is in the state measured in the Telemetry topic: a call site carrying no id leaves notification off the map.

// services.mjs — 8501 loan, 8502 notification, 8503 membership. Three signals are produced in application code.
// RS17: what the notification call site writes changes with three flags; each flag is a post-incident action.
import { createServer, request } from "node:http";
const S = { log: [], metric: [], trace: [] }, FLAG = { span: 0, id: 0, delivery: 0 };
const EVENT = [80, 140], TICK = 20, SLOW = 200, NORMAL = 5;  // the event starts at request 80, ends at 140
const metric = (tick, service, duration) => {        // counter + duration sum, carries no id
  const o = S.metric.find((x) => x.tick === tick && x.service === service)
    ?? S.metric[S.metric.push({ tick, service, requests: 0, total: 0 }) - 1];
  o.requests += 1; o.total += duration;
};
const call = (port, path, id) => new Promise((resolve) => {
  const t0 = Date.now();
  const r = request({ port, path, agent: false, headers: id ? { "x-id": id } : {} },
    (y) => { y.resume(); y.on("end", () => resolve(Date.now() - t0)); });
  r.on("error", () => resolve(Date.now() - t0)); r.end();
});
createServer((req, res) => { setTimeout(() => res.end("{}"), NORMAL); }).listen(8503);   // membership: always fast
createServer((req, res) => {                          // 8502 notification: slows during the event window
  const n = Number(new URL(req.url, "http://x").searchParams.get("n"));
  const slow = n >= EVENT[0] && n < EVENT[1], duration = slow ? SLOW : NORMAL;
  setTimeout(() => {
    const id = req.headers["x-id"] ?? null;          // action 2: does the call site carry the id
    const k = { t: n, service: "notification", id, duration };
    if (FLAG.delivery) k.delivery = !slow;            // action 3: is the delivery result written to the signal
    S.log.push(k);
    if (FLAG.span) S.trace.push({ id, service: "notification", duration });   // action 1: is the span written
    metric(Math.floor(n / TICK), "notification", duration);
    res.end("{}");
  }, duration);
}).listen(8502);
createServer(async (req, res) => {                    // 8501 loan
  const q = new URL(req.url, "http://x").searchParams;
  if (req.url === "/signal") return res.end(JSON.stringify(S));
  if (req.url.startsWith("/configure")) {
    for (const k of Object.keys(FLAG)) FLAG[k] = Number(q.get(k));
    for (const d of Object.keys(S)) S[d] = [];
    return res.end("{}");
  }
  const n = Number(q.get("n")), id = `loan-${n}`, t0 = Date.now();
  S.trace.push({ id, service: "membership", duration: await call(8503, "/member", id) });
  if (n % 3 === 0) await call(8502, `/send?n=${n}`, FLAG.id ? id : null);
  const duration = Date.now() - t0;
  S.log.push({ t: n, service: "loan", id, member: `u${n % 25}`, duration });
  S.trace.push({ id, service: "loan", duration });
  metric(Math.floor(n / TICK), "loan", duration);
  res.end("{}");
}).listen(8501);

Analysis

Six questions are six functions. Each works on real signal stores and increments the step counter on every pass; the number is not asserted, it comes out of the run. A missing field or join key leaves the question unanswered.

// analyze.mjs — rebuilding the incident from telemetry: which signal answers each question, in how many steps.
import { request } from "node:http";
const N = 200, THRESHOLD = 40, HEAVY = 100;          // RS18: event if the tick average exceeds THRESHOLD, a single call exceeds HEAVY
const call = (path) => new Promise((c) => request({ port: 8501, path, agent: false }, (r) => {
  let g = ""; r.on("data", (p) => (g += p)); r.on("end", () => c(g === "{}" ? null : JSON.parse(g)));
}).end());
let step = 0;
const scan = (store, f) => { step += 1; return store.filter(f); };   // one pass over one store
const join = (a, b) => {                                             // matching two stores through the id
  step += 1; const m = new Map(b.map((x) => [x.id, x])); return a.map((x) => m.get(x.id));
};
const slow = (x) => x.duration > HEAVY;
const notificationLog = (S) => scan(S.log, (x) => x.service === "notification" && slow(x));
const eventTicks = (S) => scan(S.metric, (x) => x.service === "loan" && x.total / x.requests > THRESHOLD).map((x) => x.tick);
const QUESTION = [
  ["which tick did the event start", "metric", (S) => { const t = eventTicks(S); return t.length ? `tick ${Math.min(...t)}` : null; }],
  ["which tick did the event end", "metric", (S) => { const t = eventTicks(S); return t.length ? `tick ${Math.max(...t) + 1}` : null; }],
  ["which dependency slowed", "trace", (S) => {
    const a = scan(S.trace, (x) => x.service !== "loan" && slow(x));
    return a.length ? [...new Set(a.map((x) => x.service))].join("+") : null;
  }],
  ["how many requests were affected", "log", (S) => {
    const b = notificationLog(S);
    if (b.length && b[0].id !== null) return `${new Set(b.map((x) => x.id)).size} requests`;
    const o = scan(S.log, (x) => x.service === "loan" && slow(x));   // no id: stores are scanned separately
    return scan(S.metric, (x) => x.service === "notification").length ? `${o.length} requests` : null;
  }],
  ["which members were affected", "log", (S) => {
    const b = notificationLog(S);
    if (!b.length || b[0].id === null) return null;                 // no key to join on
    const u = join(b, scan(S.log, (x) => x.service === "loan"));
    return `${new Set(u.map((x) => x.member)).size} members`;
  }],
  ["was the notification delivered", "log", (S) => {
    const b = scan(S.log, (x) => x.service === "notification" && x.delivery !== undefined);
    return b.length ? `${b.filter((x) => x.delivery === false).length} not delivered` : null;
  }],
];
const run = async (flags) => {
  await call(`/configure?${flags}`);
  for (let n = 0; n < N; n += 1) await call(`/request?n=${n}`);
  const S = await call("/signal");
  return QUESTION.map(([name, signal, f]) => { step = 0; const y = f(S); return { name, signal, y, step: y === null ? null : step }; });
};

const SETUP = [["at incident time", "span=0&id=0&delivery=0"], ["+ trace span", "span=1&id=0&delivery=0"],
  ["+ correlated id", "span=1&id=1&delivery=0"], ["+ delivery signal", "span=1&id=1&delivery=1"]];
const print = (a, ...r) => console.log(String(a).padEnd(28) + r.map((x) => String(x).padStart(16)).join(""));
const results = {};
console.log(`event: ${N} requests, notification takes 200 ms instead of 5 ms on requests 80-139; tick = 20 requests`);
print("configuration", "answered", "unanswered", "steps");
for (const [name, flags] of SETUP) {
  const r = (results[name] = await run(flags)), v = r.filter((x) => x.y !== null);
  print(name, v.length, r.length - v.length, v.reduce((a, x) => a + x.step, 0));
}
const format = (x) => (x.y === null ? "-" : `${x.y} (${x.step} steps)`);
console.log(`\n${"question".padEnd(34)}${"signal".padEnd(9)}${"at incident time".padEnd(30)}after the actions`);
results["at incident time"].forEach((x, i) =>
  console.log(x.name.padEnd(34) + x.signal.padEnd(9) + format(x).padEnd(30) + format(results["+ delivery signal"][i])));

const ACTION = { human: ["talk to the developer", "train the on-call engineer", "write an owner into the report"],
  system: ["write the trace span", "add the correlated id", "write the delivery result"] };
console.log(`\n${"analysis".padEnd(28)}${"actions".padStart(16)}${"returned to code".padStart(18)}${"question answered".padStart(20)}`);
for (const [kind, name, at] of [["human", "human-driven", "at incident time"], ["system", "system-driven", "+ delivery signal"]])
  print(name, ACTION[kind].length, kind === "system" ? ACTION[kind].length : 0, results[at].filter((x) => x.y !== null).length);
process.exit(0);

node services.mjs > /dev/null 2>&1 & SP=$!
sleep 1; node analyze.mjs; kill $SP

event: 200 requests, notification takes 200 ms instead of 5 ms on requests 80-139; tick = 20 requests
configuration                       answered      unanswered           steps
at incident time                           3               3               5
+ trace span                               4               2               6
+ correlated id                            5               1               7
+ delivery signal                          6               0               8

question                          signal   at incident time              after the actions
which tick did the event start    metric   tick 4 (1 steps)              tick 4 (1 steps)
which tick did the event end      metric   tick 7 (1 steps)              tick 7 (1 steps)
which dependency slowed           trace    -                             notification (1 steps)
how many requests were affected   log      20 requests (3 steps)         20 requests (1 steps)
which members were affected       log      -                             20 members (3 steps)
was the notification delivered    log      -                             20 not delivered (1 steps)

analysis                             actions  returned to code   question answered
human-driven                               3               0               3
system-driven                              3               3               6

How Many Steps It Takes to Build the Timeline

With the signals at incident time, three of six questions can be answered: start and end each take one step from the metric, how many requests were affected takes three steps from the log. The remaining three are empty.

The how many requests were affected row shows what the correlation id does: the same answer, 20, takes 1 step instead of 3. Without an id, the notification record cannot say which request it belongs to, so the loan log and metric get scanned separately, and the scan count grows with the service count. Timing questions’ cost never changes, since the metric needs no join. The timeline’s skeleton comes from the cheapest signal, its detail from the most expensive one.

The Telemetry Gap

Three questions cannot be answered by any signal at incident time, and their reasons differ.

Which dependency slowed stays unanswered, because the notification call site writes no trace span. The loan span in the trace store looks slow, but it only says it was waiting; a service’s own slowness cannot be told apart from waiting on a dependency without a child span.

Which members were affected stays unanswered: the member field lives only in the loan record, the slowness only in the notification record. Both stores exist, both fields exist; what’s missing is only the common key — the data was collected, it just cannot be joined.

Was the notification delivered stays unanswered because the delivery result is never written anywhere. All three gaps are the result of a writing decision, closable only at write time, not at read time.

Blamelessness Ties to a Measure

Blamelessness is not etiquette, it is a measure tied to the type of action. The last table compares two analyses of the same incident. The human-driven analysis produced three actions; none returns to code, and in the next similar incident the same three questions stay unanswered. The system-driven analysis’s three actions are each a writing decision; all three returned to code, and all six questions became answerable.

The measure is this: an action has returned to code if it changes the answer to a question in the next similar incident. Its cost is in the first table: steps went from 5 to 8, one step per question closed.

Summary

• The incident’s timeline was built from the three signals this course produces; root-cause analysis and the causal-chain model were built in M21/K05 and are not repeated here.
• At incident time, three of six questions were answered (5 steps), three stayed unanswered; after the actions, all six were answered (8 steps). The timing questions take 1 step under every configuration; the correlation id changed the cost, not the answer: the same number 20 came out in 1 step instead of 3.
• All three gaps are writing decisions: the unwritten trace span hid the dependency, the uncarried id blocked the join between the two stores, and the unrecorded delivery result closed off the question.
• 0 of the human-driven analysis’s 3 actions returned to code, and answered questions stayed at 3; 3 of the system-driven analysis’s 3 returned, and answers rose to 6. The cost is three steps.

Course Wrap-Up

Lesson	Where it sits in the code	Wrapped / uncovered call site	Cost of the wrong setting
telemetry/01 The Three Signals of Observability	all three, same request, same process	metric 6, log 11–12 steps; 5 of 9 attempts unanswered	the metric closes the identity question for good
telemetry/02 Structured Logging	field-based record; id lives in the client helper	11 → 7 steps; id takes the earlier unanswered question to 8	3 of 4 call sites carry the id; one service off the map
telemetry/03 Metric Types	counter, gauge, histogram at the call site	three types, three questions; none answers another	gauge saw 20 of 2000 observations, peak 199 instead of 293
telemetry/04 Distributed Tracing	trace context in one header, crosses process boundary	100 requests → 100 complete traces, 400 linked spans	one context-free call site breaks 100 traces; lowest rate, 0 of 40
telemetry/05 Instrumentation Standards	behind the collector’s interface	collector name: 5 application files → 0	a switch touches 5 files bound, 1 behind the interface
telemetry/06 Correlation	three signals, one id, one event	20 steps / 3 signals → 2 steps / 1 signal	at ratio 0.50, 51 of 100 events stay untraced
service-level/01 Indicator, Objective, and Agreement	exclusion list as a filter array	12 numbers from 1,188,000 records, three definitions, four filters	filter array drift from agreement text splits measured from promised
service-level/02 Golden Signals	saturation as queue depth in the request log	6 event classes; a single signal catches at most 3	error rate reads 0 in traffic collapse; 136 of 162 empty triggers at low traffic
service-level/03 Error Budget	release gate as a single-line condition	a 3,060-bad-request budget over 30 days; floor eats 20.6%	10 releases spent 180.5% of budget; gate overruns fall 2,463 → 471
service-level/04 Alert Design	whether the rule reads cause or symptom	12 rules, 81 alerts; 4 rules, 9 alerts; both catch 4/6 events	67 wasted alerts in the cause-based set, 3.5 per event
service-level/05 Health Endpoints	liveness/readiness split at one condition term	a 25-tick outage: 0 against 4 restarts	misclassification dropped 48 unrelated requests, recovery 0 → 4 ticks
resilience/01 Timeouts	53 lines at the call site, 28 in the wrapper	7 / 0 and 6 / 1	inner limit exceeding outer: 10 of 10 requests orphaned
resilience/02 Retry and Backoff	wrapper 6, middle layer 2, gateway 6 lines	1 of 2 call sites in the body gets retried	three layers open: 1 request becomes 27 calls, 27 deliveries
resilience/03 Circuit Breaker	state key: 2 per dependency, 4 per call site	3 call sites; at threshold 10, 1 breaker never opens	same threshold: calls to dependency 5 → 13; rare path unprotected
resilience/04 Bulkhead Pattern	pool definition 5 lines, one place	2 call sites unchanged; 8 call sites bypass the pool	pool says 4, dependency sees 12; 40 slots binds nothing
resilience/05 Graceful Degradation	schema object: 7 lines at the call site, 12 in the wrapper	6 of 14 call sites wrapped, 2 uncovered	unmarked fallback indistinguishable from a genuinely zero balance
resilience/06 Rate Limiting and Throttling	at the gateway and the service’s middle layer	2 / 6 of 8 path-access pairs; 2 in neither	cap 20 under fixed key, 100,000 under member key
resilience/07 Failure Modes	error identity read from four places	5 of 8 modes in the pattern stack, 3 never seen	zero reaches the call site in 6 of 8 modes, 1 unmarked
resilience/08 Post-Incident Analysis	action returns to code as a new signal, id, span	3 of 6 questions unanswered → 0	0 of the human-driven analysis’s 3 actions return to code

The table is one rule applied nineteen times. A pattern’s effect was measured in Resilience and Reliability; measured here is where that pattern sits in the code and what it skips. The same rule held for signals: their categories were built elsewhere, and what got counted here was how each signal is produced in code and how many steps it takes to answer a question. The third column says almost the same thing on nearly every row — the uncovered spot never shows up in the configuration, only in the source.

The system is now visible and withstands failure: where a request slows down can be traced, indicators turn into decisions, patterns contain the failure, and a timeline can be rebuilt after an outage. Yet no measurement here ever asked one question: what if the request itself is malicious. Every number assumed the caller was not trying to wear the system down; the release itself was never addressed either. M16/K08 Server Security and Going to Production starts with exactly these two questions.