TT Lab
Blog Get started
Learn Learning paths Courses

Incident Command and Postmortems

Same 5xx, different culprits — align the clocks and build the timeline

Continue in TT Lab

Goal

Align records with different time zones and clocks (two server logs, a load balancer sample, the git deploy record, the flag record, alerts and metrics) to a single reference clock to build a timeline, and determine from data the first error, the suspect changes, the detection delay, and the mitigation time. At the end, separate three services with the same symptom by cause and roll back only what should be rolled back.

Why it matters

If a postmortem's timeline is wrong, the causes and actions built on it are all wrong. And what makes a timeline wrong is usually not a big mistake but a single time zone marker or a single clock that is a few minutes off. During an incident, the same illusion leads to a decision to "roll everything back": rolling back a healthy change is making one more new change, and the real cause stays.

Steps

  1. Unpack the materials with python3 /opt/fixtures/ic/ickit.py open timeline and read /root/ic/timeline/README.txt. Add up the number of lines with a 5xx status code in web-1.log and web-2.log, and write that single number in /root/ic/timeline/answers/errors.txt.
  2. Convert all deploys in deploys.log (git log) and flag changes in flags.log to UTC, and write them oldest first in /root/ic/timeline/answers/changes.tsv, one <utc-time>\t<change-id> per line. The time takes the form 2026-11-04T05:12:03Z; the change id is the first 7 characters of the commit sha for a deploy and flag:<name> for a flag.
  3. Pair requests stamped with the same req id in lb-sample.log (the reference clock) and the two server logs, measure server_time − reference_time in whole seconds for each server, and write it in /root/ic/timeline/answers/skew.txt as two lines, web-1=<seconds> and web-2=<seconds> (+ for a clock that is ahead, − for one that is behind).
  4. Subtract the skew from the previous step to align both servers' 5xx to the reference clock, and write the time of the earliest one (UTC, to the second) and its server in /root/ic/timeline/answers/first-error.txt as two lines, first_error_utc=<time> and host=<server>.
  5. Write the ids of changes that went in within 30 minutes before the first error on the reference clock (including the first error time) in /root/ic/timeline/answers/suspects.txt, one per line.
  6. Write the seconds from the first error on the reference clock to this incident's alert (api-5xx-rate fired in alerts.csv), and the mitigation time defined in the README (start of the minute, UTC), in /root/ic/timeline/answers/phases.txt as two lines, detect_delay_sec=<seconds> and mitigated_utc=<time>.
  7. Running incident ic-error-spike raises the incident. Three services, cart, search, and pay, were deployed one after another today, and all three have had continuous 5xx since around then (records in /srv/spike/; read the README first). For each service, find what started the errors and write only what should be rolled back in /srv/spike/rollback.conf as <service> app=<previous-version> or <service> config=<previous-revision>; do not write services that need no rollback. In /root/incident/ic-error-spike/report.txt, write three lines, cart: <code>, search: <code>, and pay: <code>, and for each service one line of the materials that shows its cause, as evidence-cart: <line>, evidence-search: <line>, and evidence-pay: <line>: the line of the change that caused it, or a dependency metric or timeout line. Also write, for each service, the first 5xx time aligned to the reference clock (the load balancer) as start-cart: <utc-time>, start-search: <utc-time>, and start-pay: <utc-time> (the earlier of the two servers; within ±10 seconds is accepted). Causes are set separately per service, so the same cause may appear more than once. Each service's code is one of the following: bad-deploy (a defect in the new app version), clock-skew (an illusion created by clock skew), config-push (a config deploy), traffic-surge (a request surge), upstream-timeout (downstream dependency latency).

Notes

Unpack the materials: how many 5xx lines

Unpack the materials with python3 /opt/fixtures/ic/ickit.py open timeline and read /root/ic/timeline/README.txt. Add up the number of lines with a 5xx status code in web-1.log and web-2.log, and write that single number in /root/ic/timeline/answers/errors.txt.

The status code is the sixth field of the line. 4xx is not the server's fault, so do not count it.

Changes on one UTC line

Convert all deploys in deploys.log (git log) and flag changes in flags.log to UTC, and write them oldest first in /root/ic/timeline/answers/changes.tsv, one <utc-time>\t<change-id> per line. The time takes the form 2026-11-04T05:12:03Z; the change id is the first 7 characters of the commit sha for a deploy and flag:<name> for a flag.

git's Date is stamped in the committer's time zone (+0900, -0800), newest at the top. GNU date cannot read that form, so use python's strptime("%a %b %d %H:%M:%S %Y %z"). You must sort by instant, not by date text.

How many seconds are the server clocks off

Pair requests stamped with the same req id in lb-sample.log (the reference clock) and the two server logs, measure server_time − reference_time in whole seconds for each server, and write it in /root/ic/timeline/answers/skew.txt as two lines, web-1=<seconds> and web-2=<seconds> (+ for a clock that is ahead, − for one that is behind).

First read the time zone markers (+09:00, Z) and convert to the same instant (epoch seconds), then subtract. A request reaches the server within 1 second after passing the load balancer, so round the median of many pairs.

The first error on the reference clock

Subtract the skew from the previous step to align both servers' 5xx to the reference clock, and write the time of the earliest one (UTC, to the second) and its server in /root/ic/timeline/answers/first-error.txt as two lines, first_error_utc=<time> and host=<server>.

Aligned time = time stamped by the server − that server's skew. Reading the lines of a server whose clock is behind as is makes it look as if errors happened before the deploy.

Narrow down the suspect changes

Write the ids of changes that went in within 30 minutes before the first error on the reference clock (including the first error time) in /root/ic/timeline/answers/suspects.txt, one per line.

Line up the two previous outputs (changes.tsv, first-error.txt). If you set the window from the first error of an unaligned clock, the triggering change is pushed out of the window.

Detection delay and mitigation time

Write the seconds from the first error on the reference clock to this incident's alert (api-5xx-rate fired in alerts.csv), and the mitigation time defined in the README (start of the minute, UTC), in /root/ic/timeline/answers/phases.txt as two lines, detect_delay_sec=<seconds> and mitigated_utc=<time>.

Find the mitigation time from the per-minute error rate in metrics.csv by the definition: after the first minute at 5% or above, the first minute of 5 consecutive minutes below 1%. Be careful not to pick a quiet minute before the incident.

Incident: errors in all three services right after deploys, what to roll back

Running incident ic-error-spike raises the incident. Three services, cart, search, and pay, were deployed one after another today, and all three have had continuous 5xx since around then (records in /srv/spike/; read the README first). For each service, find what started the errors and write only what should be rolled back in /srv/spike/rollback.conf as <service> app=<previous-version> or <service> config=<previous-revision>; do not write services that need no rollback. In /root/incident/ic-error-spike/report.txt, write three lines, cart: <code>, search: <code>, and pay: <code>, and for each service one line of the materials that shows its cause, as evidence-cart: <line>, evidence-search: <line>, and evidence-pay: <line>: the line of the change that caused it, or a dependency metric or timeout line. Also write, for each service, the first 5xx time aligned to the reference clock (the load balancer) as start-cart: <utc-time>, start-search: <utc-time>, and start-pay: <utc-time> (the earlier of the two servers; within ±10 seconds is accepted). Causes are set separately per service, so the same cause may appear more than once. Each service's code is one of the following: bad-deploy (a defect in the new app version), clock-skew (an illusion created by clock skew), config-push (a config deploy), traffic-surge (a request surge), upstream-timeout (downstream dependency latency).

Direction: even with the same symptom, the start pattern differs: does it go in turn from the servers that got the new version, do all servers start at once, or did dependency latency spike first? Do not trust the order before aligning the clocks. Tools: measure each server's skew with lb-sample.log, parse git log's Date with strptime, dep_p99_ms in metrics, and the status code and response time of error lines. Concretely: for each service, align both servers' first 5xx to the reference clock, and set that time side by side with the service's app deploy and config deploy times. If you roll back, it is to the version (revision) just before the change that started the errors.