The monitoring bug that turned out not to be a bug

I spent the last couple of days debugging what looked like a fairly nasty problem in PulseWatch, the dead-man’s-switch monitoring tool I’ve been building.

My inbox was filling up with alerts:

MISSING → OK → MISSING → OK

Overnight, I received 29 of them.

Not ideal behaviour for a product whose job is to reduce monitoring noise.

What I thought was happening

PulseWatch monitors unattended jobs from the outside.

A job sends a simple HTTP request when it starts and another when it completes. PulseWatch stores those runs and a server-side watchdog checks whether a successful run has arrived within the expected interval plus a configurable grace period.

If not, the monitor becomes MISSING.

When a new successful run arrives, it becomes OK again.

The canary I use to test PulseWatch is itself a scheduled GitHub Actions workflow. It is configured to run every 15 minutes. At first I assumed my alert state logic was broken.

I increased the PulseWatch threshold to an hour plus a 30-minute grace period but the flip-flopping continued.

Typical alerts looked like this:

05:10 — MISSING — last success 1h34m ago
05:30 — OK — new successful run
07:00 — MISSING — last success 1h32m ago
07:05 — OK — new successful run
08:35 — MISSING — last success 1h33m ago
08:50 — OK — new successful run

That looked to me to be suspiciously precise.

Following the state transitions

So, what did I do? I got Codex to work tracing the relevant code.

PulseWatch declares a monitor missing when:

now - latest_success > expected_interval + grace_period
With the monitor configured for 60 minutes plus 30 minutes of grace, that gives a 90-minute boundary, so those MISSING alerts were correct.

More importantly, the watchdog cannot recover a monitor by itself. An OK recovery requires PulseWatch to receive a new /success request.

So the state machine wasn't oscillating, something really was sending successful pings after each MISSING alert and that moved the investigation upstream.

Then I looked at GitHub Actions

The canary workflow is configured to run every 15 minutes.

Its actual run history looked more like this:

00:05
00:53
03:35
05:27
07:00
08:45
09:55
11:16
12:12
13:01
14:36

One gap was 2 hours 42 minutes.

Another was 1 hour 52 minutes.

Another was 1 hour 45 minutes.

The interesting part was that the executions GitHub did run were green. The canary itself generally completed in around 10–20 seconds.

There weren't corresponding failed 15-minute runs filling those gaps. The scheduled executions simply weren't happening reliably.

GitHub documents that scheduled Actions can be delayed and, under sufficiently high load, some queued jobs may be dropped.

The smoke alarm wasn't broken

This completely changed my interpretation of the incident. PulseWatch wasn't generating false positives, it was detecting a genuine failure of the system it was monitoring.

Take the 07:00 example; the previous GitHub Actions execution had occurred at approximately 05:27. Nothing successfully ran for the next 90 minutes and so PulseWatch crossed its configured threshold and raised MISSING.

GitHub eventually executed the workflow again at 07:00 which is when the canary sent its success ping...PulseWatch reported recovery exactly as designed.

The more interesting monitoring lesson

This highlighted a failure mode that's easy to overlook, that is logs are excellent at telling you what happened inside a process that ran.

GitHub Actions was similarly quite capable of showing me green ticks for the workflows it executed successfully.

Neither helps much with the more awkward question:

What about the job that never ran at all?

There is no exception. There is no failed execution. There may be no application log. Nothing inside the job can report the failure because the job never started.

That's precisely where an external dead-man's switch becomes useful.

It doesn't ask: