The postrotate script worked. We had no logs.

The rotation was configured correctly. I want to say that upfront, because the story is worse if it was configured correctly.

The daemon

We’d inherited a C daemon — acquired platform, don’t ask, 2012, everyone involved is now at other companies — that logged by writing to a FILE* it opened at startup. fopen("/var/log/crmld/crmld.log", "a"), store the handle, write to it for the lifetime of the process, close it on shutdown. No syslog, no log library, no rotation awareness built in. Which is fine. That’s how you did it, and there is nothing wrong with it if you wire up rotation correctly.

We wired up rotation. We even tested it.

/var/log/crmld/crmld.log {
    weekly
    rotate 4
    compress
    missingok
    notifempty
    postrotate
        kill -HUP $(cat /var/run/crmld.pid) 2>/dev/null || true
    endscript
}

Signal: correct. Pidfile path: correct. We ran logrotate -df /etc/logrotate.d/crmld in staging, watched the daemon get the SIGHUP, watched its SIGHUP handler close and reopen the log file, watched fresh output appear in the new crmld.log. Everything worked.

Then we deployed to production and forgot about it.

Three months later

The service started throwing errors. Not many — elevated 2XX-to-5XX ratio over about four hours, then it recovered on its own. The kind of anomaly that makes you pull up logs and look for what it was hitting at the time.

tail -f /var/log/crmld/crmld.log. Nothing. Empty file, zero bytes.

The daemon is clearly running — traffic is flowing, health checks pass, the process is there in ps. But crmld.log is empty and its mtime is Monday. It’s Thursday.

ls -lht /var/log/crmld/:

-rw-r--r-- 1 crmld crmld      0 Aug 11 09:01 crmld.log
-rw-r--r-- 1 crmld crmld  4.2M Aug 11 09:01 crmld.log.1.gz
-rw-r--r-- 1 crmld crmld  3.8M Aug  4 09:01 crmld.log.2.gz
-rw-r--r-- 1 crmld crmld  4.1M Jul 28 09:01 crmld.log.3.gz
-rw-r--r-- 1 crmld crmld  3.9M Jul 21 09:01 crmld.log.4.gz

Four weeks of compressed logs, all from before the error window. The current log: empty. The rotation schedule: weekly since deployment. Twelve weeks of production output, not in any of these files.

What was actually happening

The open fd was in /proc. We checked:

ls -l /proc/$(pidof crmld)/fd | grep log

One entry. fd 7, pointing at crmld.log, opened at the daemon’s start date — fourteen weeks prior.

But here’s the thing about logrotate’s default create mode: it doesn’t touch the open file. It renames crmld.log to crmld.log.1, creates a new empty crmld.log, then runs the postrotate. The daemon’s fd still points at the old inode — the one now named crmld.log.1. The daemon never noticed the rename, because rename(2) doesn’t close fds. The daemon kept writing, happily, to what was now crmld.log.1.

The next week, logrotate ran again. crmld.log.1 became crmld.log.2. The new empty crmld.log accumulated nothing (correct postrotate still not working, we’ll get there). crmld.log.2 became crmld.log.3. Then crmld.log.3 became crmld.log.4. Then the week after that, crmld.log.4 hit the rotate 4 limit and was deleted.

The daemon’s entire log output was being written to a file that was getting deleted, four weeks at a time, every Monday morning at 9am. The fd situation is exactly the mirror of the deleted-file disk-full case: here the file wasn’t deleted while the fd was open — the fd kept chasing the file through renames until the file walked off the end of the rotation window and got garbage-collected.

Twelve weeks of production logs, written faithfully, deleted on schedule.

Why the SIGHUP went nowhere

The postrotate was firing. Every week. The signal was just not reaching anything.

The daemon double-forks. This is standard UNIX daemon form — fork once to detach from the session, fork again to ensure you can never reacquire a controlling terminal. The grandparent writes the pidfile and exits. The actual daemon — two forks deep — runs.

This daemon wrote the pidfile before the second fork. So the PID in /var/run/crmld.pid was the grandparent process, which had been dead since deployment day. kill -HUP $(cat /var/run/crmld.pid) sent SIGHUP to a nonexistent PID every week. The 2>/dev/null || true ate the error. logrotate’s exit status was zero. Everything was fine.

We’d tested in staging with the daemon running in the foreground — interactive mode, no double-fork, because that’s how you test things when you’re watching them. The postrotate fired, the foreground process got the signal, reopened its log, worked perfectly. We had tested exactly the wrong process topology.

The fix

The actual fix was two lines in the daemon’s init code: move the pidfile write to after both forks, so it records the PID of the actual running process. Recompile, redeploy, verify:

cat /var/run/crmld.pid         # should match
ps -p $(cat /var/run/crmld.pid) # should show crmld

Then manually force a rotation and check the fd:

logrotate -f /etc/logrotate.d/crmld
ls -l /proc/$(pidof crmld)/fd | grep log
# fd 7 should now point at crmld.log, not crmld.log.1

That’s what it should have looked like after every weekly rotation. We’d never checked.

There is also copytruncate, and I want to explain why it’s the wrong answer here even though it would have worked. copytruncate skips the rename entirely: it copies the current log to crmld.log.1, then truncates crmld.log to zero bytes. The daemon’s fd still points at crmld.log — same inode, same path, never touched — and after the truncate, writes restart from the beginning. No SIGHUP, no pidfile, no ceremony.

The problem is the race window. Between the copy completing and the truncate running, the daemon can write data that ends up in neither file. On a daemon logging a few kilobytes per minute, that window is a theoretical concern. On anything writing fast — a high-traffic service, anything doing per-request structured logging — you will lose data on every rotation, on a schedule, silently. It also copies the entire current log file before rotating, which on a multi-gigabyte log is a heavyweight weekly operation that fires at 9am Monday when you probably have better things for the I/O to be doing.

Use copytruncate for daemons you can’t modify or signal. Fix the pidfile for everything else.

The rant I had to have

Running this daemon under a proper supervision tree would have eliminated the entire problem class. Runit, s6, daemontools: supervised processes don’t double-fork. There’s no point to it — the whole reason UNIX daemons double-fork is to detach from the session and relinquish the controlling terminal, which the supervisor handles for you. The supervisor knows the process PID because it spawned the process. You signal the supervisor, the supervisor signals the service. Pidfiles are unnecessary and therefore absent, and the entire “SIGHUP went to a dead grandparent” class of bugs can’t happen.

The daemon’s author wrote correct UNIX daemon code for 1994. It worked correctly for the process model that existed in 1994, where you daemonized yourself because there was nothing else to do it for you. Twenty years later we plugged it into logrotate’s postrotate mechanism, which expects the pidfile to be authoritative, and nobody checked the assumption.

This is not a rant against the original developer. It’s a rant against treating “this code is old and stable” as the same thing as “this code is correct in the current environment.” It wasn’t wrong before. It was wrong now.

What to verify when you set up log rotation

The configuration that says “this is working” is not the same as the verification that it is. Before you forget about it:

1. Verify the pidfile PID is the actual daemon. cat /var/run/yourdaemon.pid && ps -p $(cat /var/run/yourdaemon.pid). They must agree. If the pidfile PID is dead, the postrotate signal goes nowhere.

2. Force a rotation and check the fd. logrotate -f /etc/logrotate.d/yourdaemon, then ls -l /proc/$(pidof yourdaemon)/fd | grep log. The fd should point at daemon.log, not daemon.log.1. If it still says .1, the SIGHUP handler isn’t reopening the file.

3. Watch the tail after a forced rotation. tail -f /var/log/yourdaemon/daemon.log while writing load. If output stops after a rotation and doesn’t resume, the daemon isn’t following the new file.

4. Check it in production topology, not interactive mode. If the daemon behaves differently when daemonized versus run in the foreground — double-forking, dropping privileges, changing working directories — your staging test has to run the same way or it’s testing the wrong thing.

The weekly logrotate cron ran clean for three months. The daemon wrote clean for three months. The logs were deleted clean for three months. Every component did exactly what it was configured to do.

That’s what makes it hard to catch. Nothing was broken. The integration was broken, and integrations don’t show up in systemctl status or a green health check dashboard or a zero exit code from logrotate.

The error rate spike that kicked this off never repeated. We never found what caused it. The logs that would have told us were rotated into the void on their fourth Monday.