The poller that wasn't stuck

· 12 min read
Contents

alertd is a Go daemon I run on a Fedora desktop: it polls about 27 public sources of Ukrainian air-raid alert data, one goroutine per source, and stores what they return in SQLite. About a day into a run, one of those pollers looked stuck, and I reached for systemctl --user kill -s QUIT alertd.

It is my favourite kind of command: evidence and a fix in one line. SIGQUIT makes the Go runtime print the stack of every goroutine to stderr, which for a systemd service lands in the journal, and then exit with status 2. Restart=always brings the service straight back up. I had a diagnosis to go with it, too. The poller was stuck, and I knew roughly why. Past me was very sure of that "roughly"; he usually is.

I was wrong about the poller, wrong about the why, and wrong about which of two timestamps was lying to me. The command was the only part of the plan that worked, and it worked by taking the rest of the plan apart. Nothing in the daemon was stuck. The clock had been, for the first seconds of a boot, somewhere else.

The status said ok, and one timestamp disagreed#

The 27 sources are public Telegram channel pages, plus a handful of APIs: REST, ArcGIS and a city alert service. alertd runs as a systemd --user service with Restart=always, and chrony keeps the machine's time.

Each source has its own goroutine, and the loop is about as plain as a poller gets. Trimmed to its shape:

for {
	more, err := e.step(ctx, p)   // one Fetch + commit; ALWAYS writes source_health (success or failure)
	wait := jitter(spec.Interval) // interval +-10%
	// on error: backoff or Retry-After, log.Warn("fetch failed", ...)
	select {
	case <-ctx.Done(): return
	case <-time.After(wait):
	}
}

The first step runs at startup, with no wait in front of it. Telegram pages poll every 2 minutes. Two sources poll once a day: an ArcGIS layer I'll call daily source A, whose newest data was a week old and whose staleness limit is 45 days, and a REST API, daily source B, with a 7-day limit.

The question was the dullest one there is: is it running, and is it working? systemctl --user status said active since 17:36:02 EET (15:36:02 UTC), 23 hours ago. alertd status printed its table with all 27 sources ok. The journal had no errors in 24 hours, and the 10-minute rebuild job was on schedule. Every indicator I own was green, which is usually when I start reading the small print.

The small print was the LAST SUCCESS column. Source B: 15:36:02Z, the moment the process started. Fine. Source A: 14:36:16Z, an hour before the process started.

That can't happen in this loop. The first step runs at startup and always writes the health row, success or failure. A row older than the process means the current process never finished a single step for A.

A hang theory with everything except a hang#

There was no log line for A in the whole run: no success, no fetch failed, no poller finished. A hung HTTP request was out, because the client has Timeout: 90 * time.Second, and ss -tnp showed no socket open to the ArcGIS host anyway. I ran A's connector once on its own, into a scratch data directory, and it came back with exit code 0 and 34,634 records. So the source was fine. The daemon had to be the problem. The one part I tested on its own came back fine, which in my experience is the stage where a bug starts to enjoy itself.

Then I found a mechanism, and I liked it a lot. I like a mechanism most in the moment before I check it, and I was standing right in that moment. The database handle runs with SetMaxOpenConns(1), so every goroutine shares one SQLite connection, and the loop's context has no deadline. A goroutine waiting for that connection would wait forever, quietly, with no log line and no socket. The theory had a motive, an opportunity and a weapon. My verdict was that source A was stuck, and that was the moment I reached for SIGQUIT instead of a plain restart: if A really was parked on the connection, its stack in the dump would say so, and the restart would unpark it.

The goroutine dump: 27 pollers, all asleep on schedule#

The os/signal docs list SIGQUIT among the signals that make a Go program "exit with a stack dump". No pprof endpoint, no debugger, no preparation: by default, any Go binary will do it unless it has taken the signal over (with signal.Notify, for one).

The dump held 62 goroutines. Grouped by their top frames, 27 of them were the same stack, runtime.selectgo called from ingest.(*Engine).loop, called from Run.func1: every poller, 4 API sources and 23 Telegram pages, A among them. Each one was in the select from the loop above, waiting on its time.After. Not one goroutine was blocked in database/sql.

So A wasn't waiting for the connection. It was waiting for its next poll, like the other 26, in exactly the place my theory said it wasn't. The weapon had never left the drawer.

Fourteen seconds and exactly one hour#

The restart gave me the next clue for free. Source B succeeded instantly, in under a second. Source A succeeded 14 seconds after start, so 14 seconds is how long A's fetch takes.

Now do the sum: 14:36:02Z plus 14 seconds is 14:36:16Z, A's old LAST SUCCESS to the second. A's timestamp looked exactly like a process that started at 14:36:02Z and finished one fetch. The process, according to B and to systemd, started at 15:36:02Z.

A hung goroutine is untidy. It leaves a row from whenever it stopped, minutes or days back, any number at all. It doesn't leave a gap of exactly one hour. Calendars do that. And I had spent the whole investigation suspecting the timestamp that turned out to be telling the truth.

The RTC still kept summer time#

The journal of the current boot read like a confession, signed on every line. The previous boot had ended at 14:35:37Z: a reboot of the machine, not a restart of the service. The first lines of the new boot:

  • the kernel's rtc_cmos driver: setting system clock to 2026-10-28T17:35:50 UTC. That is the RTC's raw reading, the summer local time (UTC+3) of about 14:35:50Z, 13 seconds after the previous boot ended
  • journald: Realtime clock jumped backwards relative to last journal entry, rotating.
  • chronyd, about four seconds after alertd started: System clock wrong by -3600.513343 seconds
  • systemd-resolved: Clock change detected. Flushing caches.

timedatectl finished the story with RTC in local TZ: yes, and right under it the warning systemd prints in that mode: it "will create various problems with time zone changes and daylight saving time adjustments", and "the RTC time is never updated, it relies on external facilities to maintain it." The RTC, the battery-backed clock on the motherboard, holds local time instead of UTC on this machine. Ukraine left summer time on 2026-10-25. The RTC still held summer local time, and reading it as winter local time put the system clock an hour ahead.

For the record, my composure is intact. It is being held together by the thought that somewhere on this motherboard, a chip still thinks it's summer, and is very sure about it.

Put back in order, the boot went like this. The machine really came up around 14:36Z, but its clock said 15:36Z. alertd started at what it believed was 15:36:02. Source B finished its fetch in under a second, still before chrony noticed, and was stamped 15:36:02Z: an hour in the future. About four seconds in, chrony stepped the clock back an hour. Source A finished at 14 seconds, after the step, and was stamped 14:36:16Z, which was correct. systemd's "23h ago" came from the same bad start time and was an hour short as well.

The timestamp that looked normal was the wrong one. The one that looked impossible was the honest one.

Timers on the monotonic clock, timestamps on the wall clock#

The polling itself never noticed any of this. Go's time package keeps two readings in every time.Now(), and its docs put the rule in one line: "the wall clock is for telling time and the monotonic clock is for measuring time." time.After(d) is a measurement. In the Go 1.26 source it becomes a timer due at runtimeNano() + d, and runtimeNano is the runtime's nanotime(), the monotonic clock. A one-hour step of the wall clock doesn't move it, so the 24-hour waits ran their full length regardless. The timers rode through the step without a line in the journal, right the whole time and not inclined to mention it.

The damage was confined to what alertd wrote down. Stored times are unix seconds from time.Now().Unix(), which is telling time, from the wall clock, so every row written before chrony's step was stamped an hour in the future. B's was still there a day later, because B polls once a day: the ok-looking 15:36:02Z. That one row, next to A's correct one, sent me hunting through the database layer for a stuck wait.

The wrong diagnosis found a real gap#

Later, a review note on the code said that ok in alertd status could hide a stuck source for weeks, and it built that argument on my "A is stuck" claim. Thank you. I said it first, and I was wrong first. My own wrong claim, read back to me in someone else's font, is still just my claim.

The premise was wrong and the conclusion was right, which is the more irritating combination. Before the fix, ok was what was left after never run, failing (3 or more consecutive failures), no data time and stale (newest data older than the source's staleness limit). It meant "fewer than three failures in a row, and the data isn't stale yet". Nothing compared the time of the last attempt with the poll interval. A poller that really had hung, or a daemon that had stopped altogether, would have kept A at ok until its data went stale, against a 45-day limit. The question I had asked, "is it working?", was one the status table had never been built to answer.

overdue: twice the interval plus five minutes#

The fix adds one state, overdue: no attempt for more than twice the poll interval plus 5 minutes. For a Telegram page on a 2-minute interval, that's 9 minutes. For the daily sources, about 48 hours. Sources without an interval, the streams, are never overdue. The rules moved out of the print loop into a pure function, so they can be tested without a database:

// sourceState classifies one source_health row. "overdue" = no attempt for
// 2x the poll interval + 5 min: a hung poller or a stopped daemon, which
// "stale" (data time) would only catch after stale_after_s (up to 45 days).
func sourceState(now time.Time, staleAfter int64, interval, lastTry, lastOK, wm, fails sql.NullInt64) string {
	switch {
	case !lastOK.Valid && !fails.Valid:
		return "never run"
	case fails.Int64 >= 3:
		return "failing"
	case interval.Int64 > 0 && lastTry.Valid &&
		now.Sub(time.Unix(lastTry.Int64, 0)) > 2*time.Duration(interval.Int64)*time.Second+5*time.Minute:
		return "overdue"
	case !wm.Valid:
		return "no data time"
	case staleAfter > 0 && now.Sub(time.Unix(wm.Int64, 0)) > time.Duration(staleAfter)*time.Second:
		return "stale"
	}
	return "ok"
}

overdue sits after failing and before the data-time checks, so a source that has gone quiet shows up within about two days instead of after its data goes stale. The table test has 11 cases. A Telegram source exactly 9 minutes since its last attempt is ok, at 10 minutes it's overdue. A daily source is ok at 30 hours and overdue at 72. A NULL interval and a 0 interval are never overdue.

A test I haven't seen fail is a test I don't trust yet, so I broke the rule on purpose: the overdue case became case false && .... The test failed on exactly the two overdue cases, telegram overdue: got "ok", want "overdue" and cir hung 3 days: got "ok", want "overdue", and on nothing else. With the line restored, it went green.

Then a presence check against real data, without touching the real data. On a backup copy of the database I set A's last_attempt_at to three days ago and ran alertd -data <copy> status. A came back overdue, B came back ok, and the live database never knew.

What still isn't fixed#

The status table still prints LAST SUCCESS, not the last attempt, so an overdue row doesn't say how late it is. You get the word, then you go and look.

The clock isn't fixed either. timedatectl set-local-rtc 0 would keep the RTC in UTC, which is what systemd's own warning asks for. It needs root, so I haven't run it. Until I do, the first boot after a clock change can do all of this again. I'd mark that on a calendar, but this post has left me suspicious of those. This time chrony took the extra hour back out within about four seconds, and now the table has a word for a poller that goes quiet.

Monotonic time came through the whole thing without a scratch. Wall time borrowed an hour it didn't have, paid it back four seconds into alertd's life, and left the receipt in my database. My confidence took longer, and it doesn't have a monotonic clock.

Filed under: go, linux, systemd, debugging

Sources#