654M in /var/log and the Evidence Task That Quietly Lied

Adityo Guni WaluyoSeptember 17, 202602:28

A weekly playbook said OK while /var/log grew to 654M: rotated btmp archives, an active file to shrink, and a df pipe that never ran.

#ansible #linux #logrotate

TL;DR

The dashboard caught disk creep my weekly playbook kept missing: years of SSH brute-force attempts had quietly stuffed btmp past 150M. Worse, the evidence task ran df through the command module, which ignores pipes, so it never filtered output. The fix swaps in shell and truncates oversized logs instead of deleting them, keeping sshd writing happily.

My weekly mitigation playbook reported OK every single run. The dashboard disagreed: disk usage on the mail server kept creeping up. One morning I ran du -sh /var/log by hand and it answered 654M. My first guess was journald, since it held 429M. Also wrong: my vacuum cap at 300M was holding fine. That left more than 200M unaccounted for, and it turned out to be btmp.1, a rotated archive worth 108M, plus the active btmp at 47M.

If you don't touch these files often: wtmp records all logins and logouts. The man page notes that login, init and getty maintain it, and none of those programs creates the file, so if it is removed, record-keeping is turned off [4]. last reads it to print login history, most recent first [7]. The role of btmp as the failed-login bucket comes from my own server observation, not the man page. An exposed mail server accumulates SSH brute-force attempts for years, every attempt appending a record, nothing ever cleaning it up.

The Silent Pipe Bug

While building the cleanup tasks I finally looked hard at my evidence task. It ran this every week:

- name: Before/after evidence
  ansible.builtin.command: df -h / | tail -1

The Ansible command module does not process commands through the shell, so the pipe and other metacharacters are just inert arguments [5]. All those weeks, the task had been running plain df -h /, full table, no filter. The output still appeared in the logs, which is exactly why I never suspected it. The docs recommend the shell module when you need metacharacters, and keeping command when you don't, because it's the safer default [5]. The fix was one word: command to shell.

A broken evidence task is dangerous precisely because it looks healthy. Something always printed, so I believed the playbook was checking the disk every week. It never produced the one line I actually needed.

Truncate, Not rm

The cleanup is three tasks in ansible/playbooks/mitigate-disk.yml. A find with a regex collects rotated btmp/wtmp archives. A file loop with state=absent deletes those archives, never the bare active files. Then a shell task runs the size check and empties active files above 50M with a one-liner: a find in /var/log, maxdepth 1, type f, size +50M, matched by a posix-extended regex against the bare btmp and wtmp names, each match handed to the shrink command with size 0.

truncate sets a file to the size you ask; the extra data is gone but the file itself survives [6], with its inode and permissions intact. That's the whole point: sshd keeps its file descriptor and keeps writing, no restart. Delete the file instead, and the running daemon keeps writing to an unlinked inode while new records go nowhere. Record-keeping silently dies, which is exactly the failure mode the man page warns about for wtmp [4].

The result: /var/log went from 654M to 418M, 112M freed, and the second run reported changed=0. That second number is the one I care about most, because it means the playbook is idempotent. The follow-up commit adds a permanent logrotate guard so btmp never gets the chance to swell like this again. The weekly playbook is honest again, and the pipe in the evidence task finally does what I thought it did all along.

The 50M threshold is deliberately loose. It is not a target, it is a "this has gotten out of hand" line before the playbook steps in, and between logrotate and the playbook there is now always one layer that catches it.

One more thing I appreciate about this pattern: the shrink command doesn't ask anything of the processes around it. logrotate keeps its schedule, sshd keeps writing, and the playbook is just a safety net for the week when both of them are on holiday.