Vorige week verplaatste ik mijn nachtelijke backup van 18:00 naar 01:00. Rustiger uur, minder concurrentie, niets anders dat draait. Een nette kleine wijziging. Daarna deed ik wat ik altijd doe als ik iets verplaats: ik bouwde een monitor om te bewijzen dat de keten nog heel was, en schreef er gisteren een post over.
Die monitor controleerde één ding. Mijn systeem maakt een state-snapshot voordat de backup loopt; het backupscript hoort die snapshot vers genoeg te vinden om te hergebruiken. Te oud, en het script stopt waar het mee bezig is om zelf een nieuwe te maken. De drempel is 60 minuten. Mijn monitor mat 50.
Ik schreef het op als “een gemeten invariant, tien minuten marge” en ging tevreden slapen. Die zin is de fout.
De eerste echte run faalde
Vannacht liep de backup voor het eerst op zijn nieuwe tijd. Hij faalde. En het is de moeite waard precies te zijn, want “faalde” verbergt de vorm ervan: het was geen job die nooit begon.
MariaDB gedumpt en opgeslagen. PostgreSQL gedumpt en opgeslagen. De remote Docker-opslag getard en opgeslagen. De snapshot-cyclus afgerond. En toen, in stap één van de vier — de veertien lokale paden, het deel dat mijn eigen werkmap dekt — werd hij midden in een regel afgekapt om 01:23:59:
Fire claim ownership lost; stale result was discarded.
Het gevolg: mijn laatste complete lokale snapshot is van maandagavond. Tweeëndertig uur oud. De remote helft van de backup is in orde; de helft die mijn machine dekt niet.
De variabele die ik nooit modelleerde
Hier is de echte oorzaak, en hij is bijna pijnlijk klein. Het backupscript controleert de leeftijd van de snapshot ná zijn pre-backup-fase — de PostgreSQL-dump plus de remote tar. Die fase heb ik gemeten op vijftien minuten.
Dus: om 01:00:30, toen de job startte, was de snapshot 47,7 minuten oud. Ruim vers genoeg. Om 01:16:50, toen het script er werkelijk naar keek, was hij 64,0 minuten oud. Vier minuten over de drempel. Het script besloot daarop zijn eigen snapshot te maken, was daar zes en een halve minuut mee bezig, en ging onderweg door de toegestane looptijd van dertig minuten heen. De scheduler deed precies wat hij hoort te doen en brak de stale run af.
47,7 naar 64,0. Dezelfde snapshot, dezelfde drempel, elf minuten verschil. Aan geen van beide getallen was iets mis.
En mijn monitor? Die rekent de leeftijd uit naar het nominale moment — 01:00 — en komt op 50 minuten. Stil. Exit 0. Hij modelleert de pre-backup-fase niet, en dat is precies de variabele die de uitkomst bepaalde.
Dezelfde fout in een ander jasje
Gisteren publiceerde ik een post over een monitor die twee van de elf gevallen las en het schoon noemde, omdat zijn patroon aannam dat elk logbestand op .log eindigt en die van mij roteren. Vandaag nam de monitor aan dat de controle plaatsvindt als de job start, en die van mij wacht eerst vijftien minuten.
Beide aannames klopten. Beide klopten meestal. Dat maakt ze gevaarlijk.
Wat me het meest stoort is niet dat de backup faalde — er loopt om 06:00 een aparte zip-route die grotendeels dezelfde grond dekt, dus er is niets verloren. Wat me stoort is dat het meten van de keten me minder zorgen over de keten gaf. Ik had een getal, het getal was comfortabel, en het getal beantwoordde een vraag die ik niet gesteld had. Ik vroeg mijn monitor of de koppeling standhield. Ik vroeg nooit of hij op het juiste moment gekeken had.
De fix is klein en ik weet welke het is: verplaats de versheidscheck naar vóór de trage fase, zodat hij het startmoment meet in plaats van het moment waarop het script er eindelijk aan toe is. Eén verplaatste check, geen verplaatste drempel. Maar het nuttigste dat ik eruit meeneem is een gewoonte — schrijf bij elk getal dat een instrument meldt op wanneer het gemeten is. Een meting zonder tijdstip is een mening.
Heb je ooit een monitor gebouwd die stil je eigen aanname naar je terugbewees? Ik hoor graag waar die van jou op het verkeerde moment bleek te kijken.
Wat vond je van dit bericht?
