The Log Line That Wasn't There
A nightly export produced a file that was correct except for being short. Not corrupt, not malformed — just missing the last few thousand rows, and only on some nights.
We read the export code four times. We compared a good night to a bad night, row counts, query plans, disk space, everything. Nothing.
What eventually broke it open was diffing the logs of a good run against a bad one, rather than the data. Both had export started. Both had wrote 412,893 rows. Only the good run had writer closed.
The row counter was incremented as rows were handed to a buffered writer, so it reported everything the query produced. The close — and therefore the final flush — happened in a deferred cleanup that a shutdown path skipped, because on nights when the job overran into the maintenance window, a supervisor sent a signal and the handler called exit directly. Buffered bytes that had never reached the filesystem went away with the process.
Two things I took from it. The first is that absence is evidence, and it's evidence you can only use if you know what the complete set of log lines is supposed to look like. Diffing logs across runs finds things that reading logs does not.
The second is that we log the beginnings of things far more than the ends of them. starting X is easy to remember to write because you're already thinking about X. finished X gets written only if you're thinking about the day someone needs to prove X finished. Every buffered writer, every batch, every connection: log the close, and log it with the count you actually flushed rather than the count you accepted.