Exits on `docker events terminated`

[schnittchen]

Description

I use docker compose with multiple services, and compose builds the needed images itself. Occasionally, compose aborts with an error because it cannot find the image it has just built.

I assume this happens when both of these conditions are true:

• the built image already existed, so its LRU is old enough, because all build steps were cached, leading to the newly built image being an existing one
• docuum crashed and (in my case) was automatically started, performing the more aggressive startup cleaning

The crash looks like this:

Nov 18 11:42:09 sonnenschein-gh-runner docker[1733577]: [2024-11-18 11:42:09 +00:00 DEBUG] Waking up…
Nov 18 11:42:09 sonnenschein-gh-runner docker[1733577]: [2024-11-18 11:42:09 +00:00 DEBUG] Updating last-used timestamp for image `sha256:a5ae6b5aac27c27b6e4b1f8e81ff0af7fa071e17f85a3e2c767129e1814426e7`…
Nov 18 11:42:09 sonnenschein-gh-runner docker[1733577]: [2024-11-18 11:42:09 +00:00 DEBUG] Going back to sleep…
Nov 18 11:43:38 sonnenschein-gh-runner systemd[846]: docuum.service: Main process exited, code=exited, status=1/FAILURE
Nov 18 11:43:38 sonnenschein-gh-runner systemd[846]: docuum.service: Failed with result 'exit-code'.
Nov 18 11:43:39 sonnenschein-gh-runner systemd[846]: docuum.service: Scheduled restart job, restart counter is at 99.
Nov 18 11:43:39 sonnenschein-gh-runner systemd[846]: Stopped Docuum (docker image vacuumer).
Nov 18 11:43:39 sonnenschein-gh-runner systemd[846]: Started Docuum (docker image vacuumer).
Nov 18 11:43:39 sonnenschein-gh-runner docker[1822919]: [2024-11-18 11:43:39 +00:00 INFO] Performing an initial vacuum on startup…
Nov 18 11:43:40 sonnenschein-gh-runner docker[1822919]: [2024-11-18 11:43:40 +00:00 DEBUG] Ignored image `sha256:a5ae6b5aac27c27b6e4b1f8e81ff0af7fa071e17f85a3e2c767129e1814426e7` due to the `--min-age` flag.

As you can see, all crash related information I have is the exit status, at least this time. Last time around, I saw "docker events terminated" which made docuum exit.

Instructions to reproduce the bug

It happens only sporadically, so that remains to be seen.

Environment information:

• 0.25.0
• Docker version 27.3.1, build ce12230
• Ubuntu 22.04.5 LTS

Additional context

I'm using rootless docker, and I'm starting docuum like this:

ExecStart=/usr/bin/docker run \
  --rm \
  --init \
  --name docuum \
  --mount type=bind,src=/run/user/%U/docker.sock,dst=/var/run/docker.sock \
  --mount type=volume,source=docuum,target=/root \
  stephanmisc/docuum --threshold '10 GB' --min-age '5min'

Help is very much appreciated for getting more information on this issue.

[stepchowfun]

Hi @schnittchen, thanks for filing this issue! Could you try running Docuum with LOG_LEVEL=trace to see if you get any more info from the logs?

docuum crashed and (in my case) was automatically started, performing the more aggressive startup cleaning

Docuum always tries to keep the image disk usage below the threshold, whether on startup or not—although on startup there might be more work to do. There's only one thing that is different about startup:

• Normally, when Docuum encounters an image it hasn't seen before, it takes the current time as the "last used time" for that image. This usually happens because a new image was created since Docuum started.
• However, on startup when Docuum encounters an image it hasn't seen before (according to its persisted state), it takes the image creation time as the "last used time" for that image. The reason for this is that on the first run, Docuum hasn't seen any images before, and it wouldn't be very useful to assign the current time as the "last used time" for all the images (then the deletion order would be unpredictable and probably not what one wants).

[schnittchen]

I added the LOG_LEVEL and I'm currently investigating.

The second time now I've seen this:

Nov 19 09:19:13 sonnenschein-gh-runner docker[320972]: [2024-11-19 09:19:13 +00:00 DEBUG] Going back to sleep…
Nov 19 09:28:00 sonnenschein-gh-runner docker[320972]: [2024-11-19 09:28:00 +00:00 ERROR] `docker events` terminated.
Nov 19 09:28:01 sonnenschein-gh-runner systemd[843]: docuum.service: Main process exited, code=exited, status=1/FAILURE
Nov 19 09:28:01 sonnenschein-gh-runner systemd[843]: docuum.service: Failed with result 'exit-code'.

Relevant docker service logs at that time:

Nov 19 09:19:13 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:19:13.355083168Z" level=info msg="cleaning up dead shim" namespace=moby
Nov 19 09:28:01 sonnenschein-gh-runner dockerd-rootless.sh[920]: time="2024-11-19T09:28:01.014840625Z" level=info msg="ignoring event" container=5ab5a9a6fa7d6a7f70ccae4a9389afd60b6296e5313c26608b437f5de3320022 module=libcontainerd namespace=moby topic=/tasks/delete type="*events.TaskDelete"
Nov 19 09:28:01 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:01.015714228Z" level=info msg="shim disconnected" id=5ab5a9a6fa7d6a7f70ccae4a9389afd60b6296e5313c26608b437f5de3320022 namespace=moby
Nov 19 09:28:01 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:01.015804295Z" level=warning msg="cleaning up after shim disconnected" id=5ab5a9a6fa7d6a7f70ccae4a9389afd60b6296e5313c26608b437f5de3320022 namespace=moby
Nov 19 09:28:01 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:01.015817667Z" level=info msg="cleaning up dead shim" namespace=moby
Nov 19 09:28:02 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:02.365678559Z" level=info msg="loading plugin \"io.containerd.event.v1.publisher\"..." runtime=io.containerd.runc.v2 type=io.containerd.event.v1
Nov 19 09:28:02 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:02.365755852Z" level=info msg="loading plugin \"io.containerd.internal.v1.shutdown\"..." runtime=io.containerd.runc.v2 type=io.containerd.internal.v1
Nov 19 09:28:02 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:02.365772040Z" level=info msg="loading plugin \"io.containerd.ttrpc.v1.task\"..." runtime=io.containerd.runc.v2 type=io.containerd.ttrpc.v1
Nov 19 09:28:02 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T09:28:02.367406562Z" level=info msg="loading plugin \"io.containerd.ttrpc.v1.pause\"..." runtime=io.containerd.runc.v2 type=io.containerd.ttrpc.v1
Nov 19 10:11:42 sonnenschein-gh-runner dockerd-rootless.sh[971]: time="2024-11-19T10:11:42.313428599Z" level=info msg="loading plugin \"io.containerd.event.v1.publisher\"..." runtime=io.containerd.runc.v2 type=io.containerd.event.v1

[stepchowfun]

A weird thing about this is that Docuum runs in an infinite loop with a top-level error handler. So it generally doesn't crash under normal circumstances, regardless of what Docker does.

I wonder if Docuum is receiving a signal like SIGTERM or SIGKILL from something (Docker Compose?), or maybe the system doesn't have enough memory so things are getting OOM killed (Docuum itself doesn't use much memory, but maybe something else does).

[schnittchen]

If it was a Signal, I think systemd would show that in the logs?
It's definitely not memory pressure.

[stepchowfun]

I notice the exit code is 1 (is that right?)—the only place that Docuum explicitly exits with that code after it has started running is here in the handler for SIGINT/SIGTERM/SIGHUP, so that's why I'm suspicious that it's a signal. We could potentially add some logging there to confirm. Would you be able to add something like error!("Signal recieved."); right before that exit(1); and build Docuum locally (should just be cargo build if you have Rust installed)?

[schnittchen]

That would be quite some effort, since I'm running it on a server and I'd need to set up all the tooling...

Maybe it's possible to wrap docuum with a little shell script that traps and logs signals. I'm not so much of a shell expert though.

My initial problem was probably due to my own cleanup script running in parallel and taking care of containers, networks and volumes, disrupting the startup of compose. I have hopefully fixed that and will know in a few days if it's working.

The mysterious docker events terminated probably remains though.

[stepchowfun]

It's a mystery indeed, because docker events terminating shouldn't cause Docuum to crash. Docuum will just spawn a new docker events.

[schnittchen]

As I mentioned, besides docuum I have a service running which periodically tries to get rid of old container, volumes and networks. I disabled it(*) so it does not interfere with observing this issue.

(*) it still stops long-running containers because that seems to work well enough.

As I'm looking at that periodic script, I am looking at shell code trying to parse go-formatted output of docker ps and my head is getting all dizzy. I guess what I want to express is that these are problems that would make sense for docuum to solve as well. Even a heuristic solution would be better than none (or my horrible scripting).

[stepchowfun]

I agree that it would be nice for Docuum to clean up more than just images. This is a common feature request (e.g., #68), and I don't have any major concerns about it—it just needs to be built.

[schnittchen]

For the record, this is what I'm doing right now regarding other resources, from a minutely scheduled script:

# Clear docker build cache when free disk space is running low.
free_percent=`stat -f -c '%a * 100 / %b' / | bc`
min_free_percent=30
if [ $free_percent -lt $min_free_percent ]; then
  docker builder prune -f
fi

if date | grep ' 04:00:' >/dev/null 2>&1; then                                                                              
  docker container prune --force                                                                                            
  docker volume prune --all --force                                                                                               
  docker network prune --force                                                                                              
fi                                                                                                                          

I can do this only because it's not a production machine, and there's a time window where this doesn't cause any harm.

[Edited: added --all to volume pruning]
[Edited: added build cache pruning]

[schnittchen]

Here's logs from the last time docuum terminated:

Nov 29 10:19:42 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:19:42 +00:00 DEBUG] Docker images are using `9.68 GB`, which is within the limit of `10.00 GB`.
Nov 29 10:19:42 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:19:42 +00:00 INFO] Listening for Docker events…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Waking up…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Updating last-used timestamp for image `sha256:11229070f1e2ac463af222c4a912d29a1f1dbed27610c6de2ad5f0a55d43f23e`…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Going back to sleep…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Waking up…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Updating last-used timestamp for image `sha256:40ddf29a3b2f81f8084970b142dc59edbaa2737edbfce3230d920671e2ee9833`…
Nov 29 10:20:17 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:17 +00:00 DEBUG] Going back to sleep…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Waking up…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Updating last-used timestamp for image `sha256:3b278b9780b6599272f368873357ec3d53b8b99bd09c24dd7e4aa4b13f5d4936`…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Going back to sleep…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Waking up…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Updating last-used timestamp for image `sha256:bb7a102cb30b7030de182d8eb79403348fc02922920186589fd5f784a7bd1dbd`…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Going back to sleep…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Waking up…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Updating last-used timestamp for image `sha256:fc9156a9e8b840766922b608e7ea181f379894a5bb67d60f526b5e4a0040112a`…
Nov 29 10:20:27 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:20:27 +00:00 DEBUG] Going back to sleep…
Nov 29 10:53:11 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:53:11 +00:00 ERROR] `docker events` terminated.
Nov 29 10:53:11 sonnenschein-gh-runner docker[2402942]: [2024-11-29 10:53:11 +00:00 INFO] Retrying in 5 seconds…
Nov 29 10:53:11 sonnenschein-gh-runner systemd[853]: docuum.service: Main process exited, code=exited, status=1/FAILURE
Nov 29 10:53:11 sonnenschein-gh-runner systemd[853]: docuum.service: Failed with result 'exit-code'.
Nov 29 10:53:12 sonnenschein-gh-runner systemd[853]: docuum.service: Scheduled restart job, restart counter is at 127.
Nov 29 10:53:12 sonnenschein-gh-runner systemd[853]: Stopped Docuum (docker image vacuumer).
Nov 29 10:53:12 sonnenschein-gh-runner systemd[853]: Started Docuum (docker image vacuumer).

[schnittchen]

I misconfigured the log level. Hope I did it right this time.

Will post logs when I see the crash again.

[schnittchen]

The error has not occurred again within the past five days. I suspect my previously aggressive cleanup script for running containers, which also pruned networks and volumes, somehow triggered it.

I'll continue to keep an eye on this. I'd close this when the problem does not re-appear within some time though, so we can move on.