The log that wrote into nothing for three weeks

The Croplock hub is a single-board computer in a sealed box that never turns off, and its application log is the only record of why the control loop did what it did. In early August the founder asked a simple question — is the exhaust fan thrashing? — and the honest answer turned out to be that nobody could know, because the log had stopped on 12 July and it was now the 2nd of August.

It had not stopped. That is the whole story.

What the file said

The log file on disk was 9,789,440 bytes, its last line was dated 12 July, and its modification time was four seconds past midnight. The process was up, healthy, ticking every minute, and by its own account writing normally. The two facts could not both be true, so we looked at the process’s file descriptor instead of the file:

$ ls -l /proc/307622/fd/1
1 -> /var/log.hdd/croplock/edge.log (deleted)

$ cat /proc/307622/fdinfo/1
pos:    12603444

The descriptor’s write position was 12,603,444, against a file on disk of 9,789,440 bytes. The process had written 2.8 MB since its last restart, all of it into an inode nothing could reach, and it had been doing the equivalent every day since 13 July. When the process eventually exited, the kernel would free that inode and the three weeks would be gone with it.

How a file gets deleted out from under a process

The board’s vendor image keeps /var/log on a small compressed RAM disk — sensible on an SD card, which wears out under constant small writes — and mirrors it to a directory on the real disk, /var/log.hdd, once a night. We knew about the RAM disk. Our own operations rule said, in so many words, long-running writers go to /var/log.hdd, never to /var/log, because zram does not survive a reboot. So the service wrote there.

What the rule did not say is that /var/log.hdd is not a destination. It is the output of a nightly rsync --delete from the RAM disk. Anything on the disk side that differs from the RAM side is replaced — and replacement means a new inode, with the old one unlinked. Our log lived only on the disk side, so every night at midnight rsync saw a file that did not match its source, wrote a fresh copy of the stale RAM-side version over it, and unlinked the file the application was holding open.

systemd had opened that path exactly once, when it set up the service’s standard output. The JVM held the descriptor for its whole life. A write to an unlinked inode succeeds. There is no error, no signal, no log line, because the log line is the thing being lost. The application kept appending into an orphan, and the file at the path kept showing the last night’s stale copy, modification time four seconds past midnight, every single day.

Why every deploy verified green

Our deploy script tails the log within minutes of a restart and confirms the application is writing. It always was. Writes land normally between a restart and the first midnight sync — the file is real, the inode is live, the tail shows fresh lines. The failure begins at 00:00:04 and the check runs at 22:30. A verification that runs minutes after a change cannot see a failure that starts hours later on a schedule, and this one was structurally incapable of catching the bug it most needed to.

We had already had this bug, loudly

In June the same cron job had deleted the directory, not the file. That version was obvious: systemd could not open standard output, the service failed with status 209, crash-looped, and was fixed the next day with a prerequisite unit that recreates the directory before the application starts. The fix was correct. It also taught us that this cron job was hostile to our log, and we responded by making the directory survive rather than by asking what else the job did to what was inside it.

The second failure was the first one a step further in. Same job, same mechanism, but the file instead of its parent — and a missing directory fails loudly while a replaced file fails silently. When a system has bitten you once, the next bite is usually in the same place and quieter.

The check that was written down and never run

Nine days into the outage, a handoff note for an unrelated investigation listed ls -l /proc/$(pgrep -f croplock-edge)/fd/1 as the way to confirm the live log. It is exactly the command that found the bug on day twenty. It was in the document as a tip, not a step, and nobody ran it. A check that exists and is never executed is indistinguishable from no check — we have written that sentence about a different bug before, and evidently needed to write it again.

What we changed

The log moved to /opt/croplock/logs/: the same disk partition, so the no-zram intent holds, and a directory nothing else rewrites. That last clause is the actual fix. “Not on the RAM disk” was necessary and was never sufficient; the question that needed asking was who else writes to this directory, and on this image the answer for anything under /var/log* is ramlog and logrotate.

Rotation gets its own line, because ordinary logrotate is the identical failure in a different costume: it renames the live file and creates a new one, which is an inode swap, which orphans an append descriptor exactly as rsync did. The rotation config uses copytruncate — copy the contents out, truncate the original in place — so a descriptor opened months ago stays valid.

Both were verified on the bench by provoking each failure deliberately: a forced ramlog sync and a forced rotation, then checking that the descriptor and the path still shared an inode and that the file kept growing. And a negative control, because a check that cannot fail is not a check: a rename-and-delete does produce the (deleted) descriptor; copytruncate does not. The change rides in the installer, not as a hand patch on one box, so the next unit gets it from the first boot.

What we would tell someone starting this

• ls -l /proc/<pid>/fd/1 ending in (deleted) means the process is logging into nothing. Put it in the health check, not the handoff note.
• “Persistent” means two things: not on volatile storage, and not somewhere another process rewrites. Ask who else writes to the directory, not only what it is mounted on. findmnt -T answers the first question; ls /etc/cron.daily starts on the second.
• Log rotation must be copytruncate for any long-lived append descriptor. Rename-and-recreate is an inode swap.
• A deploy check that runs minutes after a change cannot see a failure on a nightly schedule. If the failure has a clock, the check needs one too.
• An empty log is a claim about the log, not about the application. When a diagnostic surface goes quiet, verify the surface before concluding the system is quiet.
• The second bite is quieter than the first. After a loud failure, ask what the same mechanism does one level down.

Sources

All figures are from our own bench hub on 2026-08-02: an Orange Pi 5B running the vendor’s image with its ramlog service, /var/log on a 188 MB zram device mirrored nightly to /var/log.hdd on the SD card. Descriptor position and file sizes are from /proc and ls at the time of discovery. The June directory-deletion incident and the August file-replacement incident are both recorded in our bug register; the fix and its two verification paths are in the commit that moved the log. No device performance figures are given, and none are implied.