Automation Pipeline6 min read

My error monitor kept reporting an outage that had ended three days earlier

I traced a 'same-time-every-day 500 error' alert. The real outage happened exactly once. The rest was the monitor writing its own alerts into the log it scans, then re-scanning them. The same day, a dashboard also contradicted itself: 4/4 but 'waiting'. A field guide to the two ways observability lies to you.

#monitoring#observability#feedback-loop#reality-check#dashboards
Concept diagram: left shows a false alert with a [shorts] prefix accumulating one per day in the log; right shows the real outage happened only once
The number of prefixes equaled the number of days elapsed — that was the proof it was noise.

"The ja channel's perf query fails with a 500 at the same time every day." The Telegram alert arrived three days running, word for word. It's a server-side 500, there's a fallback wired in, and Google's Analytics API throwing an occasional 500 is common — I almost let it go. But one thing snagged. Why the same time every day, and only the ja channel?

A question first. Can your alerting system catch its own alerts as an outage? I had never asked mine that.

First principles: start with the one real number

When I read a metric I force one sentence on it: "What's the one number here that actually means something, and which of the rest are just derivatives?" Three alerts over three days. So did the 500 fire three times? I opened the log in time order.

08-04 18:30  [perf] ja — query failed:<HttpError 500 ... (order kept/fallback)
08-05 18:32  [perf] ja order: ['ddi','zodiac',...] | scores OK
08-06 18:34  [perf] ja order: ['ddi','zodiac',...] | scores OK
08-07 18:30  [perf] ja order: ['ddi','zodiac',...] | scores OK

The real 500 happened exactly once, on 08-04. From 08-05 on, the ja perf query was pulling scores fine. Yet the alert came every day. One signal, four alerts. The real question was: where did the other three come from?

The prefix was growing by one per day

I lined the alert texts up.

08-04  [shorts] [perf] ja — query failed:<HttpError 500 ...
08-05  [shorts] [shorts] [perf] ja — query failed:<HttpError 500 ...
08-06  [shorts] [shorts] [shorts] [perf] ja — query failed:<HttpError 500 ...
08-07  [shorts] [shorts] [shorts] [shorts] [perf] ja — query failed:<HttpError 500 ...

The count of [shorts] prefixes equaled the number of days elapsed. That is not a coincidence. Something was reading yesterday's alert line again today, prepending one more of its own label, and re-emitting it.

The monitor was eating its own tail

Here's how the failure detector (fleet_events) works: it scans the bot logs, picks out new lines with a failure marker (HttpError [45]\d\d, Traceback, etc.), and Telegrams them. The bug was in the combination of two lines.

# fleet_events: print the failures it found to stdout
print("[fleet_events]\n" + body)   # body contains "[shorts] [perf] ja ... HttpError 500"
# autopilot.sh: redirect that stdout into the log it scans
$PY engine/fleet_events.py  >> docs/autopilot.log 2>&1

The monitor wrote its own output to autopilot.log — and that file is the log the monitor scans tomorrow. The next day's scan meets its own HttpError 500 line, matches the failure marker, alerts again, prepends one more label, appends it to the log again. A snake eating its tail. One transient 500 on 08-04 became a perpetual-motion machine.

Let me stop and ask. What would you do? See a 500 alert and go patch your retry logic or fallback — fixing a server problem that doesn't exist? Or count whether the alert is even real first? My hand went to the former at first.

The same day, a dashboard lied too

And in the same session, the self-improvement gate dashboard was showing this row:

repackage flag   aftermath   4 / 4   ○ waiting

4/4 means the threshold is met — so why waiting? Looked like a cheap bug. Tracing it: two different data sources were mixed in one row. "Current (4)" counted long-form videos in the publish list; the "fired" verdict checked whether a completely different file (the repackage-candidates output) existed. And the input the actual gate uses was different again — the count of long-form videos that Analytics has views for (the video published that day isn't aggregated yet, so only 3). So 4/4 was true, "waiting" was correct behavior, and only the display glued the two into one verdict, reading as a contradiction. When current >= threshold but not fired, I split the label to aggregating and the illusion was gone.

Two symptoms, one root

The echo loop and the self-contradicting row look different but are the same disease: the observability tool got entangled with what it observes. One read what it writes; one mixed two sources into a single verdict.

I fixed both at the root.

  • Route the monitor's output to a separate log (docs/monitor.log), not the one it scans. The alerts already persist to Telegram and a history file, so nothing is lost.
  • Belt and suspenders: the scan skips lines bearing its own signature ([label] prefix, the alert header). Safe even if a log reset/rotation makes it re-read old echoes.
  • The dashboard now shows aggregating when "current" and "fired" come from different sources.

The honest part

What I fixed was the false repeated reporting. The 08-04 500 itself is a Google server-side hiccup I can't prevent — the fallback already handled it, and it was never mine to fix. The real danger isn't the 500; it's that when noise rings every day, you stop reading the real alert when it comes. A self-referential alert is automating the boy who cried wolf.

Three things to check in your own pipeline right now:

  1. Is there a path where a monitor's output flows back into that monitor's input (what it scans)? Dump everything into one log file and there almost certainly is.
  2. In a dashboard row, do the "current value" and the "status verdict" come from the same source, or are they just plausibly pasted together?
  3. When you see a repeated alert, have you counted the log in time order to confirm there were as many real events as alerts?

Related: the same day I also wrote up "a metric that looked broken but was correct by design" — about reading the code before trusting the metric. The early notes on building this alerting infra itself are here.

Do one thing now. grep the file your alert script appends to, and the file that same script scans next. If they're the same file, you might be eating your own tail too.

Related