Active was measuring the wrong thing
My overnight builder thought I was awake from 1 to 7 AM, because the signal it trusted for awake was being touched by something that was not me.
By Andrew Pyle
This one is about a timestamp that answered the wrong question all night.
01Five log lines
The refill kept saying I was there
The worker log had five entries that night, and they all said the same thing. On October 6th the overnight refill set its cap to 1 and gave the reason as operator active. Stripped down to the time and the stamp, the entries read like this:
1:00 AM cap 1, 'operator active'
2:31 AM cap 1, 'operator active'
4:00 AM cap 1, 'operator active'
5:30 AM cap 1, 'operator active'
7:01 AM cap 1, 'operator active'Nobody typed anything at my desk before 7:19 that morning. I was away from the keyboard for every one of those entries.
The refill exists to use exactly those hours. I have an overnight process that proposes parallel work while I am away, and it holds back while I am at the keyboard so it does not pile work on top of mine. A cap of 1 is the held-back setting. So between 1 and 7 AM it proposed no parallel work at all, and each time it checked, it was sure about why.
Nothing crashed. The process ran on schedule and logged a clear reason every time. The reason was false, and nothing in the log looked wrong unless you already knew where I had been.
02A sensible proxy
Fresh files meant I was working
The check that decided I was active was simple. It looked at my interactive session transcripts, and if any of them had a file modification time inside the last 15 minutes, it counted that as me. When I work, I type, and typing writes to the transcript. The timestamp moves because I moved it.
I still think that was a reasonable first version. Reading a modification time is cheap, because the file never has to be opened. It needs no extra tracking. For most of the day the proxy and the truth line up so closely that there is nothing to see between them.
The weakness is in the question the check never asks. It asks whether the file changed. It does not ask who changed it. While I was the only thing writing to those files, that difference did not matter. I do not have a record of how long the rule was in place before this night, so I cannot say how many earlier nights it misread the same way.
03Other writers
Idle sessions kept touching the files
When I looked at the transcripts from that night, the files had in fact changed. I had not changed them. Idle sessions keep appending small metadata lines that carry no timestamp of their own. They also receive task notifications from background work. Each of those writes refreshes the modification time, so a session nobody had used in hours looked as fresh as one I had just closed.
I confirmed it live before changing anything. Two idle sessions showed a modification time of two minutes ago. The newest entry in each that carried a real timestamp was from 3:37 PM the previous day in one case and 7:53 AM in the other. The file said recent. The contents said I had walked away long before.
The bug lived in that gap. Once something other than me could move the signal, a recent modification time stopped meaning I was awake. It inverted, and it reported the opposite of the truth with the same confidence it always had.
04Read the real event
Count only what I actually typed
The new rule keeps the modification time, but only as a cheap prefilter. A file that has not changed inside the window is still skipped without being opened. For a file that passes, the check reads the last 2 megabytes from the end and looks for the newest prompt I typed that carries a timestamp. The tail read is that large on purpose. A long agent turn can bury my last typed prompt under many lines of tool output, and a shorter read would miss it.
Most of the work was deciding what does not count as me. Tool results do not count. Text the system injects into a conversation, such as notifications, reminders and command output, does not count. Lines marked as metadata do not count, and neither does a message that holds anything other than text and images. What is left is a person typing a prompt, which is what I meant to measure in the first place.
The prompt also has to be at or before the moment being checked. For a live check that is automatic, but replays need it spelled out. The test for that case carries the rule in its docstring:
A replay at 3 AM must not see a prompt typed at 9 AM.
Without that limit, a replay would quietly borrow from the future and agree with whatever the morning showed.
With that in place I replayed the real transcripts from the bad night. At 1, 3 and 5 AM the old rule said active and the new one said idle. At 7:25 AM, six minutes after my first real prompt at 7:19, both said active. At 7:45 AM the old rule still said active and the new one said idle, because that prompt had aged out of the 15 minute window. While I was typing, both agreed. Reverting to the old rule turns six tests red, including one where a file is touched by metadata only and has to read as idle.
The fix does not land the instant it merges. The process that runs the check reads from a copy of the code that advances every 15 minutes, and only when crawls allow it. For a check like this that lag is fine. A signal is trustworthy only while the thing it stands for is the only thing that can move it, and I had stopped asking who else could write to those files.
Related
writing
A close that would not stick
I was about to clean up a third of my task board, and the code that filed those rows would have put them all back.
writing
A queue with no backoff floods on every tick
My approval queue filled with the same pull request on every tick, and the thing it kept trying to merge could never merge.
writing
A dry run that spent money
The flag meant to make a rehearsal safe was making paid model calls and writing real rows.
writing
Dead is not asleep
A liveness alarm kept telling me to revive a laptop that was healthy and asleep, until I changed what the alarm counts as dead.
writing
The publishing pipeline that lied to me for four days
A green log, a stale site, and the difference between a job that ran and a job that did the thing.