DEV Community

Cover image for copytruncate: A "Very Small Time Slice" Cost 33,879 Lines
Mustafa ERBAY
Mustafa ERBAY

Posted on Originally published at mustafaerbay.com.tr

copytruncate: A "Very Small Time Slice" Cost 33,879 Lines

At the end of the paragraph describing copytruncate, logrotate's man page leaves a one-sentence warning: "Note that there is a very small time slice between copying the file and truncating it, so some logging data might be lost."

I read that sentence for years. Every time I thought "fine, a few lines" and moved on. Then I sat down and measured it, and that "very small moment" swallowed a tenth of everything written to a 400 MB log file. Not a few lines: 141 thousand of them, in a single rotation.

The genuinely unsettling part is that the lost lines aren't scattered around. They're consecutive. What you lose isn't "a missing record here and there" — it's a hole in your log's timeline. And if it lands in the middle of an incident, you'll read that incident as if it never happened.

Why copytruncate exists

Let's give it its due first, because nobody added this option out of malice.

Classic rotation works like this: you rename the file, then tell the application to reopen it. But renaming on Unix doesn't move anything — the inode stays the same. The application's open file descriptor keeps writing to that same inode as if nothing happened. While you're compressing app.log.1, the app is still writing into it. And if you never signal it, the new app.log stays empty forever.

That's why nginx has USR1 and many daemons have SIGHUP. But some programs don't listen for any signal. A script you wrote yourself, an old Java application, a vendor binary whose source you can't touch — it opens the file once and won't let go until the process dies.

copytruncate exists for exactly that helplessness: it asks nothing of the application. It copies the file, then shrinks the original to zero. The app's descriptor stays on the same inode, the file is now empty, and it keeps writing. An elegant trick. The problem is what the trick costs — and part of that cost is visible on the disk: while the copy runs, two copies of the log sit there at once. For a 400 MB file that means 800 MB at rotation time. On a server that's already tight, the rotation itself can trigger the disk-full crisis.

The measurement rig

To measure the claim you need a deterministic writer: one that knows how many lines it wrote and can tell you which line went missing. The simplest version writes sequence numbers. In the first three experiments the log starts from an empty file; the effect of size gets its own measurement further down.

The whole rig lives inside a throwaway Debian 13 container — no reason to sacrifice my real logs:

distro:    Debian GNU/Linux 13 (trixie)
kernel:    7.0.0-34-generic   (the HOST kernel the container sees — the host runs Ubuntu)
logrotate: 3.22.0
python3:   3.13.5
Enter fullscreen mode Exit fullscreen mode

The writer is ten lines. It opens with O_APPEND and emits increasing integers:

fd = os.open(path, os.O_WRONLY | os.O_CREAT | os.O_APPEND, 0o644)
i = 0
end = time.time() + dur
while time.time() < end:
    i += 1
    os.write(fd, b"%d\n" % i)
    if i % 2000 == 0:
        time.sleep(0.001)   # rein the writer in a little
Enter fullscreen mode Exit fullscreen mode

The logrotate config is as plain as it gets:

/var/log/lab/app.log {
    copytruncate
    rotate 3
    missingok
    notifempty
}
Enter fullscreen mode Exit fullscreen mode

While the writer runs, I force a rotation with logrotate -f. Then I collect every number from app.log.1 and app.log into a set and check which integers between 1 and the maximum are missing. I'm not estimating the loss; I'm counting it.

First measurement: 33,879 lines, and consecutive

The first run:

written (highest sequence) = 2,642,000
found in files             = 2,608,121
lost                       = 33,879
lost range                 = 1,001,090 - 1,034,968
rate                       = 1.28%
Enter fullscreen mode Exit fullscreen mode

Look at those two numbers: 1,034,968 - 1,001,090 + 1 = 33,879. The loss is exactly one uninterrupted block. Not random dropped lines — a slice cut out of the log's timeline.

The mechanism predicts this. After cp reaches the end of the file, the application keeps writing until truncate() is called; those lines never made it into the copy and they live in the original that's about to be emptied. Everything caught in between evaporates.

Picture a midnight incident. The service starts emitting ten thousand error lines a second at 00:00, and the logrotate cron job fires at exactly that moment. Next morning you open the log: the beginning of the error storm isn't there. The problem appears to have started in the middle. Black boxes tend to spend their worst moments quietly.

The loss grows with log size

Everything so far is arguably in the man page. What I actually wanted to know was: what determines the width of that window?

The window is the time between the copy finishing and truncate() being called — not the whole copy. It wasn't instrumented directly; the writer's throughput and the number of lines it lost were both measured, and the window is derived from those two. Dividing lost lines by lines-per-second gives you the duration of the window.

I pre-filled the log to 1, 20, 100 and 400 MB and rotated three times at each size:

Log size Copy duration Write rate (lines/s) Derived window Loss rate
1 MB 0.055 – 0.177 s 393,500 – 413,500 4 – 10 ms 0.11% – 0.25%
20 MB 0.058 – 0.194 s 388,000 – 594,500 9 – 68 ms 0.22% – 1.70%
100 MB 0.147 – 0.237 s 369,345 – 501,520 21 – 118 ms 0.54% – 2.95%
400 MB 0.997 – 2.120 s 299,076 – 417,130 271 – 396 ms 6.78% – 9.91%

The loss percentages are noisy. At 20 MB one run gave 0.22% and another 1.70%; the best run at 100 MB lost less than the worst run at 20 MB. The container shares its disk, the writer's throughput wanders between 299,000 and 594,500 lines per second across runs, and the page cache sometimes makes the copy nearly free.

The derived-window column is free of that noise, because it is normalised against the writer's actual speed in that particular run: 4 milliseconds to 396 milliseconds, moving one way only. In all twelve runs the window came out shorter than the copy duration — truncate follows hard on the heels of the copy, and the gap between them stretches as the file grows.

The loss at the extremes points the same way. At 1 MB the three runs sit between 0.11% and 0.25%. At 400 MB they came in at 6.78%, 9.90% and 9.91% — two of them right up against ten percent.

Rotating more often doesn't reduce total loss

The obvious conclusion from that table looks like: keep the file small, lose less. Write size 20M, rotate twenty times a day, lose two per thousand per rotation instead of 1.7%. That was my first thought too. Then I did the multiplication.

Loss per rotation shrinks, but the number of rotations grows. Here's the total bill for rotating the same 1 GB of log volume, using each size's median run:

Rotation size Rotations per GB Loss per rotation Total loss
1 MB 1024 3,715 ~3,804,000 lines
20 MB 51.2 18,861 ~966,000 lines
100 MB 10.24 35,135 ~360,000 lines
400 MB 2.56 118,422 ~303,000 lines

The direction is the opposite of the intuition. Rotating small and often loses more lines in total — the 1 MB strategy costs twelve times what the 400 MB one does. The reason is visible in the earlier table: the window doesn't grow linearly with file size. Make the file 400 times bigger and the window grows only about forty times, which means every rotation pays a fixed start-up cost, and how many times you pay it starts to matter.

So the argument for keeping files small isn't the amount you lose. It's the shape of the hole. A single 400 MB rotation opens an uninterrupted gap of a hundred and forty thousand lines, which is more than enough to swallow an entire incident. Twenty small rotations may lose the same total, but they spread it across twenty places and none of them erases one incident end to end.

The choice isn't between losing little and losing a lot; it's between rare deep holes and frequent shallow ones. Which hurts less depends on what you read the log for — shallow and frequent suits incident forensics, low total loss suits counting and metrics. For anyone who wants both there's only one right answer, and that's not to use this path at all.

The second trap: a huge hole at the start of the file

Now for the sneakier one. I removed the O_APPEND flag from my writer and reran the same experiment. That was the only change.

The open(2) man page says this about O_APPEND: "Before each write(2), the file offset is positioned at the end of the file, as if with lseek(2)." And it adds: "The modification of the file offset and the write operation are performed as a single atomic step."

So a process writing with O_APPEND goes to the file's current end before every write. If the file was truncated, its end is zero, and the new line lands at the beginning. All is well.

Without O_APPEND, the process carries its own offset. Truncating the file doesn't change that offset. The application still believes it is "at byte 6,734,895" and writes the next line there. That 6.4 MB at the start of the file was never written — the filesystem leaves it sparse, and anyone reading it sees NULs.

That's exactly what the measurement showed:

lost                  = 4,116 lines (0.16%)
app.log apparent size = 19 MB
app.log size on disk  = 12 MB
first 16 bytes:
0000000  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0  \0
Enter fullscreen mode Exit fullscreen mode

A hole of nearly six and a half megabytes. ls -l shows you 19 MB, du says 12 MB, and cat quietly spews six and a half million NULs at the start. If your log shipper tries to read this file it will either decide it's binary and skip it, or dump a pile of control characters into your terminal. This is why your greps start saying "binary file matches".

This run lost fewer lines (0.16% versus 1.28%), but I won't pin that on the absence of O_APPEND: the loss window sits in the same place either way, between the copy and the truncate. A one-run difference of that size falls inside the run-to-run swing you'll see in a moment. What O_APPEND changes isn't how much you lose — it's the state the file ends up in.

logrotate knows about this behaviour too. Its changelog has an entry under 3.9.0 reading "Allow rotation of sparse files with copytruncate", and an as-yet-unreleased fix addresses a unit mismatch in sparse-file detection. Sparse files aren't an incidental side effect of this path — it's a long-standing problem upstream is still chasing.

The create you wrote next to it does nothing

Let me squeeze in a small detail that gets expensive, because I keep seeing it in configs.

People put copytruncate and create 0640 root adm side by side, assuming that's how permissions get set. The man page is unambiguous here: when copytruncate is used, the create option has no effect, because the old log file stays in place. No new file is created, so there are no permissions to assign. The file continues with whatever mode it was opened with.

The result: you believe you tightened permissions, the audit report agrees with you, and the file's mode never changed. Config lines that silently do nothing are more dangerous than ones that do the wrong thing — because nobody suspects them.

Compression can surprise you in the same pairing. logrotate's own changelog lists "fix wrongly skipping copy with copytruncate and compress" under 3.22.0. In other words, getting those two to work together was something upstream had to fix in 2024. If you're on an older distribution release, go look at your logrotate --version.

The right way: rename first, then tell it

For the third experiment I gave my writer a SIGHUP handler — ten lines that close the file and reopen it. I dropped copytruncate from the config and used create with a postrotate script:

/var/log/lab/app.log {
    rotate 3
    missingok
    notifempty
    create 0644 root root
    postrotate
        kill -HUP $(cat /tmp/writer.pid) 2>/dev/null || true
    endscript
}
Enter fullscreen mode Exit fullscreen mode

The result:

written = 2,396,221
found   = 2,396,221
lost    = 0
Enter fullscreen mode Exit fullscreen mode

Zero. Not rounded to zero — actually zero.

The reason is simple: nothing is deleted at any point in this path. During mv the application is still writing to the old inode, but that inode now answers to the name app.log.1 — the lines it writes aren't lost, they stay in the rotated file. When the signal arrives, it opens the new file. Some lines may end up "in the wrong file", but they exist.

nginx's documentation spells out this ordering: "In order to rotate log files, they need to be renamed first. After that USR1 signal should be sent to the master process." The order matters. Reverse it and the application reopens a file whose name hasn't changed yet, and nothing has rotated at all.

Diagram

A third way: let the application do it

There's also a design that never outsources rotation at all, and I think it's the most honest of the three.

PostgreSQL's documentation says this about logging_collector: "The logging collector is designed to never lose messages." Then it doesn't hide the price: under extreme load, if the collector falls behind, server processes can block while trying to send more log messages. The same paragraph describes syslog's opposite preference — it drops messages when it can't write them, so it won't block the rest of the system but it will fail to log some things.

Three philosophies, three different trade-offs:

  • copytruncate: ask nothing of anyone, lose silently.
  • Rename plus signal: ask the application for one thing (listen for a signal), lose nothing.
  • The application's own collector: lose nothing, slow down if you must.

Notice that the first is the only option that picks the "lose" side on its own and doesn't tell you. The other two put the decision in front of you. I arrived at a similar place when I wrote about choosing log levels: in logging infrastructure, the quiet defaults cost more than the noisy ones.

A five-minute check on your own system

The lab is all very nice, but the real question is: am I losing lines right now?

Three commands answer it. First, see which configs chose this path:

ls /etc/logrotate.d/ | wc -l
grep -rl copytruncate /etc/logrotate.d/ /etc/logrotate.conf
Enter fullscreen mode Exit fullscreen mode

Running that on my own CI server was reassuring: out of fourteen configs, exactly one (bootlog) used copytruncate. Distribution packages tend to behave well here; copytruncate usually shows up in hand-written lines, added because "the app wasn't listening for signals, so I put this in". So audit the configs you wrote, not the ones that came with packages.

Second, check whether you have sparse files:

find /var/log -type f -size +1k 2>/dev/null | while read -r f; do
  ap=$(stat -c %s "$f")
  re=$(( $(stat -c %b "$f") * 512 ))
  [ "$ap" -gt "$re" ] && echo "SPARSE: $f apparent=$ap allocated=$re"
done
Enter fullscreen mode Exit fullscreen mode

I owe you a warning here. My first version of this had du -b on both sides of the comparison — and as du --help states plainly, -b already means --apparent-size --block-size=1. The two values were therefore always equal, the condition never fired, and the script pronounced every system clean. A scanner returning nothing doesn't mean nothing is there; you have to prove the tool works first. I ran the version above against a file I deliberately made sparse, and it caught it correctly.

Re-scanning my own CI server with the corrected script produced something far more interesting than the first attempt: 96 of 121 files were sparse. But every one of them lived under /var/log/journal/ — journald preallocates its archive files at 8 MiB and then fills as much as it fills. Apparent size 8,388,608, allocated 3.8 MB. That's design, not damage.

Exclude the journal directory and you're left with zero files. So this server has no copytruncate-induced holes — but now I'm saying that from a measurement rather than an assumption. If anything outside journal shows up on yours, the process writing it isn't using O_APPEND, and you have the hole described above.

Third, verify that a process actually reopened its log. After a rotation:

ls -l /proc/$(pidof -s myapp)/fd | grep '\.log'
Enter fullscreen mode Exit fullscreen mode

If you still see (deleted) or the rotated name in there, the process never opened the new file — either the signal wasn't sent or the application doesn't listen for it. In that case the new app.log sits at zero bytes for days and nobody notices, because monitoring usually asks "is the disk filling up?" rather than "is this file growing?".

So when is copytruncate acceptable

Ending this with "never use it" would be lazy. Sometimes there really is no other option. What I ask myself when deciding:

  1. Can the application reopen its file on a signal? If yes, the discussion is over; use create plus postrotate. nginx, Apache, HAProxy, PostgreSQL and most modern daemons do this.
  2. Can you briefly restart the process? A systemctl reload inside postrotate is usually acceptable and gives you zero loss.
  3. Do you have to write to a file at all? If not, pipe the output to journald or a collector and the rotation problem disappears.
  4. If none of those work: use copytruncate, but know what you're trading. Small, frequent rotations lose more lines in total; what you buy is that no single hole swallows an entire incident.
  5. Make sure the writer uses O_APPEND. If it doesn't, budget for the sparse-file hole too — and test how your log shipper reacts to it beforehand.
  6. Write down the loss you accepted. One line in the runbook: "this service loses roughly 1% of its logs at rotation time." In six months the person staring at that hole may not be you.

That last one matters most, I think. Choosing to lose data is a legitimate engineering decision; not knowing that you're losing it is not.

Closing

The real lesson I took from this measurement isn't about copytruncate. It's about the language of documentation.

"Very small time slice" isn't technically wrong — even in the worst run the loss window was 396 milliseconds. But while "very small" holds up in seconds, it doesn't hold up at all in lines you wrote. For a process writing between 299,000 and 594,500 lines per second, that tiny moment came to 141,517 lines on the largest file I tested. Same sentence, same system, two different units.

I no longer accept words like "small", "rare" or "negligible" from documentation without translating them into my own load profile first. It's the same thing I learned the night a disk filled up: production numbers rarely contradict the adjectives in the docs — they just convert them into a different unit. If you don't do the conversion, it gets done for you, at midnight.

Official Sources

Top comments (0)