DEV Community

Cover image for I Asked My Journal for 7 Days, It Kept 6 Days 18 Hours
Mustafa ERBAY
Mustafa ERBAY

Posted on Originally published at mustafaerbay.com.tr

I Asked My Journal for 7 Days, It Kept 6 Days 18 Hours

Around noon today I ran journalctl --list-boots on my server to find out when something had changed, and I got a single line: the machine booted on October 23 at 08:50. Odd, because I hadn't touched that server on that date. uptime -s gave me a second answer: October 18, 18:13:28. There are 4 days 14 hours 36 minutes 33 seconds between those two timestamps, and everything that happened in that span — deploys, service restarts, my own mistakes — is missing from the journal.

Chasing those four and a half days, the numbers said something uncomfortable: none of the things I believed controlled my retention actually did. journald's 4 GiB disk budget had never filled. The 128 MiB per-file ceiling had never fired. I wasn't even halfway to the file-count limit. Two things were setting my retention: the fill level of a hash table, and a cleanup script I wrote on June 1 and never opened again. Every number below comes from my own server and from a controlled lab on my own Mac; I've included the measurement commands so you can run the same checks on your own setup.

This is not a sequel to central logging with systemd-journal-remote: there I was discussing retention as a policy while shipping logs to another machine, here I'm measuring who decides retention on a single box.

I probed all three gates

The server runs Ubuntu 24.04 with systemd 255 (255.4-1ubuntu8.18). Apart from the [Journal] header, not a single setting line is uncommented in my journald.conf — everything is at its default. So my retention budget is entirely in the hands of the formulas in the documentation.

The first gate is the disk budget. Ubuntu's man page says this about SystemMaxUse= and SystemKeepFree=: "The first pair defaults to 10% and the second to 15% of the size of the respective file system, but each value is capped to 4G." My root filesystem is 726,958,051,328 bytes, so 10% of it is 67.7 GiB — but it gets clamped to 4 GiB. My budget is 4 GiB.

# how much of the budget am I using?
journalctl --disk-usage
# Archived and active journals take up 966.9M in the file system.

df -B1 --output=target,size,used,avail /var/log/journal
# /                726958051328   384234774528   342706499584
Enter fullscreen mode Exit fullscreen mode

966.9 MiB, which is 23.6% of the 4096 MiB budget. Since the budget isn't full, journald deletes nothing. The subtle part is that this budget isn't a fixed number: the limit journald actually enforces is recomputed every 30 seconds from the currently available space (journald-server.c, cache_space_refresh()):

avail = LESS_BY(vfs_avail, metrics->keep_free);
space->limit = CLAMP(vfs_used + avail, metrics->min_use, metrics->max_use);
Enter fullscreen mode Exit fullscreen mode

So if something else fills my disk — Docker images, a Postgres backup — the keep_free reserve (also 15% clamped to 4 GiB) kicks in, the limit drops, and my journal gets shorter without me noticing. Today I have 319 GiB free, so this gate is closed. But a closed gate is a state, not a guarantee.

The second gate is the per-file ceiling. Per the documentation, SystemMaxFileSize= "Defaults to one eighth of the values configured with SystemMaxUse= and RuntimeMaxUse= capped to 128M, so that usually seven rotated journal files are kept as history." One eighth of 4 GiB is 512 MiB, clamped to 128 MiB. So my files should be rotating at 128 MiB. They don't:

ls -l --block-size=1 /var/log/journal/<machine-id>/system@*.journal | head -3
# -rw-r----- 1 root systemd-journal 58720256 Oct 23 21:18 system@...-00065e7b8d19d3b1.journal
# -rw-r----- 1 root systemd-journal 58720256 Oct 24 09:40 system@...-00065e860057bc42.journal
# -rw-r----- 1 root systemd-journal 58720256 Oct 24 22:18 system@...-00065e905dc3b237.journal
Enter fullscreen mode Exit fullscreen mode

The first three are 56 MiB. Across all sixteen archived system files the range comes out at 56 to 72 MiB; even the largest sits at 56.25% of the ceiling. The third gate, the file-count limit (SystemMaxFiles=100), is idle too: there are 41 files in the directory. If all three gates are closed, what is rotating these files, and who deleted October 18–23?

Files rotate before reaching the ceiling, because a hash table fills up

The answer was written in the file header. journalctl --header dumps the internal counters for each journal file, and on an archived file I saw this:

journalctl --header --file /var/log/journal/<machine-id>/system@...-00065e7b8d19d3b1.journal
# State: ARCHIVED
# Data hash table size: 233016
# Rotate suggested: yes
# Entry objects: 88131
# Data objects: 174763
# Data hash table fill: 75.0%
# Disk usage: 51.6M
Enter fullscreen mode Exit fullscreen mode

75.0%. Exactly. That number is a threshold in the systemd source: journal_file_rotate_suggested() in journal-file.c suggests rotating the file the moment the data hash table's fill level passes three quarters. Its comment even says where 75 came from: "Let's check if the hash tables grew over a certain fill level (75%, borrowing this value from Java's hash table implementation), and if so suggest a rotation." The comparison looks like this:

if (le64toh(f->header->n_data) * 4ULL > (le64toh(f->header->data_hash_table_size) / sizeof(HashItem)) * 3ULL) {
Enter fullscreen mode Exit fullscreen mode

The table's size isn't magic either; it is derived from the file ceiling. journal_file_setup_data_hash_table() does this:

/* We estimate that we need 1 hash table entry per 768 bytes
   of journal file and we want to make sure we never get
   beyond 75% fill level. Calculate the hash table size for
   the maximum file size based on these metrics. */

s = (f->metrics.max_size * 4 / 768 / 3) * sizeof(HashItem);
Enter fullscreen mode Exit fullscreen mode

Put 128 MiB into that formula: 134217728 * 4 / 768 / 3 = 233,016. (The s in the code is in bytes, i.e. 16× that; journalctl --header divides by sizeof(HashItem) and prints the bucket count — the 233,016 in my header is the result of that division.) In other words journald sized the table assuming the file would grow to 128 MiB and that each record would take about 768 bytes.

My records don't take 768 bytes. The 56 MiB file holds 174,763 data objects: 336 bytes per object (measured against the file size ls reports, which is the code's own yardstick too), 2.29× denser than the assumption. The rest is arithmetic. The table has max_size/576 buckets, the threshold is three quarters of that, i.e. max_size/768 = 174,762 objects; the file closes once it reaches that count. Pull the file size out of that and you get an identity: bytes per object / 768 = file size / 128 MiB. 336/768 = 0.4375, and 56/128 = 0.4375. My files rotating at 43.75% of the ceiling is not a coincidence — it is the direct consequence of writing records that take half the space the default estimate expects.

Counting all sixteen archived system files, the identity holds one by one: ten files at 56 MiB and 336 bytes per object, five at 64 MiB and 384 bytes, one at 72 MiB and 432 bytes. Those sizes come out so round because of the code too: FILE_SIZE_INCREASE is 8 MiB, so files grow in 8 MiB steps and a file that hits the threshold closes at the nearest step. The data actually written is a little less — the Disk usage line in --header counts allocated blocks and ranges from 51.3 to 60.7 MiB. One thing never moves: all sixteen closed at a data-object count between 174,763 and 174,766, at 75.0% fill. The size varies, the threshold doesn't.

What I call "density" here isn't byte volume, it's vocabulary: what goes into the hash table is unique field=value pairs. Lining up the counters of the four consecutive files I carried into the lab makes this very clear.

File (first record) Records Data objects Fill Size (ls)
Oct 25, 23:27 87,820 174,765 75.0% 56.0M
Oct 26, 11:53 87,314 174,763 75.0% 56.0M
Oct 26, 23:54 88,281 174,766 75.0% 56.0M
Oct 27, 12:10 88,488 174,765 75.0% 56.0M

The record counts differ by more than a thousand; the data-object counts sit within three objects of each other. The threshold is 75% of 233,016, i.e. 174,762 — all four closed on the first write after crossing it. My journal rotates by its vocabulary, not by its volume: a service emitting unique message text, unique PIDs or unique request IDs fills the table fast, while one repeating the same ten lines barely touches it.

Across all sixteen files it becomes even clearer: my older files filled up at around 87,000 records, while the last five hold 101,000–115,000, with the data-object count standing still. So lately my server talks more but says fewer new things; because the same field values repeat, more records fit into each file.

That also explains my rotation cadence: the gaps between the sixteen files' opening timestamps come to 10.8 hours on average, the shortest 6 hours 7 minutes, the longest 12 hours 40 minutes. The expectation behind the documentation's "usually seven rotated journal files are kept as history" is 7 × 128 MiB; what I actually have is 16 archived files, none of which reached 57% of the ceiling.

The real governor was cron

With all three gates closed, something had still deleted October 18–23. I found the culprit on my own machine:

systemctl cat disk-cleanup.service | grep -E "Description|ExecStart"
# Description=Safe disk cleanup (Docker cache, journals, build artifacts)
# ExecStart=/usr/local/sbin/disk-cleanup.sh

grep -n "vacuum-time" /usr/local/sbin/disk-cleanup.sh
# 37:journalctl --vacuum-time=7d 2>&1 | tail -3 || true
Enter fullscreen mode Exit fullscreen mode

My own cleanup script, running every day at 03:30 (plus RandomizedDelaySec=10m). So my retention is set by one line of mine, not by journald's budget — and I had been reading that line as "7 days".

Diagram

A file's age is the age of its first record

The journalctl man page gives --vacuum-time= a single sentence: "removes archived journal files older than the specified timespan". There's a gap inside that sentence: what is the age of a file? Its newest record, or its oldest?

journal-vacuum.c sorts deletion candidates by the realtime field it parses out of their names, and breaks the loop on this condition:

if ((max_retention_usec <= 0 || list[i].realtime >= retention_limit) &&
    (max_use <= 0 || sum <= max_use) &&
    (n_max_files <= 0 || left <= n_max_files))
        break;

r = unlinkat_deallocate(dirfd(d), list[i].filename, 0);
Enter fullscreen mode Exit fullscreen mode

I verified what that last hexadecimal field in the filename means on my own files: the header of ...-00065e7b8d19d3b1.journal says Head realtime timestamp: Fri 2026-10-23 08:50:01 +03 (65e7b8d19d3b1). The very same number. So the unit of decision is the entire file, and the file's age is the age of its first record. If a file's first record lands one minute before the cutoff, the hours of records it holds after the cutoff go with it.

But the filename is only a starting point. Right before the list is built, patch_realtime() runs, and its comment states the intent plainly: "The timestamp was determined by the file name, but let's see if the file might actually be older than the file name suggested..." The function looks at st_ctim, st_atim, st_mtim and the file's creation time, and pulls the key down if any of them is older. So a file can be treated as older than its name says — never newer.

That isn't an abstract detail; it is exactly what happened this morning. The single deletion my script recorded is user-1003@…-00065e775fea5b24.journal, and that hexadecimal number decodes to October 23, 03:51:03 — 10 minutes 50 seconds after the cutoff. The filename rule should have kept that file; it was deleted. The reason shows up on its surviving siblings: in all fourteen user journals, the file's creation time precedes its first record, by between 1.9 and 12.2 hours. Which makes sense: journald opens the new user file the moment the system journal rotates, but that user's first line lands hours later. So for user journals the deletion key can be up to half a day older than the oldest record in the file.

I paid that bill this morning. Today's cleanup called vacuum at 03:40:14, so the cutoff was October 23, 03:40:14. After the vacuum, the oldest record in my journal is October 23, 08:50:01. The 5 hours 9 minutes 47 seconds in between were inside the 7-day window, and they were deleted. What I called "7 days" was, at that moment, 6 days 18 hours 50 minutes 13 seconds.

I counted the cost in the lab

I can't resurrect a file that production already deleted and count what was in it, so I repeated the measurement somewhere controlled: I pulled copies of four consecutive archived files onto my Mac, mounted them into a container with the same systemd version (255.4-1ubuntu8.18), and ran the vacuum against those copies. Nothing was deleted on the live server.

docker run --rm -e TZ=Europe/Istanbul -v "$PWD/slab":/lab ubuntu:24.04 bash -c '
  apt-get update -qq && apt-get install -y -qq systemd tzdata
  CUT=$(date -d "-4 days" +"%Y-%m-%d %H:%M:%S")
  journalctl -D /lab --since "$CUT" -o json --no-pager | wc -l
  journalctl -D /lab --vacuum-time=4d
  journalctl -D /lab --since "$CUT" -o json --no-pager | wc -l'
Enter fullscreen mode Exit fullscreen mode

The cutoff landed on October 26, 13:51:31. The first record of the second deleted file was October 26, 11:53:01 — only 1 hour 58 minutes 30 seconds before the cutoff. Its last record was October 26, 23:54:04. The vacuum deleted it whole:

Deleted archived journal /lab/system@...-00065eb00a93c855.journal (56.7M).
Deleted archived journal /lab/system@...-00065eba751401a0.journal (56.9M).
Vacuuming done, freed 113.6M of archived journals from /lab.
Enter fullscreen mode Exit fullscreen mode

The number of records newer than the cutoff dropped from 249,497 to 176,769: 72,728 records, i.e. 83.29% of the deleted file's contents, went away while sitting inside the window I had asked to keep. The oldest record jumped forward from October 25, 23:27 to October 26, 23:54 — a 24 hour 27 minute jump, of which the part beyond the cutoff line, i.e. the part lost from inside the window, is exactly 10 hours 2 minutes 33 seconds. I asked for 4 days and got 3 days 13 hours 57 minutes.

The size of that loss window is tied directly to file granularity — and granularity is decided by the hash table counted above. So the chain closes like this: because my records are twice as dense as expected, files close before reaching the ceiling; that is 10.8 hours on average on my box; therefore every vacuum can delete up to 12 hours 40 minutes more than I asked for — the worst case in my measurements. On a less chatty server, files stay open for days and the same command takes far more with it.

The evidence itself was truncated

The only place that records what the vacuum deleted is that script's output, and when I wrote the script I put | tail -3 at the end of the line. Today's journal holds these three lines:

disk-cleanup.sh[2746430]: Deleted archived journal .../user-1003@...-00065e775fea5b24.journal (3.5M).
disk-cleanup.sh[2746430]: Vacuuming done, freed 116.8M of archived journals from /var/log/journal/<machine-id>.
disk-cleanup.sh[2746430]: Vacuuming done, freed 0B of archived journals from /run/log/journal.
Enter fullscreen mode Exit fullscreen mode

116.8 MiB was deleted; the only file on record is the 3.5 MiB one. The rest stayed behind tail -3. The script's file date is June 1, 2026; for five months I've been looking at a disk graph and calling it "cleanup is working", and today I learned it is an operation whose deletions I cannot see. This is a cousin of the same defect that showed up in the run where my alert only recognised one word: I build the gate and skip keeping the gate's ledger.

Two of my hypotheses collapsed along the way. First, I assumed journald's rate limiting (default RateLimitBurst=10000 / RateLimitIntervalSec=30s) was dropping messages; I scanned the whole journal and there are zero "Suppressed … messages" lines. Second, I thought --list-boots was reporting the wrong date. I checked the documentation, and the man page says "the timestamps of the first and last message pertaining to the boot" — it never promises a boot time, it reports the first message. The documentation wasn't wrong; my reading was.

If I want the real boot time, the journal carries that too, because the monotonic clock doesn't reset:

journalctl --header --file /var/log/journal/<machine-id>/system.journal | grep -E "Tail (realtime|monotonic)"
# Tail realtime timestamp: Fri 2026-10-30 13:45:30 +03
# Tail monotonic timestamp: 1w 4d 19h 32min 1.876s
Enter fullscreen mode Exit fullscreen mode

Count back 11 days 19 hours 32 minutes 1.876 seconds from 13:45:30: October 18, 18:13:28. The same second uptime -s reports. Even when the boot record is gone, the boot time is still in your hands.

The logs didn't actually vanish — they're somewhere else

I can't ask journalctl about October 21:

journalctl --since "2026-10-21" --until "2026-10-22"
# -- No entries --
Enter fullscreen mode Exit fullscreen mode

But the same lines are still there. Ubuntu's systemd package ships a drop-in at /usr/lib/systemd/journald.conf.d/syslog.conf containing a single setting: ForwardToSyslog=yes. So rsyslog writes the same stream, and its retention policy lives in logrotate: weekly, rotate 4.

grep -am1 "2026-10-21.*Vacuuming done" /var/log/syslog.1
# 2026-10-21T03:33:18.865403+03:00 ... Vacuuming done, freed 127.0M of archived journals from ...
Enter fullscreen mode Exit fullscreen mode

The vacuum record of the day journalctl knows nothing about is sitting there in a plain text file. The oldest syslog.4.gz starts on September 27: 33 days. So my forensic window is 6.8 days in journalctl and 33 days in zgrep. I counted which one I look at, too: five live scripts under /usr/local/sbin call journalctl (excluding .bak snapshots), and none of them opens /var/log/syslog. There's a cost as well: by du, /var/log totals 1.9 GiB — 975 MiB of journal and 367 MiB of the syslog family. (The gap with journalctl --disk-usage's 966.9 MiB is a difference of yardstick: one counts allocated blocks, the other file sizes.) I keep two separate ledgers at once, their lifetimes are decided in different places, and neither knows about the other. (The contents aren't identical; rsyslog's default rule is *.*;auth,authpriv.none, so authentication lines go to the auth.log family. All I verified is that the lines I was looking for are there.)

The window can shrink, and nobody will tell you

The first gate, the budget, is moved by an entirely external variable: free disk space. The limit = CLAMP(vfs_used + (vfs_avail − keep_free), min_use, max_use) expression in cache_space_refresh() says the budget moves with the rest of the disk. My keep_free reserve is, again, 15% clamped to 4 GiB. That gate is dormant today because I have 319 GiB free; what follows is derived, not measured: if free space drops below 4 GiB, the enforced limit approaches current usage and the vacuum starts eating archived files without me touching a single setting. The man page says this is only corrected when the service starts: "If the file system is nearly full and either SystemKeepFree= or RuntimeKeepFree= are violated when systemd-journald is started, the limit will be raised to the percentage that is actually free." So a build job that fills the disk indirectly shortens my log window too.

That makes a "disk full" event doubly expensive: the service breaks, and the records that would explain the breakage are deleted at the same moment. When you sit down to investigate the next day, what's left is the journal of the hours after the incident.

The forensic side bothered me for the same reason. Right after every cleanup my window drops to 6.8 days; a suspected unauthorised access or an unexplained service crash usually surfaces later than that. The good news is that thanks to ForwardToSyslog=yes, the auth.log family lives under the same logrotate policy — auth.log.4.gz goes back to September 27 — roughly five times what journalctl gives me. The bad news is that none of my tooling looks there. If you don't know your retention window, you'll find out on incident day that you can't run the investigation.

Four questions to ask your own setup

After this measurement, these four lines became a habit on any server of mine. None of them changes anything; they're all reads.

# 1) What is the real window? (gap between the oldest record and now)
journalctl -o short-iso --no-pager | sed -n 2p | cut -c1-25; date +%FT%T%z

# 2) Which gate is in charge? How close am I to the budget?
journalctl --disk-usage; ls /var/log/journal/*/ | wc -l

# 3) How long do files live? (the extra window a vacuum can delete)
for f in /var/log/journal/*/system@*.journal; do
  journalctl --header --file "$f" | grep -E "Head realtime|Data hash table fill"
done | paste - -

# 4) Who else is deleting, besides me?
grep -rl "vacuum\|journal" /etc/cron* /usr/local/sbin /etc/systemd/system 2>/dev/null
Enter fullscreen mode Exit fullscreen mode

The fourth question matters most, because in my case the answer was me. My own decisions: I'll drop that tail -3 from the cleanup script and record every deleted file — one line cost me five months of blindness. I'll pick --vacuum-time with file lifetime in mind: if I want 7 days and my files live 12 hours, writing 7 days 12 hours is the only honest option I have. And I'll tie the alert to the symptom rather than the mechanism: "is the oldest record younger than I expect?" gives the right answer without knowing which gate fired.

Using MaxRetentionSec= looks tempting but carries the same trap: it runs through the same condition in journal-vacuum.c, with the same whole-file granularity. Anyone who really wants finer granularity should lower SystemMaxFileSize= — files close more often, the vacuum takes less excess with it, and you pay for it with more files and a bit more index overhead. We make the same trade with the max-size/max-file pair for Docker logs; the difference is that there rotation is decided by a number I wrote, while here it's decided by the fill level of a hash table.

Conclusion

Log retention isn't a setting, it's a race: the budget, the per-file ceiling, the file count, the hash table fill level and an external cleanup command are all queued up to delete the same data, and whichever arrives first defines your window. I had read four of the five gates correctly and never counted the fifth — my own cron line.

The more general lesson I take from this is about measurement: "I keep 7 days" is a statement of intent, not a measurement. The measurement is looking at the oldest record's timestamp and subtracting it from today, and in my case that subtraction came out 5 hours 9 minutes 47 seconds short of my intent. You can read what a system promises you from the documentation; what it does, you only learn by counting.

Official Sources

Top comments (0)