A Log With No Runs in It
The fix was correct, and its notes said what it would cost. Under a heading called Limit: “file-only failures, including usage caps recorded only in self-logs, may now classify as unknown.” Seventeen minutes after it landed, the next commit was undoing it, because a usage cap recorded only in a self-log had just been classified as unknown.
The medic
A program I call the medic watches my scheduled jobs. When one fails, it collects what the failed run said about itself, sorts the failure into a cause, and picks a remedy: wait, re-run, or page me. Its budget is two re-runs a day per job. After that it gives up and turns red.
The hard part is what a run said about itself. Most jobs print to the system journal, which tags every line with the run that wrote it. Six of mine append instead to their own log file, one file shared by every run they have ever done, and leave the journal only the service manager’s own boilerplate: started, exited with status 1.
On the morning of 9 October one of those jobs, a daily research run, failed three times in nineteen minutes. Each time its log got the same line, three seconds after start:
You've hit your weekly limit · resets 8am (America/Los_Angeles)The medic read the journal, found boilerplate, filed the cause as unknown per none, spent both re-runs into the same limit, and paged me. That afternoon it learned to read the job’s own log file too, to recognize that line, and to hold the re-run until the reset time it names, with the budget untouched.
The reader
Reading a shared append file means answering one question the file cannot: where does this run begin? So the reader guessed. It skipped the file if it had not been modified since the run started. Otherwise it took the last 64 KiB, found the first line stamped at or after the run’s start, and kept everything from there. When no line carried a usable stamp, it kept the tail anyway and put a header above it: no line proves where this run begins, so an earlier run’s lines may precede this run’s.
A review pass by a second model found the hole. A retry that crashed before printing anything with a timestamp still bumped the file’s modified time. The guess then fell back to the tail, and the tail ended in an earlier run’s crash, a Python AttributeError from a different failure. The header warned about exactly this, but nothing downstream read headers. The matcher that sorts failures into causes saw the traceback and matched it. The medic was diagnosing yesterday.
The reviewer’s argument was hard to dispute: neither a modified time nor a line timestamp proves which run wrote the bytes. So the fix stopped reading log files entirely, until something better existed, and wrote down the Limit. It was the conservative move: evidence you cannot attribute is out.
What I had not counted on was that the medic does not get more careful when it knows less. A failure it cannot classify is still a failure, and the remedy for an unclassified failure is a re-run. The research job’s limit line went back to being invisible, the cap wait added that morning could no longer fire, and the medic re-ran the job twice into the limit and paged me again. Removing the doubtful evidence did not make the decision cautious. It made the decision on less, and the default it fell back to was action.
The writer
The real fix moved the question to the only party that knows the answer. Before anything else, each job now writes one line to its log:
aiops-run-start invocation=<id>The id is the one the service manager gives each run and keeps after a one-shot job exits. The reader asks the service manager for the last run’s id, finds that exact marker, and takes the lines after it up to the next marker of any run. A file without a marker stays out, as the reviewer wanted.
Twenty-four minutes later that last clause found two of my own jobs. Neither printed the marker, so the medic again saw only boilerplate, and it had already re-run one of them twice against a problem it could not see. The id was available to every run all along. The log just never had a place to write it.
The research job’s log now opens each run with its own name. The next time it hits the limit, the medic will read the reset time off the line below and wait until 8am.