Four days of nothing, and every health check stayed green // hupden

I run a small Go service that tails nginx's access and error logs and writes parsed rows into Postgres. It is about as simple as a service gets: open the file, read lines forever, insert. It ran for weeks without a complaint.

Then I opened the traffic dashboard and the last four days were empty.

Not wrong. Not sparse. Empty — the most recent row in the table was from the 26th, and it was the 30th.

Everything said it was fine

This is the part worth dwelling on, because I checked all of it before I found anything:

docker ps said Up 8 days. No restarts, no unhealthy marker.
The container's own logs were still producing output — a nightly purge job inside the same process was firing on schedule, on time, every night.
There was no error anywhere. Not in the service's logs, not in nginx's, not in Postgres'.
The database connection was alive. The purge job was proving that every 24 hours by deleting old rows successfully.

Every signal I had was a liveness signal, and the process was extremely alive. It just wasn't doing the one thing it exists to do.

What actually happened

nginx's logs are rotated weekly by logrotate. The default rotation does this:

mv access.log access.log.1
# signal nginx to reopen its log files

The rename is the whole story. A rename changes a directory entry, not a file. The inode is untouched, and an open file descriptor refers to the inode — so a process holding access.log open before the rotation is still holding the exact same file afterwards, now reachable at access.log.1. nginx reopens by path and starts writing to a brand new inode. My tailer kept reading the old one.

And the old one is never written to again. Which means my read loop sat at end-of-file, got io.EOF, slept, tried again, got io.EOF, slept, forever.

That is the cruel part: io.EOF is not an error condition for a tailer, it is the normal resting state. A tail spends almost all of its life at EOF waiting for a writer. There is no signal available at the read loop that distinguishes "nothing new yet" from "nothing new ever again." The original code was, in effect:

f, _ := os.Open(path)
f.Seek(0, io.SeekEnd)
// read from f forever

Which is correct until the first rotation, and permanently silent after it.

/proc gave it away

The thing that actually confirmed it was /proc/<pid>/fd, which shows what a running process has open — symlinks from descriptor number to path:

lrwx------ 1 root root 64 Jul 30 18:04 3 -> /var/log/nginx/access.log.1
lrwx------ 1 root root 64 Jul 30 18:04 4 -> /var/log/nginx/error.log.1

Both tailers, pinned to the rotated files, exactly as the theory predicted. If the rotated file had been deleted rather than renamed, the same listing would have shown (deleted) on the end of the path — which is the version of this bug people usually run into, because it also explains "the disk is full but I can't find the file."

The fix has three parts, and two of them are not the obvious one

Reopen on rotation. Detect it by comparing what you hold against what the path now points to:

func rotated(f *os.File, path string) bool {
	open, err := f.Stat()
	if err != nil {
		return true // can't tell what we're holding; reopening is the safe move
	}
	onDisk, err := os.Stat(path)
	if err != nil {
		return false // replacement not in place yet, keep reading what we have
	}
	if !os.SameFile(open, onDisk) {
		return true
	}
	// copytruncate: same inode, contents restarted from zero
	pos, _ := f.Seek(0, io.SeekCurrent)
	return open.Size() < pos
}

os.SameFile compares device and inode, so it catches the rename case. The size check underneath it catches the other rotation style — copytruncate, where the file is copied and then truncated in place. There the inode never changes, so SameFile says everything is fine while your read offset sits far past the new end of a file that restarted at zero. Two different mechanisms, one symptom, and a fix that handles only the first is a fix you get to make twice.

Read from the start after reopening, not from the end. This is the part I nearly got wrong. Seeking to the end on reopen makes the tailer healthy again and permanently abandons whatever landed while it was stalled. What you want on every open is to read from byte zero and skip what you already stored — so ask the database for the newest timestamp it holds and drop everything at or before it. A restart then backfills the gap instead of stepping over it, which is the same code path that recovers from a crash, a redeploy, or a Postgres blip.

Decide what happens when the watermark query fails. This one is the actual trap. My access_logs table has no unique constraint — nothing in the schema would notice a duplicate row. So "read from the start and skip what's already stored" is safe exactly as long as you know what's already stored. If that query errors, replaying the file inserts every line a second time, silently, and now your traffic charts are wrong in a way that looks like a traffic spike.

So a failed lookup has to be distinguishable from an empty table:

func watermark(name string, query func() (time.Time, error)) func() (time.Time, bool) {
	return func() (time.Time, bool) {
		t, err := query()
		if err != nil {
			log.Printf("%s: watermark query failed: %v — skipping catch-up, reading new lines only", name, err)
			return time.Time{}, false
		}
		return t, true
	}
}

On false, the tailer seeks to the end and takes new lines only. That deliberately loses data. It loses it once, in a bounded window, loudly, in preference to duplicating an unbounded amount of it invisibly. Given a choice between a gap and a fabrication, the gap is the one you can still reason about later.

A bug that was hiding behind the first bug

Rewriting the read loop surfaced something that had been wrong the whole time. bufio.Reader.ReadString('\n') returns what it has plus io.EOF when it hits the end mid-line — and a log line being written is exactly that. The old code took the error branch and threw the partial line at the parser, losing whatever came after it.

Now partial lines are held until their newline arrives. With a cap: those lines carry the request URI, the User-Agent and the Referer, all of which are attacker-controlled, in a process that stays up for months. An unterminated line that grows without bound is a memory exhaustion primitive handed to anyone who can make a request. nginx's own header limits mean a line past a megabyte should never exist, so one gets dropped loudly rather than accumulated.

Recovering the four days

The live tailer only ever looks at the current log, so it was never going to go back for the gap — that data was sitting in access.log.1, a file the running service is now specifically designed to stop reading. So the fix also shipped a -sweep flag: ingest one named file with optional time bounds, then exit. The rotated file and the live file are disjoint, so a lower bound was enough to be sure nothing overlapped.

What I actually changed my mind about

Not "handle log rotation" — that's a detail, and if you've written a tailer before you already knew it.

The thing worth keeping is that "still running" and "still working" are different assertions, and almost every health check tests the first one. docker ps, restart policies, uptime graphs, a /healthz that returns 200, a liveness probe that pings the database — the ones I had were green, and the ones I didn't have would have been green too, because every one of them answers a question I wasn't actually asking. The process was healthy. The process was also idle in a way it had no vocabulary to describe, because from inside the read loop nothing had gone wrong.

The check that would have caught this in an hour instead of four days is embarrassingly cheap and asserts output rather than existence:

SELECT max(time) FROM access_logs;

If that's older than a few minutes on a server that gets scanned continuously, something is broken regardless of what any process says about itself. I now treat freshness of the thing produced as the real health check, and everything else as a hint about where to look once it goes red.

There's a nastier corollary. A crash is a good failure: it's loud, it trips your restart policy, it shows up in docker ps as a restart count. This service would have been better off panicking. The failures that cost you days are the ones where the process is fine and only the work has stopped, and those are exactly the failures your uptime monitoring is structurally incapable of seeing.