My Backstop Cut the Pump 64 Times. Its Log Says It Never Did.

Last week I finished a post about a weather score in my sump pump system that had read 0.30 since June because nothing ever measured it. At the end I promised myself a cheap, generalizable check:

For every computed field in the status emails, count distinct values over the last 30 days. Anything with a count of one gets flagged.

This week I wrote it. Thirty-day window, 2,987 assessor verdicts, 29 daily digests, 21,449 status lines from the guardian process, 4,253 monitor heartbeats. It flagged eight fields.

Seven were either benign or things I already knew. The eighth is the field that tells me what my safety backstop most recently did.

Twenty-one thousand lines, one value

guardian.last_action    n=21375    always: 'cooling rest expired'

Of 21,449 guardian status lines in that window, 21,375 carry this field, and every one of them says the same thing. So do all 926 lines it wrote in the last twenty-four hours. I widened the query to the whole log, six and a half months, and the picture got worse rather than better:

Now the part that makes this more than a cosmetic complaint. The guardian is a small process that runs every two minutes, independently of my main monitor, with one primary job: if the pump has been drawing power continuously for more than four minutes, cut the relay and hold it off for five minutes. That is the whole reason it exists. I wrote it because I did not want a single long-lived Python process to be the only thing between my basement and a pump running until it burns out.

It has done that job 64 times. The log records each one plainly:

relay OFF: pump exceeded guardian max continuous run

Sixty-four cutoffs. Thirty-two of them in the last thirty days. And the field whose entire purpose is to report the most recent action has reported a cutoff zero times, ever.

It is not dropping the value. It is structurally unable to print it

My first assumption was a lost write, and my first assumption was wrong. The cutoff reason is stored. Here is the function that runs when the pump gets cut:

def force_cooling_rest(state, host, reason):
    set_relay(host, False, reason)
    state["forced_rest_until_wall"] = now_s() + GUARDIAN_FORCED_REST_SECONDS
    state["last_action_taken"] = reason

The reason goes straight into the state file. The problem is what happens next. main() has several branches, each with its own log line and its own early return, and the field only appears in one of them.

Read down the third column. The only log line that carries last_action= sits at the bottom of the function, and the only way to reach it is to not be cutting the pump and to not be in a forced rest. Both of the branches that run while the field holds a cutoff reason return early, and neither prints it.

The forced rest lasts five minutes. The guardian polls every two. So for the two or three polls where the answer is "I just cut the pump because it ran too long," the process writes a different line and leaves. By the time it reaches the line that would tell me, the rest has expired and this has already run:

state["last_action_taken"] = "cooling rest expired"

Worse: the value it does report is usually an action that never happened

Look at the ordering around the rest expiry:

if state.get("forced_rest_until_wall") and rest_remaining <= 0:
    state["forced_rest_until_wall"] = 0
    state["last_action_taken"] = "cooling rest expired"
    if not status["output"] and status["temp_c"] <= SHELLY_TEMP_RESUME_C:
        set_relay(host, True, "guardian cooling rest expired")

The field is set unconditionally. The relay command below it is gated on two conditions. So how often does the guardian actually turn the pump back on after one of its 64 cutoffs?

Fourteen times.

In the other fifty, the gate failed because status["output"] was already true — my main monitor had already reversed the cut and switched the pump back on, which it does through two separate code paths and did 32 times in this window alone. That conflict is the fight I wrote about two weeks ago, the one that cooked the plug past a thermal cutoff it had never touched, and the nesting inversion behind it. I knew about the fight. What I did not know is that the guardian's own status line has been narrating a tidy version of it the whole time: cooling rest expired, as though the rest ran its course and the guardian calmly restored power. Mostly something else restored power, several minutes early, over its objection.

This is the same defect shape I have now hit three times in this system: state recorded on intent rather than on effect. The alert latches that arm themselves whether or not the email sent. The temperature resume check that clears its own flag before testing whether it can act. And now a status field that reports an action taken by a line of code it never reached.

The same structure produced a second bug, and it hides the good lines

The audit also reported the guardian's relay-state field as healthy — four distinct values, plenty of variation. Then I read them.

Two encodings of one boolean, in one field, in one file. The normal line formats it:

output={'ON' if status['output'] else 'OFF'}

The forced-rest line interpolates the raw Python value:

output={status['output']}

All fifty of the dual-encoded lines in the entire log are forced-rest lines. Which means grep "output=OFF" — the obvious query, the one I would type without thinking — silently excludes exactly the fifty lines that describe the moments this system was holding a running pump off. In a fourteen-megabyte log, the most interesting lines in the file are the ones the natural query cannot see, and it returns no error to tell you so.

I went looking for this pattern, as it happens. Two weeks ago I found a reboot table where one numeric code had been printed under two different names after I fixed a decoder, so old and new labels split by date in a way that looked exactly like a real diagnostic lead. I wrote down a rule: log the raw value beside the label, and count on the raw value. I expected to find more of those. This is not one. That one split by time, and checking the commit history would have found it. This one splits by code path, and no amount of git archaeology would have surfaced it. Only counting the distinct values did.

What the check got right, including about itself

A check that only ever confirms your suspicions is not a check, so two of the eight flags are worth reporting as non-findings.

My daily digest's OVERALL field read OK on all 29 days. The three service-status fields read active all 29. Those are single-valued and they are fine: a health field that says OK every day during a month with no outage is doing its job. A flag is a cue to go and check the mechanism, not a verdict.

And that is where the real refinement is. The difference between OVERALL and last_action is not in the data at all — both showed up as one value, n=29 and n=21,375. The difference is that OVERALL can take other values on a reachable path, and last_action cannot. Counting distinct values is the one-line query. The finding is in the second question.

One correction, which is the point of running it on a schedule

The underlying complaint about that assessor does survive, and the audit quantifies it better than my original hand-sample did. Of 2,805 "pumping a lot" verdicts, 1,347 — 48% — report exactly 8 minutes per hour, and 198 report zero, against a busy-threshold of 12 minutes per hour. Nearly half the verdicts fire below the threshold they are nominally about. This morning's line is the clean version:

[2026-09-25 06:50:32] HIGH_INFLOW INFO | 0W 40.3C ON state=NORMAL | Pumping a lot but pump is healthy (0 min/hr)

Zero watts. Zero minutes per hour. Pumping a lot.

None of this was the control loop

Here is what I keep coming back to. The guardian cut the pump 64 times, and as far as I can tell it was right to do so every time. The monitor put it back, and on the occasions I have checked in detail it was usually right about that too. The control logic worked. What failed is the surface a human reads: the field in the email I actually open in the morning cannot describe the event it exists to describe, and the obvious grep excludes the interesting lines.

The framing going around the industry this month is that vision and robotics pilots don't die of model error — there was a conference talk titled almost exactly that last week. I would narrow it one more turn. In my experience it is usually not even the control loop. It is the instrumentation around the control loop. And instrumentation is the one part nobody writes a test for, because the test would have to assert on the contents of a log line, and that feels like testing a comment.

It is not testing a comment. For six months, the only thing standing between me and a burnt-out pump has been reporting its work to me in a string that cannot contain the word it needs.

What I am changing

1. Put the field in every log line, not just the quiet one. Three one-line changes, one per early-return branch. That is the entire fix for the main finding, which is the annoying part — it was always three lines away from being visible.
2. Record actions on effect, not on intent. Move the assignment inside the gate that actually commands the relay. Better still, record both outcomes: rest expired (relay already ON, no action) is the honest string for 50 of those 64 cases, and it is the string that would have shown me the fight without my having to go and join two logs on timestamp.
3. Format the boolean in one place. One helper, used by both log statements. Then grep the archive for the orphaned encoding, because I now know those fifty lines are the forced-rest windows and they are worth reading.
4. Commit the audit and run it weekly. It currently exists as a scratch script, which means next time I will write it again from memory and slightly differently. It goes in the repo, it runs every week, and the flagged list gets saved so that changes in the list are visible — that is how I would have watched the assessor come back to life instead of noticing by accident a month later.
5. Add the second question to the script. For each flagged field, find every assignment in the source and report whether another value is reachable. Half of that is a grep. It is the half that turns a list of quiet fields into a list of defects.

If you run equipment monitoring of any kind, the version of this you can do this afternoon is the first question. Take the status email your system sends you — the one you skim — and for each field in it, count how many distinct values it has actually printed in the last thirty days. Then, for the ones that come back as one, go and read the code and find out whether they can print anything else. A field that reads the same every day might mean a quiet month. It might also mean that the only thing you would ever learn from it is that it is still running.