A log shipper kept retrying logs its backend had rejected, and burned 1.5 cores in dockerd

September 9, 2026docker · observability · loki · promtail · performance

Promtail looped forever on a backlog Loki would not accept, and every retry made dockerd re-parse 159 MB of container logs; a positions volume, a slower service-discovery refresh and a force-recreate fixed it.

Context

server-3 is a 4-core VPS that hosts my monitoring stack (Prometheus, Alertmanager, Grafana, Loki, Promtail) plus a few internal apps. Promtail ships container logs to Loki. It discovers containers through docker_sd_configs, pointed at a docker-socket-proxy endpoint, so it reads logs through the Docker API rather than from the files on disk.

What I saw

Load average 4.7 on 4 cores.
dockerd itself using 116-161% of one core, continuously, for about 7 hours.
All containers together under 8% CPU. The load was not coming from any application.
st (steal) was 0, so this was not a noisy neighbour on the host. That was the first thing I checked.

Finding the cause

I did not want to guess, so I profiled the daemon:

perf record -p <dockerd pid> -g

48% of the samples sat in encoding/json.(*Decoder).readValue, unquoteBytes, stateInString and time.parseRFC3339. That is the signature of parsing the json-file log driver format: each line is a JSON object with an RFC3339 time field. So dockerd was spending its CPU reading container logs through the API.

Who reads logs through the API? Promtail, because of the Docker service discovery setup. To prove it rather than assume it, I ran an experiment:

Promtail stopped: dockerd dropped to 0%.
Promtail started: dockerd went back to 161%.
Stopping the dozzle log-viewer agent as well changed nothing, so it was not the other log reader.

That told me who, but not why Promtail would re-read so much. Its own log had the answer:

400 Bad Request: "entry too far behind, entry timestamp is 2026-09-08T14:09:27Z, oldest acceptable is 2026-09-08T16:36:32Z"

Loki was rejecting old entries: the one in the error was about two and a half hours older than the oldest it would accept. Promtail kept trying to ship a backlog that Loki would never accept. I did not establish why the backlog had fallen behind in the first place; the fix below breaks the loop, not the original lag. It retried forever, and each pass made dockerd decode the same 159 MB of logs again. A second multiplier: refresh_interval on the Docker discovery was 5 seconds, so the target list was rebuilt constantly. Promtail's positions file was in /tmp inside the container, so the bad state survived a plain restart.

Dead ends and traps along the way, which cost me time:

The glob /var/lib/docker/containers/*/*-json.log does not expand for a normal user, because the directory is root-only. du and stat quietly returned 0 and I briefly concluded "no container is writing logs". Wrong. It needs sudo bash -c "..." so root expands the glob.
I read the positions file's modification time as 17:28 and decided it had been frozen since the day before. The container clock is UTC; 17:28 UTC is 00:28 in Ho Chi Minh City, so it was updating normally. I now run date -u before saying a file is "stuck".
Promtail had cpus: '0.5' in the compose file. That gave a false sense of safety: Promtail was capped at half a core while it drove dockerd, which is outside that limit, to 1.5 cores.

Root cause

Promtail kept retrying a backlog that Loki refused with a 400, and every retry forced dockerd to re-decode the container logs through the API. The 5-second discovery refresh amplified it, and the positions state was not on persistent storage, so the loop did not clear on a restart.

The fix

Changes in the monitoring compose project:

Add a named volume promtail_positions mounted at /promtail.
Move positions.filename from /tmp/positions.yaml to /promtail/positions.yaml.
Raise refresh_interval from 5s to 60s.
docker compose up -d --force-recreate promtail.

Step 4 matters. docker restart promtail does nothing useful here: a restart keeps the same container, so the state in /tmp survives. Only recreating the container discards it.

Result: dockerd went from 146% to between 0 and 16%, load from 4.7 to 0.9, Promtail errors to roughly zero, and Loki caught up at a normal rate of about 43 lines per second.

What stops it happening again

Positions now live on a volume, so a recreate or upgrade does not lose or corrupt them silently.
The discovery refresh is 60 seconds, not 5.
If it ever returns, the stronger option is to drop docker_sd_configs and have Promtail tail the *-json.log files directly (the directory is already mounted). That takes dockerd out of the log path for good, at the price of relabelling by hand because the automatic Docker labels go away. I left it as a fallback because the current fix works.
Monitoring gap, still open: the Prometheus rules on server-3 have no alert for dockerd CPU, for Promtail or Loki 400 errors, or for steal. The two CPU rules would not have fired. HighCpuUsage needs the whole machine above 80% for 5 minutes, and dockerd at 116-161% of one core is 29-40% of four. ContainerHighCpuUsage watches containers, and dockerd is not one.

What I learned

Measure before blaming. perf plus a stop/start experiment gave a causal chain, not a theory.
A symptom on one process can be caused by a client of that process. dockerd was the victim; the culprit looked cheap, because Promtail was within its own limit.
Resource limits can hide the real cost. A cap on the client does not cap the work it makes the server do.
Retry loops need a way out. An error like "entry too far behind" will never succeed on retry, and a shipper that retries it forever is a load generator.
Check your tools before you trust your conclusions: unexpanded globs and UTC versus local time each nearly sent me the wrong way.