dockerd fails to delete container and rsync becomes stuck

[cavedon]

I have sysbox-ce running Ubuntu jammy.

Sometimes I see a situation where the content of /var/lib/sysbox/docker is not cleaned up. For those containers I see 3 rsync processes stuck, and some errors in the docker logs about not being able to remove the container.

What I suspect is happening is that a request is done to stop the container. At that point sysbox starts an rsync from /var/lib/sysbox/docker/XXX to /var/lib/docker/overlay2/YYY (is that true? What is the purpose of that rsync?). But because of the size of /var/lib/sysbox/docker/XXX, the rsync takes too much time, docker gives up waiting and deletes /var/lib/docker/overlay2/YYY, which causes rsync to get stuck (instead of crashing, why?) and the content of /var/lib/sysbox/docker/XXX not to be deleted.

Here are the relevant logs:

# du -sh /var/lib/sysbox/docker/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570
1.6G    /var/lib/sysbox/docker/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570

# ps axf | grep rsync
1143356 pts/1    S+     0:00      \_ grep --color=auto rsync
 869488 ?        S      0:02  \_ rsync -rauqlH --no-devices --delete --usermap=165637:101,166546:1010,165636:100,165542:6,166536:1000,165536:0 --groupmap=166546:1010,165548:12,166536:1000,165579:43,165578:42,165540:4,165637:101,165544:8,165586:50,165536:0 /var/lib/sysbox/docker/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570/ /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/diff/var/lib/docker
 869489 ?        S      0:00      \_ rsync -rauqlH --no-devices --delete --usermap=165637:101,166546:1010,165636:100,165542:6,166536:1000,165536:0 --groupmap=166546:1010,165548:12,166536:1000,165579:43,165578:42,165540:4,165637:101,165544:8,165586:50,165536:0 /var/lib/sysbox/docker/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570/ /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/diff/var/lib/docker
 869490 ?        S      0:03          \_ rsync -rauqlH --no-devices --delete --usermap=165637:101,166546:1010,165636:100,165542:6,166536:1000,165536:0 --groupmap=166546:1010,165548:12,166536:1000,165579:43,165578:42,165540:4,165637:101,165544:8,165586:50,165536:0 /var/lib/sysbox/docker/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570/ /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/diff/var/lib/docker

# ls /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/
ls: cannot access '/var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/': No such file or directory

$ journalctl   -u sysbox-mgr -u sysbox-fs -u sysbox -u containerd -u docker | grep 53b8fe15f63d
Oct 31 16:18:48 jenkins-agent01 sysbox-mgr[2287]: time="2024-10-31 16:18:48" level=info msg="registered new container 53b8fe15f63d"
Oct 31 16:18:48 jenkins-agent01 sysbox-fs[2312]: time="2024-10-31 16:18:48" level=info msg="Container pre-registration completed: id = 53b8fe15f63d"
Oct 31 16:18:48 jenkins-agent01 sysbox-fs[2312]: time="2024-10-31 16:18:48" level=info msg="Container registration completed: id = 53b8fe15f63d, initPid = 832907, uid:gid = 165536:165536"
Oct 31 16:21:39 jenkins-agent01 sysbox-fs[2312]: time="2024-10-31 16:21:39" level=info msg="Container unregistration completed: id = 53b8fe15f63d"
Oct 31 16:21:48 jenkins-agent01 dockerd[1173]: time="2024-10-31T16:21:48.156229633Z" level=info msg="Container failed to exit within 10s of signal 15 - using the force" container=53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570
Oct 31 16:22:09 jenkins-agent01 dockerd[1173]: time="2024-10-31T16:22:09.177376495Z" level=warning msg="failed to delete container from containerd" container=53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570 error="DeadlineExceeded: context deadline exceeded"
Oct 31 16:22:09 jenkins-agent01 dockerd[1173]: time="2024-10-31T16:22:09.185412210Z" level=error msg="53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570 cleanup: failed to delete container from containerd: cannot delete running task 53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570: failed precondition"
Oct 31 16:22:12 jenkins-agent01 dockerd[1173]: time="2024-10-31T16:22:12.086314438Z" level=error msg="Error removing mounted layer 53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570: unlinkat /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/diff/var/lib/docker/overlay2/fc76115298a69bf9185a5ceafb48f88899e0fa0b7870a006b37f3410d6bd8b04/diff/usr/lib/python3.10/__pycache__: directory not empty"
Oct 31 16:22:12 jenkins-agent01 dockerd[1173]: time="2024-10-31T16:22:12.087546214Z" level=error msg="Handler for DELETE /containers/53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570 returned error: container 53b8fe15f63d2e2152bf093ff000a192a687199ec6b77d0f44e4ad7e063a3570: driver \"overlay2\" failed to remove root filesystem: unlinkat /var/lib/docker/overlay2/2db48bae7d36c5bc635f748d9ce02aced58c550a131bd36383314d62fdec6a2d/diff/var/lib/docker/overlay2/fc76115298a69bf9185a5ceafb48f88899e0fa0b7870a006b37f3410d6bd8b04/diff/usr/lib/python3.10/__pycache__: directory not empty"

[ctalledo]

Hi @cavedon, thanks for trying Sysbox and reporting the issue.

Your observation is correct: when a Sysbox container stops, Sysbox transfers data from /var/lib/sysbox/docker/<uuid> to the container's nominal rootfs on the host (usually /var/lib/docker/overlay2/uuid/...). It uses rsync to do the transfer efficiently. The data it transfers is basically the contents of the container's /var/lib/docker. It's trying to transfer that data to the container's rootfs, which is ideally where it should have been in the first place (but can't during container runtime as it results in overlayfs-on-overlayfs which does not work). This way, if one ever does a docker commit to stop and capture the container state, the resulting container image will have the contents of /var/lib/docker in it, which in turn results in the ability to preload container images into Sysbox containers (more about this in the Sysbox docs).

The problem you are seeing occurs typically when the container's /var/lib/docker has a lot (GBs) of data. Is that the case?

The best way to work-around it is to set this flag in sysbox-mgr to true: disable-inner-image-preload=true.

See here for how to do this.

Hope that helps!

[cavedon]

Thank you! I will try disable-inner-image-preload=true as I do not need image preload.

The problem you are seeing occurs typically when the container's /var/lib/docker has a lot (GBs) of data. Is that the case?

I have now 25 GB in /var/lib/docker, but I do not think there was much when the issue occurred he first time, I had just clean up the system to triage that...