The service was logging that it could not log: how a full disk turned into a self-feeding outage

Short answer: a single out-of-space event became permanent because the database could not write to its own log file, reported that failure to stderr for every suppressed message, and Docker's default json-file driver captured stderr into a file whose max-size defaults to unlimited. Freeing the disk brings inserts back and leaves the loop running at full speed, because the logger does not recover without a restart. Judge the repair by the growth rate of whatever ate the disk, not by the absence of errors.

The complaint arrived from the wrong place. A development stand reported that its buffering insert proxy had stopped shipping and was spooling files locally, with its own disk filling up. The cluster it ships to was the thing that was actually down, on both replicas, with zero bytes free. A small consumer failed loudly enough to be noticed, which is the only reason anyone looked.

TL;DR

• Fix: truncate the runaway container log in place with truncate -s 0, then restart the service whose logger is wedged, one node at a time. Both halves are required.
• Alternative: there isn't one for the restart. Upstream's own issue says the logging internals "will not recover without a restart", and reopening by signal is unreliable in a separate, older issue.
• Trap: treating the return of successful inserts as the repair. That is what happened a few days before I looked, by someone doing exactly what any on-call engineer would do, and the outage came back.

Why freeing the disk fixed nothing

Because it removes the symptom and the urgency together, while the thing that ate the disk keeps eating at the same rate. This had already happened once: a few days earlier the oversized log was trimmed, a ballast file was dropped on the disk as emergency headroom, inserts resumed, and the incident was closed. The disk filled again.

The check that settles it takes thirty seconds and no ClickHouse knowledge at all:

stat -c %s <suspect-file>; sleep 30; stat -c %s <suspect-file> 

Suppose those two readings differ by thirty-odd megabytes. That is about a megabyte a second, which is some ninety gigabytes a day, and whatever headroom you just freed is gone inside of one. Space had been returned to the filesystem and the hole was still being dug, at a rate you can state in a sentence.

This is the measurement I wish had been taken during the first repair, and it is the one durable lesson from the whole incident. The absence of errors is not evidence of a fix when the error was a symptom of exhaustion: clear the exhaustion and the errors stop, whatever caused it. A growth rate cannot be faked that way.

The number that found the culprit, and it was not the database

A database can be asked how much space it believes is its own, and the answer compared against df. When those two disagree by a wide margin, the thing filling the disk is not the database, and that single comparison cuts the search in half.

SELECT active, formatReadableSize(sum(bytes_on_disk)), count() FROM system.parts GROUP BY active; 

Take a case where the parts add up to roughly a hundred gigabytes, active and inactive together, while df reports three times that on the partition. The gap is bigger than anything the database can account for. At that point I stopped reading system.parts and started looking at the partition itself, which is where the container log was sitting.

I had spent time before that on a genuinely anomalous table, and it was a detour. One monthly partition of a log table held a couple of hundred times what its neighbouring months held at comparable row counts, because full request and response bodies had been landing in two of its columns for a month. Dropping it returned real space and explained none of the shortfall. A convincing local anomaly is the easiest way to lose an hour during an outage: it is true, it is fixable, and it is not the reason you were paged.

The loop

The mechanism is positive feedback, and the diagnostic output is what closes the circuit.

1. The disk fills for its own reasons. The last line in the database's own error log before it went silent was the ordinary complaint of a full disk:

Code: 243. DB::Exception: Cannot reserve 1.00 MiB, not enough space. (NOT_ENOUGH_SPACE) (version 23.2.6.34 (official build)) 

1. The same absence of space breaks the server's write to that log file, and the logging channel enters a state it does not leave.
2. Every message that cannot reach the file is written to stderr instead, each one carrying a full stack trace of twenty-six frames:

Cannot add message to the log: Poco::Exception. Code: 1000, e.code() = 0, File access error: /var/log/clickhouse-server/clickhouse-server.log 

1. Docker collects stderr and writes it to the container's *-json.log. The json-file driver's max-size "Defaults to -1 (unlimited)" in its own documentation, and max-file defaults to 1, so nothing rotates and nothing is ever discarded.
2. That file grows at about a megabyte a second on the very partition whose exhaustion it is reporting.

The ordering in step 1 matters and is worth checking in your own logs rather than assuming: space ran out first, and the logger broke as a consequence. The reverse story, where a broken logger somehow fills a disk, would need a different fix.

What makes this class of outage behave unlike a normal failure is the sign of the feedback. A recoverable, one-off condition is converted into a permanent one, and the worse it gets the faster it gets worse. Between the two replicas, the container logs held roughly three times as many bytes as the actual analytical data did. Garbage outweighed the database it was burying.

There is an uncomfortable detail in the timeline: one node had been sitting in this loop for about three weeks and the other for about ten days, and nothing fired. The monitoring watched the host machine rather than the partition inside the OS container where the replica lives. I am flagging that as a hypothesis rather than a finding, because I never went back to verify the monitoring configuration, and it is the most likely reason a full disk survived to a hundred percent unannounced.

Why a restart is not optional here

Because upstream says the logging internals do not come back on their own, and I found both issues before trying anything clever. I wanted to avoid restarting a production replica and went looking for a way to make the server reopen its log files in place.

The first issue is the one that describes this outage exactly. ClickHouse issue #68438, open since August 2024, states it plainly:

when clickhouse attempts to log to a full disk, the code that appears to be intended to handle this case is never triggered, and the logging internals will not recover without a restart

The second kills the signal-based workaround. Issue #8696, "Sometimes logs remain open after SIGHUP", is a single sentence:

The server may open a new log file but still continue to write to the old log file.

A reopen that works most of the time is worse than one that never works, because the cases where it silently did not work look identical to success. With two replicas and a load balancer, the restart cost about fifteen seconds of one node being out of rotation. The cost of not restarting was the same outage again in a few days.

For the record, the server rotates its own log perfectly well under normal conditions, <size>1000M</size> with <count>10</count> in the default configuration. Its own rotation was never the problem, and there was no external logrotate touching it either, which was my third dead end. Both logs had gone silent late at night, which looked exactly like a logrotate run renaming a file out from under a running process. There was no such configuration anywhere, inside the container or on the host. The timing was a coincidence and I had built a theory on it.

Two ways the cleanup lies to you

Both of these are measurable in a minute on any machine, so I measured them here rather than asserting them.

rm does not return the space while something holds the file open. This is the cleanup an on-call engineer reaches for first, and on a wedged log file it does nothing visible. Holding a 500 MiB file open, unlinking it, then closing the descriptor:

after unlink : 0 MiB returned to df lsof deleted fds : 1 after closing fd : 500 MiB returned to df 

The space comes back when the last descriptor closes, not when the directory entry disappears. That is why the remediation is truncate -s 0 on the live file: the holder keeps its descriptor, the blocks are released immediately, and df moves while you watch. If someone already ran rm, lsof | grep deleted finds it and only restarting the holder will help.

An emergency ballast file made with the wrong tool occupies nothing. truncate -s 60G and dd with seek= both produce a sparse file: the size in a listing is whatever you asked for, and the blocks are not there. Deleting it during an outage returns nothing at all, which is the worst possible moment to discover that your insurance was notional. One gigabyte by each method, on the same filesystem:

Check an existing ballast with du -h <file> against du -h --apparent-size <file>. If they disagree, you are holding a receipt instead of a reserve. Use fallocate.

Dropping a huge partition without finishing off the server

Use DROP PARTITION, and specifically not DELETE WHERE or DETACH, because on a disk that has already run out of space the other two need space to work.

• ALTER TABLE ... DELETE WHERE is a mutation: it rewrites whole parts and needs roughly the volume being rewritten in free space. On a full disk that is a way to make things worse.
• DETACH PARTITION moves the parts into detached/ on the same disk and frees nothing. You can confirm what is parked there with SELECT count(), sum(bytes_on_disk) FROM system.detached_parts, and you will still need DROP DETACHED PARTITION afterwards.
• DROP PARTITION marks the parts inactive and deletes the directories without rewriting anything.

Two defaults will make a correct DROP look broken, and both are in the source rather than clearly in the docs. Space comes back when a background task removes the inactive parts after old_parts_lifetime, declared as old_parts_lifetime, 8 * 60 in MergeTreeSettings.cpp, so eight minutes of apparently nothing happening is the documented behaviour and not a failed command. If you genuinely cannot wait, MODIFY SETTING old_parts_lifetime = 60 temporarily and RESET SETTING afterwards.

The second is a safety catch: max_partition_size_to_drop, 50000000000lu in ServerSettings.cpp, which is 50 GB, and anything larger is refused outright. max_table_size_to_drop carries the same number. Raise it in the configuration, or drop a one-shot flags/force_drop_table file, which is consumed by the first successful drop.

Why daemon.json will not fix the containers you already have

Because logging options are fixed into a container's configuration when it is created. Docker's own documentation is unambiguous about the scope of a daemon-level change: "The changes take effect for newly created containers after the restart." A container with nine months of uptime keeps the unlimited log it was born with, no matter what daemon.json says now.

Verify per container rather than by reading the daemon config, because the daemon config will tell you what you hoped for:

docker inspect <container> --format '{{.HostConfig.LogConfig}}' 

That leaves two options for the containers already running. Recreate them, which for a long-lived database container means trusting that the image tags and the compose file still describe what is actually running, and after many months that is its own risk. Or leave them alone and put logrotate with copytruncate on /var/lib/docker/containers/*/*-json.log, which works on a running container and matches the truncate-rather-than-rm behaviour the open descriptor forces on you anyway. I took the second and it is still the part of this I am least happy about, because until that rotation exists the protection rests entirely on the logger being healthy.

Does this only happen to ClickHouse

No, and the database is the least interesting part of it. The loop needs three conditions, none of which are specific to this product.

The first is a service that reports its own logging failures through a second channel. That is a reasonable thing to build: a process that cannot write its log should say so somewhere rather than go quiet. It becomes a hazard only when the second channel is cheaper to write than the first and has no limit.

The second is an unbounded sink on that channel. Under Docker, that is the default rather than a mistake someone made: max-size is unlimited unless you set it, for every container, whatever is inside it. The same shape exists outside Docker wherever stderr is appended to a file by a supervisor with no cap.

The third is shared storage, so the sink and the thing it complains about are the same filesystem. Split them and the loop still runs, but it stops being self-feeding, which is the whole difference between an incident and a recurring one.

Check your own fleet by asking which services write diagnostics to stderr at a rate proportional to how badly they are failing, and then whether anything caps that stream. The two-reading stat test works on any of them, and so does the trick of asking a stateful service how much disk it believes it owns and comparing that against df. Neither needs you to know what the service is.

Step by step

1. Compare what the database thinks it owns against df on the partition. A wide gap means look outside the database.
2. Find the file: ls -lhS /var/lib/docker/containers/*/*-json.log | head.
3. Measure its growth with two stat -c %s readings thirty seconds apart. This number, not the error log, tells you whether you are still bleeding.
4. truncate -s 0 the file. Never rm it.
5. Restart the service whose logger is wedged, one node at a time, checking between nodes.
6. Confirm all three signals: the service writes to its own log file again (a fresh mtime, not a frozen one), the container log is not growing, and inserts are accepted.
7. Drop any genuinely oversized partition with DROP PARTITION, and wait out old_parts_lifetime before deciding it failed.
8. Rebuild the emergency ballast with fallocate, double it, and write the restart step on the same page as the ballast. A reserve without a procedure next to it only buys the next engineer the same half-repair.
9. Add rotation for the container logs, the same day if you can.

Bottom line

Three things survive from this incident. Measure the growth rate of whatever consumed the disk rather than the disappearance of errors, because clearing exhaustion always stops the errors and sometimes fixes nothing. Any log without rotation is a loaded weapon, and it is pointed at you specifically when the service is capable of logging its own logging failures. An emergency reserve with no written procedure beside it is not insurance, it is a delay, and the delay gets spent by whoever is on call next.

Two things are still open, which is the honest state of it: nothing explains yet why that one month's partition took full request bodies, and the hypothesis about monitoring watching the host instead of the container's partition was never verified, although it is the best explanation for three weeks of silence.

Originally published at bitpage.me — BitPage, a technical blog on backend, databases, infrastructure and incident post-mortems.