My Health Check Watched the Wrong File

I wrote a rule for my own agents:

Liveness is not usefulness. Artifact age beats PID.

A job that is loaded, looks healthy to the supervisor, and is producing nothing is the failure worth catching. Anyone can detect exit 127.

Then I applied the rule to my own machine and got the wrong answer.

What I saw

Three listener jobs. launchctl lists them. pgrep -f sentinel_listen.py returns a PID. Their log files:

sentinel_listen.log    8103 bytes   mtime 2026-08-11
courtside_listen.log   8127 bytes   mtime 2026-08-11
eye_listen.log         8149 bytes   mtime 2026-08-11

Last written August 11. By my own rule, that is three dead jobs wearing a costume. I had the sentence written.

A word about what these are, so nobody has to guess. They are small Telegram pollers, 148 to 243 lines each. They wait for a message and answer it. They are not the interesting part of anything I build, and the failure below is not a failure of theirs — it is a failure of how I checked them. I am using them as the specimen precisely because they are simple. If a health check cannot get a 148-line polling loop right, it will not get anything harder right either.

What the script actually does

Before publishing that, I opened the thing that writes the file. There are three print() calls in it:

scripts/sentinel_listen.py:120    print("SENTINEL LISTEN: no rail configured ...")
scripts/sentinel_listen.py:128    print("SENTINEL LISTEN: awake, polling every 20s ...")
scripts/sentinel_listen.py:142    print(f"SENTINEL LISTEN error: {type(exc).__name__}: {exc}")

Startup, banner, error. Courtside and eye are the same shape at :144/:152/:175 and :198/:201/:236.

The successful path prints nothing. There is no "still polling" heartbeat. On the normal path it calls getUpdates with a 25-second long-poll, writes a small state file, sleeps 20, and says nothing at all. So a quiet pass is the poll plus 20 seconds, not 20. A caught exception sleeps 30 and then takes that same sleep on the way round. The interval is not uniform across passes.

So silence in that log does not mean the job stopped. The file is only written on startup and on a caught exception, and I was reading its silence as death.

I cannot go further than that, and the reason matters. These three run without -u, so stdout is block-buffered. An exception printed one minute ago could still be sitting in a buffer instead of on disk. An unchanged file does not prove no errors occurred. It proves the file has not been modified. Those are different statements, and the second one is the only one I can support.

The 8103 bytes are an old error storm — one banner and eighty caught exceptions: 76 URLError, 3 timeout, 1 HTTPError. That is what the file records. What it has failed to record since is a question the file cannot answer about itself.

The file that was actually moving

While I was checking whether these jobs were dead, they were writing. I watched all three state files advance. Sentinel, for example:

$ stat -f '%Sm %N' -t '%H:%M:%S' scripts/sentinel_listen_state.json
  11:13:03   sentinel_listen_state.json
$ stat -f '%Sm %N' -t '%H:%M:%S' scripts/sentinel_listen_state.json
  11:15:19   sentinel_listen_state.json

The log had not been touched since August 11 and the state file was seconds old. Both belong to the same listener job, but only one of them was designed to move on ordinary loop iterations — and they live in different directories. I was watching agent_outputs/. The living file was in scripts/.

I picked the artifact that only moves on startup and on failure. The last startup line in that file is from August 11. The process itself came back on September 18, and at the September 22 check, the banner emitted by that restart had not reached the log file on disk.

The better signal is also not proof

Here is where I have to stop myself a second time, because "check the state file instead" is the obvious lesson and it is not quite right either.

This is the end of courtside's loop:

while True:                                           # :153
    try:                                              # :154
        for upd in updates.get("result", []):         # :156  (body elided)
            ...
            STATE_PATH.write_text(json.dumps(state))  # :173  only after a handled message
    except Exception as exc:                          # :174
        print(f"COURTSIDE LISTEN error: {type(exc).__name__}: {exc}")
        time.sleep(30)
    STATE_PATH.write_text(json.dumps(state))          # :177  every pass, either way
    time.sleep(POLL_SECONDS)                          # :178

There are two writes. The one at :173 happens inside the try, after a message is handled. The one at :177 is at loop level, outside the except, so it runs on every pass — including a pass that just caught an exception and slept.

That second write is the one that keeps courtside's timestamp fresh, and eye is built the same way. So for those two, a fresh state mtime proves the loop is turning. It does not prove a poll succeeded, and it cannot tell a good pass from a failed one.

Sentinel is not the same. It has no loop-level write — only :140, inside the try, after getUpdates returns. So sentinel's timestamp is a stronger signal than the other two. It shows that the API call returned parseable JSON and the loop reached its write. It does not separately record API-level success, whether messages arrived, or whether a reply was delivered. An empty successful poll is normal. Three jobs I had been treating as one row are three different write sites.

And the contents are not one story either. I checked all three:

sentinel    offset 0            history 0      13 bytes
courtside   offset 51848716     history 4     545 bytes
eye         offset 63652330     history 8    2988 bytes

I had looked at sentinel, seen {"offset": 0}, and was about to write that all three had never consumed a message. Two of them hold a non-zero saved cursor and a non-empty history. Three jobs that look identical from launchctl are in three different states, and the only reason I know that is that I opened all three instead of one.

Even sentinel's zero is smaller than it looks. It is the saved cursor right now. It is not a history of everything that job has ever done.

What each thing actually establishes

The last two rows are the point. Every signal I have is incidental — something the program happens to leave behind while doing its job. None of them was written to record that the job succeeded. Those are the two I would have to build, and until they exist I am inferring operation from debris.

My rule was an improvement on checking the PID. It was not the end of the ladder. "Artifact age beats PID" needs a harder second question: which operation am I checking, what evidence does that operation emit, and under what conditions does absence of that evidence mean failure?

A newer file is not automatically a better signal. You have to know what causes it to change. A quiet listener with no incoming work needs a different expectation than a queue with messages waiting, and a timestamp cannot tell those apart on its own.

The buffering part, which is real and separate

There is a second thing going on with those files, and it is worth separating from the write semantics. Two properties compound. The successful path barely writes to stdout at all, so the stream produces very little. And because stdout is block-buffered, the few lines it does produce may not reach disk promptly. Either one alone would be survivable. Together they make log silence ambiguous rather than informative.

I had a live example of the second half. These processes restarted on 2026-09-18 and the startup path prints a banner at :128. On September 22 the file still contained exactly one banner, with an mtime of August 11. The September restart ran the print, and the line was nowhere on disk. Either it was waiting in a buffer or it was gone. The result at the end says which.

These three plists run /usr/bin/python3 script.py. Four sibling jobs on the same machine run /usr/bin/python3 -u script.py. When Python's stdout is non-interactive, as it is when these jobs write to a file, it is normally block-buffered. The exact size is a runtime detail rather than a guarantee: Python commonly uses the file's block size and falls back to io.DEFAULT_BUFFER_SIZE, which on this interpreter reports 8192. -u and PYTHONUNBUFFERED=1 disable that buffering for stdout and stderr.

finance    -u   2026-09-22 19:50   52479 bytes
health     -u   2026-09-22 09:22   55759 bytes
kairos     -u   2026-09-22 09:30   55029 bytes
organizer  -u   2026-09-22 09:21   61883 bytes

sentinel   no   2026-08-11 16:52    8103 bytes
courtside  no   2026-08-11 16:52    8127 bytes
eye        no   2026-08-11 16:57    8149 bytes

On September 22, four out of four with the flag had logs that moved that day. Three out of three without it were frozen. That is a seven-job cohort on one machine, not a law of nature, and I am reporting it as what it is.

Both things are true at once: those programs have almost nothing to say, and without -u, the little they do say is not guaranteed to reach disk promptly.

A prediction, dated before I know

Frozen 2026-09-17. The ledger entry also carried my buffering explanation and an ESTABLISHED socket condition; the socket clause was removed by an amendment on 2026-09-17 and the script-name test added on 2026-09-21. This is a summary of the observable part that remains:

Those three logs will still carry mtime 2026-08-11 on 2026-10-01, while the processes are still alive.

Wrong on 2026-10-01 if any of the three logs has an mtime on or after 2026-09-18 while its plist still lacks -u and PYTHONUNBUFFERED, or if any of the three listeners is absent when tested by script name on that date. An intermediate restart is not a falsifier; the prediction is about what is true on the resolution date.

Not by PID. My ledger recorded 86150 / 86156 / 86157. The machine rebooted on 2026-09-18 and they came back as 859 / 860 / 853. On September 21, ps -p 86150,86156,86157 returned no rows. Resolving against those numbers would have written WRONG against a prediction that was still holding at the time.

That is an observation, and it is the only part I am committing to. The buffering account above is my explanation for it, and a correct prediction would not prove the explanation. If the October 1 check fails, I will say so here.

I am not adding -u until then. Changing the launch configuration now would invalidate the observation window I froze for the prediction.

October 1: it failed

By September 25, the logs had changed.

              frozen               Sep 29 snapshot (mtime Sep 25)   Oct 3 reading
sentinel   8103 B  2026-08-11    16276 B  2026-09-25 06:32    65095 B
courtside  8127 B  2026-08-11    16315 B  2026-09-25 20:39    65322 B
eye        8149 B  2026-08-11    16333 B  2026-09-25 21:27    57130 B

The plists still run /usr/bin/python3 script.py, no -u, no PYTHONUNBUFFERED, and their modification times are July 5 and July 11, before the prediction was made. So the launch configuration did not change across the window, and the September 25 log changes satisfy the frozen falsifier retrospectively, even though I failed to run the resolver on October 1. That first falsifier alone makes this WRONG. The process condition was never observed on October 1 itself. Checked later, on October 2 and again on October 3, all three were alive by script name, the same PIDs that started 2026-09-18 06:28:01. Eye's last change was October 2 at 20:20; its Oct 3 number is a reading, not a third move.

The new content is what the write sites said to expect: caught-error lines. As of October 3, sentinel's log holds 673 error lines. 594 are URLError, and 459 of those are this one:

SENTINEL LISTEN error: URLError: <urlopen error [Errno 8] nodename nor servname provided, or not known>

That is a name-resolution failure. The error alone does not tell me whether the name was invalid or whether resolving a valid name failed. Between the frozen sizes and the September 29 snapshot, the files had grown by 8,173, 8,188 and 8,184 bytes. Together with the caught errors and the buffered configuration, those increases are consistent with accumulated output being flushed. I did not trace the writes, so I cannot identify the exact flush count or trigger from these snapshots, and a consistent result does not prove the explanation.

The bet was the part that lost. I bet the logs would sit still until October 1. Enough new error output accumulated that the logs had moved before October 1.

The banner question has an answer too. The sentinel log now has two startup banners. The second is line 82, directly after the 81 lines that were there on August 11, and the only startup these processes have had since August 11 was September 18. That banner is the September 18 startup line. It was not lost. It eventually reached disk. That is consistent with the buffering explanation above. I had a second dated prediction that said the opposite, that the restart's output was destroyed and the file would still be 8103 bytes with one banner on October 5. As of October 3 the file is 65,095 bytes with two banners. It is already not that file, so Monday can only confirm a result that is already visible, unless the file shrinks. Under my own rule it stays pending until then.

One more thing the date did not do. Nobody ran the check on October 1. The resolver is a script. An interim run on September 29 had already reported failing criteria, but no run was recorded on October 1, and the first recorded run after the deadline was October 2 at 23:35 UTC. Writing the falsifier down before the result stops me from moving it afterward. It does not make anyone show up on the day. If you bet on something, put the check on a scheduler, not on your memory.

What to run on yours

# 1. does the process exist
pgrep -fl your_job.py

# 2. what does the log say, and WHEN does your program write to it
stat -f '%Sm %z %N' -t '%Y-%m-%d' /path/to/your_job.log
grep -nE 'print\(|log\.|logger\.' /path/to/your_job.py

# 3. -u as its own argument, not a substring match
plutil -extract ProgramArguments json -o - ~/Library/LaunchAgents/com.you.yourjob.plist

# 4. if you made a dated bet about it, schedule the check
#    (a falsifier nobody runs on the day is a note, not a test)

These are macOS commands. On Linux, stat -c '%y %s %n' and your service manager's unit file do the same jobs.

Step 2 is the one I skipped. Read the write sites before you interpret the file. If the only print() is inside an except block, an old timestamp is not evidence of failure. It is also not evidence of health. It is evidence the file did not change.

What this does not establish

It does not prove these three jobs are healthy. On September 22, state mtimes showed courtside and eye reaching their loop-level write, sentinel getting a parseable response from getUpdates, and two of them holding a non-zero cursor. The October error logs do not re-prove that. What still holds is that I do not have a signal tied to a poll actually succeeding. That is the thing I have to go build.

It does not prove every quiet daemon is fine. It proves that for these three, on this machine, the file I chose could not answer the question I was asking it.

It does not prove -u is the only fix. PYTHONUNBUFFERED=1 would do the same thing.

And it does not prove the buffering story. The October result fits it, including three aggregate growth deltas clustered around 8 KiB, but fitting is not proof. The prediction tested the observation, and the observation was wrong.

The rule needed replacing, not defending. "Artifact age beats PID" got me off the PID and onto a file with no per-poll success record in it. The version I can actually use is longer and worse as a slogan: name the operation, name the evidence it emits, and name the conditions under which its absence is a failure. If I cannot write that third part down, I do not have a health check. I have a file I like looking at.