Lab 14: Make Sense of Giant Logs (Time Windows, .gz Files, One Request Across Every File)
0 / 8 steps
The goal
You get 117,000 lines of logs from a one-hour outage, spread over six files, half of them compressed. By the end you will have found when it started, what triggered it, and exactly what happened to one customer who says “checkout failed”, and you’ll have written it up as a five-line timeline. You never open a log in a text editor.
Everything here is fake and runs on your own machine. A short script writes made-up logs into a folder. No real servers, customers or data are involved, and nothing connects to the internet.
Why this lab. The hardest part of most support escalations isn’t the fix. It’s reading several megabytes of logs, working out which lines matter, and turning them into a story someone else can follow. These are the moves that do it: cut a time window, read rotated .gz files without unzipping them, ignore the loud noise, and follow one ID through every file.
Steven’s method at his last job: open the 900 MB log in Notepad, wait, scroll, cry. We’re doing it properly. — Nyx
Before you start. You need Python 3 and a terminal with the usual Linux tools: Linux, macOS, or on Windows WSL or Git Bash. On macOS, type gzcat -f wherever this lab says zcat -f. Make an empty folder, save the script below in it as make_incident.py, then run it. It takes about a second and writes six files into logs/. Everyone gets exactly the same logs, so your numbers will match the ones below.
# StashGrid Lab 14: builds a fake "incident in a box" in ./logs (about 8 MB, takes a few seconds).
# Everything here is made up: no real servers, people or data. Python 3.8+.
import gzip, os, random
from datetime import datetime, timedelta
R = random.Random(1414) # fixed seed, so everyone gets the same logs
DAY = datetime(2026, 10, 9)
def t(h, m, s=0.0): return DAY + timedelta(hours=h, minutes=m, seconds=s)
def iso(d): return d.strftime("%Y-%m-%dT%H:%M:%S.") + "%03dZ" % (d.microsecond // 1000)
def pg(d): return d.strftime("%Y-%m-%d %H:%M:%S.") + "%03d UTC" % (d.microsecond // 1000)
def rid(): return "%016x" % R.getrandbits(64)
def pick(pairs):
x = R.random()
for item, p in pairs:
x -= p
if x < 0: return item
return pairs[-1][0]
DEPLOY, POOL_FULL, ROLLBACK, HEALTHY = t(10, 14, 52), t(10, 16, 41), t(10, 30, 40), t(10, 31, 5)
VICTIM, VICTIM_TIME = "u-48213", t(10, 17, 41.27)
nginx, app, db = [], [], [] # lists of (time, line)
def app_line(d, level, comp, msg): app.append((d, "%s %-5s [%s] %s" % (iso(d), level, comp, msg)))
def nginx_line(d, ip, method, path, status, rt, req, ua="Mozilla/5.0"):
nginx.append((d, '%s %s "%s %s HTTP/1.1" %d %d %.3f req=%s "%s"' % (
iso(d), ip, method, path, status, R.randint(200, 9000), rt, req, ua)))
def request(d, user=None, path=None):
req, user = rid(), user or "u-%05d" % R.randint(10000, 99999)
ip = "10.20.%d.%d" % (R.randint(0, 9), R.randint(2, 250))
method, path = path or pick([(("GET", "/api/products"), .55), (("GET", "/api/cart"), .22),
(("GET", "/api/account/orders"), .12), (("POST", "/api/orders"), .11)])
slow = (DEPLOY < d < ROLLBACK) and path == "/api/account/orders" # the new release's query has no index
dur = min(4.0 + (d - DEPLOY).total_seconds() / 30.0, 30.0) + R.random() if slow else 0
blocked = POOL_FULL < d < HEALTHY and path != "/api/products" and not (slow and R.random() < 0.25)
app_line(d, "INFO", "http", "req=%s user=%s %s %s start" % (req, user, method, path))
if blocked: # no free database connection
e = d + timedelta(seconds=5.0 + R.random() / 50)
app_line(e, "ERROR", "db", "req=%s pool exhausted: timed out after 5000ms waiting for a connection "
"(active=20 idle=0 waiting=%d)" % (req, R.randint(8, 60)))
app_line(e, "INFO", "http", "req=%s %s %s -> 503 in %dms" % (req, method, path, 5000 + R.randint(5, 30)))
nginx_line(e, ip, method, path, 503, (e - d).total_seconds(), req)
return
ms = R.randint(8, 90) + int(dur * 1000)
end = d + timedelta(milliseconds=ms)
if slow:
db.append((end, "%s [%d] LOG: duration: %.3f ms statement: SELECT * FROM orders WHERE customer_email = $1 "
"ORDER BY created_at DESC /* req=%s */" % (pg(end), R.randint(4100, 4300), dur * 1000, req)))
app_line(end, "INFO", "http", "req=%s %s %s -> 200 in %dms" % (req, method, path, ms))
if ms > 10000: # nginx gives up after 10 s, even though the app finishes later
nginx_line(d + timedelta(seconds=10), ip, method, path, 504, 10.0, req)
else:
nginx_line(end, ip, method, path, 200, ms / 1000.0, req)
# an earlier, quieter hour that has already been rotated (access.log.1.gz)
old = []
d = t(9, 0)
while True:
d += timedelta(seconds=R.expovariate(4))
if d >= t(10, 0): break
old.append((d, '%s 10.20.%d.%d "GET /api/products HTTP/1.1" 200 %d %.3f req=%s "Mozilla/5.0"' % (
iso(d), R.randint(0, 9), R.randint(2, 250), R.randint(200, 9000), R.randint(8, 90) / 1000, rid())))
d = t(10, 0)
while True:
d += timedelta(seconds=R.expovariate(9)) # about 9 requests a second
if d >= t(11, 0): break
request(d)
request(t(10, 16, 20.41), VICTIM, ("GET", "/api/account/orders"))
request(VICTIM_TIME, VICTIM, ("POST", "/api/orders"))
for s in range(0, 3600, 10): # load balancer health checks
h = t(10, 0, s + 0.5); nginx_line(h, "10.20.0.1", "GET", "/health", 200, 0.001, rid(), "ELB-HealthChecker/2.0")
for s in range(0, 3600): # loud, harmless background noise
if R.random() < 0.4:
app_line(t(10, 0, s + R.random()), "WARN", "cache", "redis latency %dms above threshold 50ms" % R.randint(51, 70))
if s % 60 == 37:
app_line(t(10, 0, s + R.random()), "ERROR", "mailer", "SMTP 421 4.7.0 rate limited, will retry in 60s")
if s % 300 == 0:
db.append((t(10, 0, s), "%s [61] LOG: checkpoint starting: time" % pg(t(10, 0, s))))
db.append((t(10, 0, s + 2.4), "%s [61] LOG: checkpoint complete" % pg(t(10, 0, s + 2.4))))
app_line(DEPLOY, "INFO", "deploy", "release 2.3.1 rolling out (commit 9f2c1ab: 'show order history on account page')")
app_line(DEPLOY + timedelta(seconds=3), "INFO", "deploy", "server ready version=2.3.1")
app_line(ROLLBACK, "INFO", "deploy", "rollback to 2.3.0 requested by on-call")
app_line(ROLLBACK + timedelta(seconds=12), "INFO", "deploy", "server ready version=2.3.0")
app_line(HEALTHY, "INFO", "db", "pool healthy (active=3 idle=17 waiting=0)")
def write(path, rows, start=None, end=None, gz=False):
rows = sorted(r for r in rows if (start is None or r[0] >= start) and (end is None or r[0] < end))
opener = gzip.open if gz else open
with opener(path, "wt", encoding="utf-8", newline="\n") as f:
f.writelines(line + "\n" for _, line in rows)
os.makedirs("logs", exist_ok=True)
write("logs/access.log.1.gz", old, gz=True)
write("logs/access.log", nginx)
write("logs/app.log.1.gz", app, end=t(10, 30), gz=True) # rotated at 10:30
write("logs/app.log", app, start=t(10, 30))
write("logs/db.log.1.gz", db, end=t(10, 20), gz=True) # rotated at 10:20
write("logs/db.log", db, start=t(10, 20))
print("Done. Your incident is in ./logs")
$ python3 make_incident.py
On Windows without WSL, run python make_incident.py, then use the PowerShell box in step 4.
Steps
01Size up the pile before you search it
List the files and count the lines in each. zcat -f reads a file whether it’s compressed or not, so one loop covers them all.
$ ls -lh logs $ for f in logs/*; do echo "$f $(zcat -f "$f" | wc -l)"; done
You should see six files and 116,776 lines in total. app.log is the current file. app.log.1.gz is the one before it: the logger rotated it at 10:30 and compressed it. A bigger number means older.
Why this matters. Rotation splits one story across files. If you only search app.log, you only see the last half hour.
02Find when it started
Count errors per minute, oldest file first. Cutting each line to its first 16 characters leaves just the date, hour and minute.
$ zcat -f logs/app.log.1.gz logs/app.log | grep ' ERROR ' | cut -c1-16 | uniq -c | head -20
For the first quarter hour you get one error a minute. Then 10:16 jumps to 48, and every minute after that has more than 200. That jump is the start of the outage, as users saw it.
Why this matters. One error a minute before the outage is the normal background. Errors that were already there before the problem started are rarely the cause.
03Cut a time window, then look just before it
Our timestamps are ISO 8601, so they sort as plain text. That means awk can compare them with >= and <. Pull out ten minutes before the jump and hide the busy, routine components.
$ zcat -f logs/app.log.1.gz | awk '$1 >= "2026-10-09T10:10:00" && $1 < "2026-10-09T10:16:47"' | grep -vE '\[(http|cache|mailer)\]'
Two lines stand out just before the errors: a new release, 2.3.1, went out at 10:14:52, “show order history on account page”. The first pool errors follow at 10:16:46.
Now the trap. A lot of guides use sed with a start and end pattern. The database log has a different timestamp format and few lines, so watch what happens:
$ zcat -f logs/db.log.1.gz | sed -n '/10:16:00/,/10:18:00/p' | wc -l $ zcat -f logs/db.log.1.gz | awk '$2 >= "10:16:00" && $2 < "10:18:00"' | wc -l
The sed version prints 0, because no line contains exactly “10:16:00”. The awk version finds 74. Note the $2: this log puts a space between the date and the time, so the time is the second field.
Why this matters. A window that silently comes back empty looks exactly like “nothing happened”. Compare times; don’t match them.
04Read compressed logs without unzipping them
Count slow database queries in the current file, then in the rotated one.
$ grep -c duration logs/db.log $ zgrep -c duration logs/db.log.1.gz $ zgrep -m1 duration logs/db.log.1.gz
The current file has 163, and its first slow query is at 10:20. The compressed file has 160 more, and the first one is at 10:14:56, four seconds after the release. If you had only read db.log, you’d have dated the database trouble six minutes too late.
ripgrep does the same across a whole folder with -z: rg -z duration logs. You might also have heard of igrep (ig). It’s a handy way to browse matches and jump into your editor, but it doesn’t read compressed files. We tested it: plain logs match, .gz files don’t.
Windows PowerShell, no extra tools. Select-String searches plain files. For .gz files, paste this small function once per session, then pipe it into Select-String or Where-Object.
PS> function Read-Gz($Path) { $r = [IO.StreamReader]::new([IO.Compression.GZipStream]::new([IO.File]::OpenRead((Resolve-Path $Path)), [IO.Compression.CompressionMode]::Decompress)); while ($null -ne ($line = $r.ReadLine())) { $line }; $r.Close() } PS> Select-String -Path .\logs\access.log -Pattern 'req=21a50af4487a4bf9' -SimpleMatch PS> Read-Gz .\logs\app.log.1.gz | Select-String 'req=21a50af4487a4bf9' -SimpleMatch PS> (Read-Gz .\logs\app.log.1.gz | Where-Object { $_ -ge '2026-10-09T10:16:00' -and $_ -lt '2026-10-09T10:18:00' }).Count
The last line should print 2440, the same as the Linux version of a two-minute window.
05Find the first error, not the loudest
Group errors by message. Strip the parts that change on every line (the timestamp, the request ID and the numbers) or every line looks unique.
$ zcat -f logs/app.log.1.gz logs/app.log | grep ' ERROR ' | sed -E 's/^[^ ]+ //; s/req=[0-9a-f]+ //; s/[0-9]+/N/g' | sort | uniq -c | sort -rn
Two messages: 3,363 “pool exhausted” errors and 60 mailer errors. The mailer is the once-a-minute background noise from step 2. The app log also has 1,466 cache warnings, spread evenly over the whole hour. None of the three explains the outage on its own. “Pool exhausted” is a symptom: every database connection was busy. The question is why.
The answer is in the database log you read in step 4. After the release, one query, SELECT * FROM orders WHERE customer_email = $1, takes 4 seconds, then 7, then 14, then 30. Twenty connections fill up with it, and everything else has to wait.
Why this matters. The loudest error is usually the last domino. Sort the evidence by time, not by count, and the first domino is the slow query four seconds after the deploy.
06Follow one customer through every file
The ticket says: “Customer u-48213 says checkout failed around 10:18.” Only the first line of each request carries the user ID, so start there.
$ zcat -f logs/app.log.1.gz logs/app.log | grep -F 'user=u-48213'
Three requests. Take the checkout, POST /api/orders at 10:17:41, and follow its request ID through every file, merged into one timeline. The sed in the middle rewrites the database log’s timestamps into the same format as the others, so they sort together.
$ REQ=0a465c60e8d00b9d $ for f in logs/*; do zcat -f "$f" | grep -F "req=$REQ" | sed -E 's/^([0-9-]+) ([0-9:.]+) UTC/\1T\2Z/' | sed "s|^|$(basename "$f") |"; done | sort -k2
The story: her checkout started at 10:17:41, waited five seconds for a database connection, got “pool exhausted”, and nginx sent her a 503. Run it again with REQ=21a50af4487a4bf9. That’s her order-history page at 10:16:20, which took 7.7 seconds and shows up in all three logs, including the slow query itself. The app writes the request ID into a comment on the SQL, which is how the ID reaches the database log. Her third request, at 10:38, worked: by then the release had been rolled back.
A merged timeline is only as good as the servers’ clocks. Lines in the same millisecond can come out in either order, and a server whose clock drifts can put the effect before the cause. Check NTP before you trust the order. — Nyx
07Write the story in five lines
Before you read the answer, write your own timeline with these five labels: trigger, first symptom, user impact, cause, recovery. Each line needs a time and a piece of evidence.
Show our version
- Trigger, 10:14:52: release 2.3.1 goes out (app.log.1.gz, [deploy]).
- First symptom, 10:14:56: a 4-second query on orders by customer email (db.log.1.gz), getting slower every minute.
- User impact, 10:16:46 to 10:31:10: 3,363 requests fail with 503 and 200 time out with 504 (access.log). Product pages keep working.
- Cause: the new order-history query has no index, so it holds database connections for up to 30 seconds and the 20-connection pool runs dry.
- Recovery, 10:30:40 to 10:31:05: on-call rolls back to 2.3.0, and the pool reports healthy 25 seconds later.
Why this matters. Your write-up is what the next person reads, not the logs. It’s the same discipline as reading an incident like an analyst: what you know, when, and how you know it.
08Look the error up properly
Most of what you run is open source, so someone has usually hit your error before. Search the stable part of the message, not the whole line.
- Strip anything that changes per line: timestamps, IDs, hex, counts. “pool exhausted: timed out after 5000ms waiting for a connection (active=20 idle=0 waiting=18)” becomes "timed out" "waiting for a connection".
- Add the name of the library or product that wrote it. The same problem reads differently in each one. HikariCP says “Connection is not available, request timed out after 30000ms”. node-postgres says “timeout exceeded when trying to connect”. PostgreSQL itself says “sorry, too many clients already”.
- Check the project’s own GitHub issues and docs before random forum answers. Match the version you run.
Why this matters. Pasting a whole log line into a search engine matches nothing, because nobody else has your request ID. And never paste customer data, tokens or internal hostnames into a public search box.
What you learned
- zcat -f — read rotated .gz files and current files in one stream, oldest first
- awk '$1 >= "…"' — cut a time window by comparing timestamps, not matching them
- cut -c1-16 | uniq -c — errors per minute shows when it really started
- sed -E 's/[0-9]+/N/g' — strip the variable parts so you can count messages
- One ID, every file — user ID to request ID to a merged timeline, with the timestamps made consistent first
- rg -z — ripgrep reads compressed files; igrep doesn’t
Put it on your resume. Reconstructed a one-hour outage from 117,000 log lines across six files (some compressed) with grep, awk, zcat and Python, and wrote a five-line timeline. Change it to match what you actually did.
Tried it? Tell us
Nova built this lab from Steven’s own support days, and it’s had one full run so far. If a step broke, behaved differently for you, or you know a better way, tell us. Ideas for the next lab are welcome too — no promises on timing.
NextSAML, OIDC and RADIUS in plain English→
Go deeper
- Lab 13: Diagnose DNS in Wireshark — the lab before this one: the same timeline habits, on packets
- Lab 09: Linux log triage — the same habits on your own machine’s system logs
- Reading an incident like an analyst — turning evidence into a timeline someone else can trust
- journalctl cheat sheet — time windows when your logs live in the systemd journal
Original walkthrough. Every command was run on the generated logs on Ubuntu 24.04 (GNU grep 3.11, both mawk and gawk, ripgrep 14.1), and the script and PowerShell commands on Windows 11 with Python 3.13 and Windows PowerShell 5.1. macOS wasn’t tested; use gzcat for zcat. If something doesn’t match what your machine does, tell me and I’ll fix it.