DEV Community

y4u
y4u

Posted on Originally published at uvp.y42u.net

Making the On-Call Night Lighter — Four Things You Set Up for Your 2 A.M. Self

#devops #sre #oncall #logging

2:14 a.m. Ninth reopen.

The same 50 GB log, opened nine times tonight already. Why does investigation turn into opening one file over and over?

The answer has nothing to do with how good you are at this.

Your 2 a.m. self makes worse decisions than your daytime self. That part can't be fixed. What can be fixed is handing that tired brain jobs that have to be constructed on the spot. Most of what helps at night is something you set up during the day.

Four situations that decide how heavy an on-call night feels: the reopens that pile up, rebuilding a search while half asleep, 5xx errors that only happen sometimes, and the thirty seconds before a kernel panic. All four jam on the same single point.

Up front: With UwView Pro, a 47.73 GB log you have already opened reopens in 0.02–0.07 s with line numbers intact, and a saved search can be re-applied as-is (measured on one setup; results vary — details at the end)

1. Are you reopening the same log ten times a day?

Situation

You're mid-incident. Open the 50 GB application log, narrow down the time window, pull a request ID, and then — to search on that ID — open it again.

Two minutes each time. Nine times tonight is eighteen minutes. That alone would be survivable. What isn't survivable is switching to another tab during those two minutes and, on returning, having to reconstruct what you were about to check.

Why it happens

Investigation is inherently iterative, and the tools assume you open a file once.

Investigation is hypothesis, check, next hypothesis. It essentially never ends on the first pass. Yet most viewers and editors recount line boundaries on every open, build an index in memory, and throw it away the moment the process exits. The next time you open it — the exact same file — the tool remembers nothing.

The arithmetic is also worse than it looks. A two-minute wait does not cost two minutes. Getting back to the thought you interrupted takes longer than the wait itself. During the day you absorb that difference. At 2 a.m. you don't.

Working around it, and where that stops

The usual approach is to reduce the number of reopens.

less +40000000g app.log                        # jump by line (recounts from the top)
tail -c +53687091200 app.log | head -n 200     # jump by byte offset (line numbers lost)
split -b 2G app.log part_                      # cut it into openable pieces
Enter fullscreen mode Exit fullscreen mode

The second one is fast. Seek by byte and nothing has to be counted.

Three limits. First, seeking by byte throws away the line number. A colleague asks "which line?" and you can't answer; the report can't cite it either. You end up trading speed against coordinates.

Second, splitting breaks the mapping to the original. Line 12,043 of part_ac is which line of the original? It's addition, but it isn't the arithmetic you want to be doing at 2 a.m.

Third, "just keep it open" doesn't survive a long night. You hold the memory for hours, you want a second file open too, and eventually you close the wrong window. And the moment it closes, the two minutes start again.

2. Don't rebuild the search with a tired brain

Situation

You saw these symptoms three weeks ago. Some filter worked back then.

Ctrl-R through shell history. Thirty lines containing grep come back, all vaguely similar, none obviously the one. So you write it again from scratch.

Why it happens

Search conditions are treated as disposable and never saved as an artifact.

The postmortem keeps the conclusion: "upstream connection pool exhaustion." But the searches that got you there are recorded nowhere. They live in individual shell histories, which are neither shared nor pleasant to search.

And that is exactly what bites at night. Composing a filter means holding the shape of the data in your head and writing a regex against it. It is the single worst kind of work to hand a degraded brain.

Working around it, and where that stops

Give the conditions names and carry them around.

# keep these in runbook.sh
check_pool_exhaustion() { grep -nE 'pool (exhausted|timeout)' "$1"; }
check_slow_upstream()   { awk '$NF > 3.0 {print NR": "$0}' "$1"; }
Enter fullscreen mode Exit fullscreen mode

This works well. The moment a filter has a name, it stops being something you remember and becomes something you call.

Three limits. First, you can save the condition but not the result. Every call re-scans 50 GB. It's the same shape as the "third zgrep also takes eight minutes" from Part 8. Watching a known signal means applying the same filter repeatedly — and you pay full price every repetition.

Second, any tweak takes you back outside the function. You want only pool timeout, or a narrower window, or more context lines. Each time you either edit the function or retype it by hand. At night it's the second one.

Third, you can't hand over the narrowed state. At the morning handoff all you can pass is a command string, and whoever receives it starts from a full scan again. If you could pass the filtered result itself rather than the filter, that round trip disappears.

3. 5xx errors that only happen sometimes — pulling them with context

Situation

Thirty million requests a day. Eighty 5xx responses. That's 0.0003%.

Monitoring alerts on error rate, so nothing fires. Your only signal is user reports — "it fails sometimes" — plus eighty lines in a log.

Why it happens

Monitoring looks at aggregates; the log holds individual events.

Round eighty events into a rate and you get 0.0003%. Operationally that is indistinguishable from zero and won't cross any threshold. Eighty users still saw a failure. The aggregate is correct and useless.

Then there's context. The 5xx line itself rarely says why. The upstream timeout just before it, the retry just after, another request in the same second — as Part 2 argued, the cause lives outside the line that matched. With sporadic errors, you need to look at that "outside" eighty times.

Working around it, and where that stops

Extract with context.

awk '$9 ~ /^5/ {print NR": "$0}' access.log | head -100   # line numbers of 5xx
grep -B3 -A3 ' 502 ' access.log > 502_context.txt         # pull with three lines either side
awk '{print $9}' access.log | sort | uniq -c              # status distribution
Enter fullscreen mode Exit fullscreen mode

The second gets you the shape you wanted: an excerpt with surrounding lines.

Three limits. First, -B/-A must be chosen before you look. You find out three lines isn't enough after reading three lines. Rerunning with five reads the whole access log again.

Second, widening the time range escalates fast. "Sometimes" can't be confirmed in a single day; you want thirty. But thirty days is thirty compressed files, and one pass over them costs minutes to tens of minutes.

Third, extracting cuts you off from the original. Something in 502_context.txt looks interesting, and widening it by ten more lines sends you back to the source file. An older article, tracing 5xx errors as one thread, used colour-coding and bookmarks to keep that thread intact — and its precondition was working with the original still open.

4. Reading the thirty seconds before a kernel panic, safely

Situation

The server went down and came back. You want the tail of /var/log/syslog.

Precisely: not the panic itself, but the thirty seconds before it. Something started just before, and that's what you're after. But the tail is cut off mid-line, followed by what looks like a block of NUL bytes.

Why it happens

Log writes still in flight are lost before they're flushed.

Normal log output goes through the page cache on its way to disk. A panic stops the machine, and whatever sat in the cache is gone. The last few kilobytes are missing, or zero-filled by the filesystem. The window you most want to read is in the place most likely to be damaged.

There's a second mismatch: the tail isn't a place you want to address by line count. You want "from thirty seconds before the panic," not "the last 500 lines." As long as log volume varies, those two are not the same range.

Working around it, and where that stops

Work inward from the end.

tail -n 500 /var/log/syslog
tail -c 2000000 /var/log/syslog | strings | less        # salvage the broken tail as text
journalctl -k -b -1 --since "02:13:30" --until "02:14:10"
zcat /var/log/syslog.1.gz | tail -n 200                  # stitch on the previous generation
Enter fullscreen mode Exit fullscreen mode

If the third one works, it's the cleanest — you get to cut by time.

Three limits. First, line boundaries can't be trusted in a damaged tail. tail -n walks backwards counting newlines. Mixed-in NUL padding or binary fragments turn your 500 lines into a few bytes, or into one enormous line.

Second, journalctl can't read a corrupted journal. It's a binary format, and depending on the damage the range query itself won't run. You fall back to the text syslog, which you then have to treat as one file.

Third, you don't want to touch the original. It's the subject of the investigation and possibly evidence in a report; opening it in anything with an edit mode is something to avoid. But stitching on the previous generation means zcat, and that adds gigabytes of temporary files — exactly the storage problem from Part 4.

What all four had in common

Situation What you do at night What you can set up by day What happens if you don't
Nine reopens Rebuild the index every open Persist the index Two-minute waits fragment your thinking
Rebuilding the filter Dig through memory and shell history Give filters and results names You can't reproduce yesterday's search
Sporadic 5xx Rerun grep with different -B/-A Be able to widen context afterwards Every check costs another full read
Thirty seconds before panic Poke at a broken tail with tail A way to open the original unmodified Preservation and readability conflict

Read the third column downwards and it resolves. Every one of them is about carrying state forward. The night is heavy not because you're slow, but because the tools start from zero every time. The index dies with the process, the filter sinks into history, the excerpt is severed from the original. Each single instance is cheap; in work that repeats, it multiplies.

Three things worth carrying forward.

  • The index, until the next open. For the same file, the second open should be able to use what the first one produced. If reopening costs under a second, opening nine times stops being a problem. The problem was nine waits, not nine opens.
  • Filters and their results, with names. Hand over only the filter and the recipient restarts from a full scan. Hand over the narrowed state and the morning handoff becomes "look at this."
  • Position and context on the original, unmodified. The moment you cut an excerpt, the mapping back is gone. If you can widen the context inside the original, the excerpt is only needed once, at the very end.

None of the three can be made up for by trying harder at 2 a.m. They're the kind of thing you push into the tool during the day.

Back to the opening: 2:14 a.m., ninth reopen. If the ninth open is instant, it isn't a ninth reopen at all — it's a ninth hypothesis tested. Same count, completely different night.

The tools I use

I build UwView (free), a viewer that displays, scrolls and searches a huge text file from the moment it opens. Indexing runs in the background, and line numbers appear when it completes (most other viewers show only the head until indexing finishes). No splitting: the original stays one file, unmodified. It has no edit mode, which makes opening an incident log a safe operation in itself.

  • Make reopening cheap: UwView Pro persists the index and compression, so every open after the first comes back with line numbers already there (measured at 0.02–0.07 s on a 47.73 GB text file; varies by environment). The "two minutes per open" from section 1 stops accumulating.
  • Carry filters and results forward: search results live in a separate popup you can jump from into the original. Naming and keeping filters is covered in the filter popup article; reopening the same investigation the next morning is in the archive × session restore article.
  • Change the context width afterwards: instead of committing to ±3 before you run, widen it while looking at the results. Section 3's "rerun because three lines wasn't enough" doesn't happen (free version is ±1; variable ±N is Pro).
  • Approach the tail safely: you can move to the end from the moment it opens, so a damaged tail doesn't need trial-and-error with tail. Expanding a previous generation to line it up also leaves the original untouched.

To be straight about it: UwView is not a monitoring tool. No thresholds, no alerts, and it does not compute a 5xx rate. Noticing a sporadic error needs something else; this tool's job starts after you've noticed. It also won't tidy up binary fragments in a broken tail — NUL padding stays NUL padding, and strings is the better fit there. And in the free version you get single-stage search, ±1 context and saving results; multi-stage search, sequence search, variable ±N, and persisting the index and compression are Pro features.

And if a huge log is eating your disk and you want it compressed for storage while staying searchable at speed, give UwView Pro a look — persistent index, compressed-cache search, and ~1/9 storage make both reopening and searching a step faster (all OS, one-time or monthly). For on-call work, where you return to the same file again and again, the more state you can carry forward, the lighter the night gets.

Links

From the developer: A full list of my apps, Kindle books and open-source work lives at GitHub: amru195704.

A note
This article is provided for reference and makes no guarantee of accuracy or completeness. The behaviour of tail, journalctl and grep, the way logs are truncated during a panic, and log-rotation settings all vary by OS, distribution, version and configuration. Measured figures come from one specific environment and are not a promise of the same result elsewhere. Command examples may need adjusting for your environment (GNU vs BSD, shell, and the implementation and version of awk and sed). If you spot an error or something inaccurate, please leave a comment and I'll check and correct it.

Top comments (0)