Docker fails to start after reboot when a system container with a restart policy exists

[jfmontanaro]

If you create a system container with --restart always or --restart unless-stopped, then reboot the system, Docker fails to come back up properly.

Restarting just the daemon also exhibits some issues, but it doesn't hang entirely in that case. The system container won't come back up, but the daemon will eventually (after ~1min) get itself sorted out and be available for other containers.

Ubuntu 20.04, Linux 5.4.0-54-generic
Sysbox 0.2.1-0.ubuntu-focal

Steps to reproduce:

• Create a clean Ubuntu 20.04 instance
• Install Docker and Sysbox
• docker run -d --runtime sysbox-runc --restart always alpine:latest sh -c 'sleep infinity'
• reboot

docker.service will hang in the activating state indefinitely.

What's especially fun is that apparently this also means the system is unable to shutdown properly. It can, however, get far enough into the shutdown process to terminate other daemons (such as, say, sshd.) So if you run into this while working remotely and try to reboot without manually killing the Docker process first, your machine will be inaccessible until you can trigger a hard reboot.

Logs:

-- Reboot --
Jan 10 22:28:51 sysbox-test systemd[1]: Starting Docker Application Container Engine...
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.567021861Z" level=info msg="Starting up"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.569329382Z" level=info msg="detected 127.0.0.53 nameserver, assuming systemd-resolved, so using resolv.conf: /run/systemd/resolve/resolv.con>
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.664031120Z" level=info msg="parsed scheme: \"unix\"" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.664636760Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.665491866Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}>
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.665772896Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.672322779Z" level=info msg="parsed scheme: \"unix\"" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.672757550Z" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.673029328Z" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock  <nil> 0 <nil>}] <nil> <nil>}>
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.673293346Z" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.714060480Z" level=info msg="[graphdriver] using prior storage driver: overlay2"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.752448137Z" level=warning msg="Your kernel does not support swap memory limit"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.752799641Z" level=warning msg="Your kernel does not support CPU realtime scheduler"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.753079561Z" level=warning msg="Your kernel does not support cgroup blkio weight"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.753356100Z" level=warning msg="Your kernel does not support cgroup blkio weight_device"
Jan 10 22:28:51 sysbox-test dockerd[607]: time="2021-01-10T22:28:51.753780823Z" level=info msg="Loading containers: start."

I first encountered this with a docker:dind image that I wanted to come back up automatically. dind is Alpine-based, but I've tested as well with Debian and CentOS and it doesn't seem to make a difference.

The daemon can be gotten out of its stuck sate with kill -9 <daemon PID>, but the container in question remains stopped until manually started.

[ctalledo]

Thanks @jfmontanaro for giving Sysbox a shot and filing this issue. I've not come across this, but will reproduce and get back to you tomorrow.

[ctalledo]

Hi @jfmontanaro, I can see there is a problem, though I am not able to repro the exact behavior you describe.

On my ubuntu focal machine, I tried the steps to reproduce that you mentioned:

1. Create a clean Ubuntu 20.04 instance
2. Install Docker and Sysbox
3. docker run -d --runtime sysbox-runc --restart always alpine:latest sh -c 'sleep infinity'
4. reboot

After the reboot, I can see that Docker fails to restart the container automatically:

vagrant@ct-ubu-focal:~$ systemctl status docker
● docker.service - Docker Application Container Engine
     Loaded: loaded (/lib/systemd/system/docker.service; enabled; vendor preset: enabled)
     Active: active (running) since Tue 2021-01-12 05:26:29 UTC; 19s ago
TriggeredBy: ● docker.socket
       Docs: https://docs.docker.com
   Main PID: 782 (dockerd)
      Tasks: 14
     Memory: 136.8M
     CGroup: /system.slice/docker.service
             └─782 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock

Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.187023106Z" level=info msg="Loading containers: start."
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.761472680Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.761551070Z" level=error msg="stream copy error: reading from a closed fifo"
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.861286174Z" level=error msg="8db2e73210060e5e3b1aac519e1be557bfee1a9bc1f12cbc6f90e4471bf850b5 cleanup: failed to delete container from containerd: no such container"
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.861358789Z" level=error msg="failed to start container" container=8db2e73210060e5e3b1aac519e1be557bfee1a9bc1f12cbc6f90e4471bf850b5 error="OCI runtime create failed: failed to register with sysbox-mgr: failed to invoke Register via grpc: rpc error: >
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.861474629Z" level=info msg="Loading containers: done."
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.920928250Z" level=info msg="Docker daemon" commit=8891c58 graphdriver(s)=overlay2 version=20.10.2
Jan 12 05:26:29 ct-ubu-focal dockerd[782]: time="2021-01-12T05:26:29.921786943Z" level=info msg="Daemon has completed initialization"
Jan 12 05:26:29 ct-ubu-focal systemd[1]: Started Docker Application Container Engine.

The reason for this is that the Sysbox service has not yet started. This is a bug on our installer: we need to fix the Sysbox systemd unit file to ensure Docker starts after Sysbox is ready.

But Docker itself starts fine (it's not hanging in the Activating state as you reported). In fact I can manually restart the container without problem:

vagrant@ct-ubu-focal:~$ docker ps -a
CONTAINER ID   IMAGE           COMMAND                  CREATED          STATUS                        PORTS     NAMES
8db2e7321006   alpine:latest   "sh -c 'sleep infini…"   10 minutes ago   Exited (137) 31 seconds ago             nice_mestorf

vagrant@ct-ubu-focal:~$ docker start nice_mestorf 
nice_mestorf

vagrant@ct-ubu-focal:~$ docker ps
CONTAINER ID   IMAGE           COMMAND                  CREATED          STATUS         PORTS     NAMES
8db2e7321006   alpine:latest   "sh -c 'sleep infini…"   10 minutes ago   Up 3 seconds             nice_mestorf

vagrant@ct-ubu-focal:~$ docker exec nice_mestorf sh -c "ps"
PID   USER     TIME  COMMAND
    1 root      0:00 sleep infinity
   51 root      0:00 ps

I tried the reboot sequence several times, and it was always the same.

Also, I was not able to reproduce the shutdown problem you reported. In my case the shutdown proceeded without any problem in all of the several times I tried.

Let me work on fixing the Sysbox systemd unit file.

But I am still curious why you are seeing the problems on shutdown and with Docker activating after reboot, yet I can't repro those.

[jfmontanaro]

@ctalledo Hmm, that's very interesting. I have a VM running that is consistently exhibiting the behavior, would you like access to it to test? Or are you satisfied that this is probably due to the order in which services start and will go from there?

[ctalledo]

@ctalledo Hmm, that's very interesting. I have a VM running that is consistently exhibiting the behavior, would you like access to it to test? Or are you satisfied that this is probably due to the order in which services start and will go from there?

Let me first come up with a fix for the Sysbox systemd service, so you can apply it and see if the problem goes away. If it does not, then I would certainly appreciate getting access to the machine to investigate.

Thanks!

[ctalledo]

@jfmontanaro : FYI, I was able to reproduce the docker hang too, by playing a bit with the timing of the start of the sysbox service vs. that of the docker service during the machine boot. Will take a deeper look at it tomorrow. Thanks again for reporting the issue!

[ctalledo]

@jfmontanaro: found the root cause of the hang: it's a cyclic dependency between Docker and Sysbox.

When the machine is rebooted, systemd starts Sysbox and then Docker. When Docker starts, it automatically proceeds to launch containers previously configured with --restart. This causes Docker to tell Sysbox to start the container. In some cases however, Sysbox sends a query back to Docker asking for some info about the container. Turns out that Docker is not responding to that query, because it's waiting for the restarted containers to come up. Sysbox waits for the response forever (which is a bug), which in turn causes Docker to never restart the containers (since its waiting on Sysbox to do so).

When the hang occurs, one can see that sysbox-runc (which is normally an ephemeral process) is stuck:

root@ct-ubu-focal:/home/vagrant# ps -fu root | grep docker                                                                                                                                                                                                                                                                    
root         822       1  0 06:46 ?        00:00:09 /usr/bin/dockerd -H fd:// --containerd=/run/containerd/containerd.sock                                                                                                                                                                                                    
root        1051    1041  0 06:47 ?        00:00:01 /usr/local/sbin/sysbox-runc --root /var/run/docker/runtime-runc/moby --log /run/containerd/io.containerd.runtime.v2.task/moby/8db2e73210060e5e3b1aac519e1be557bfee1a9bc1f12cbc6f90e4471bf850b5/log.json --log-format json create --bundle /run/containerd/io.containerd.r$
root        1982    1889  0 17:35 pts/0    00:00:00 grep --color=auto docker   

If I manually kill the sysbox-runc process, then Docker resumes its normal operation (though the restart containers fail to come up).

I will dig deeper to look for a solution.

[ctalledo]

So in summary we have two bugs here:

1. The Sysbox systemd service should be configured to start Sysbox before Docker. This is a bug in the Sysbox installer.

2. We need to break the cyclic dependency between sysbox-runc and Docker for containers configured with --restart. This is a bug in sysbox-runc.

I'll work on fixing both of these.

[jfmontanaro]

@ctalledo Fascinating stuff, thanks so much for looking into it! I really appreciate your quick and thorough response.

Really enjoying Sysbox so far, BTW. Aside from this it's been very smooth. Very nice to have a solution for docker-in-docker that a) doesn't require privileged mode and b) avoids some of the performance pitfalls of previous docker-in-docker solutions. Before I discovered sysbox I was thinking I'd have to run a fat VM for my CI builds, which would have been both far more resource-intensive and much more annoying to manage. So thanks! :)

[ctalledo]

@jfmontanaro, really good to hear, thanks for the feedback. CI is one of the top uses of Sysbox currently, exactly for the reason you mentioned: avoiding the VM. FYI, our blog site has a couple of articles on CI with Sysbox (with Jenkins and GitLab).

Glad Sysbox is working smoothly, we write a lot of tests for it. Docker --restart is one thing we had not tried / tested yet, so it's not surprising it did not work as expected.

I'll likely have a fix by tomorrow, but you'll probably need to build from source until we do our next packaged released (towards the end of January). Building from source is very easy (clone the repo and do make sybox). Details are here: https://github.com/nestybox/sysbox/blob/master/docs/developers-guide/build.md

[ctalledo]

So in summary we have two bugs here:

1. The Sysbox systemd service should be configured to start Sysbox before Docker. This is a bug in the Sysbox installer.
2. We need to break the cyclic dependency between sysbox-runc and Docker for containers configured with --restart. This is a bug in sysbox-runc.

The fix for (2) is out for code-review.

For (1), the fix is still pending. As a temporary work-around, one can edit the systemd service file for Sysbox to look as follows. Notice the "Before=docker.service" and "ExecStart=/usr/bin/sleep 5" lines.

root@ct-ubu-focal:/home/vagrant# cat /lib/systemd/system/sysbox.service
# Sysbox unit to act as a wrapper of sysbox's inner components/daemons:
# sysbox-mgr and sysbox-fs.
[Unit]
Description=Sysbox General Service
After=sysbox-mgr.service sysbox-fs.service
Before=docker.service

[Service]
Type=oneshot
# Execute a dummy program.
# ExecStart=/bin/true
ExecStart=/usr/bin/sleep 5
# Sysbox service shall be considered 'active' after start.
RemainAfterExit=yes

[Install]
# Components of this application should be started at boot time
WantedBy=multi-user.target

[ctalledo]

Hi @jfmontanaro: the fix for problem (2) has been submitted to the Sysbox repo. This means that if you build Sysbox from source you'll now be able to use docker run --runtime=sysbox-runc --restart on the containers.

To get the fix you must:

1. Clone the Sysbox repo
2. Build and install Sysbox

• This will generate the Sysbox binaries and place them at /usr/local/sbin/.
• NOTE: Do not start Sysbox with the scr/sysbox script; use the systemd unit you have (see next step).

4. Edit the Sysbox systemd service unit as described in the prior comment.
5. Ensure all Docker containers that use Sysbox are stopped before doing this.
6. Restart the Sysbox systemd service: sudo systemctl restart sysbox.

At this point you'll have the latest version of Sysbox running, and you can use Docker + Sysbox as usual. The Docker --restart option should work properly.

The next Sysbox release will come with the fix included (both in the Sysbox runtime as well as its systemd service unit file), so you'll just install Sysbox and you are done.

Hope this helps. I'll keep the issue open until we have a proper fix for the Sysbox systemd service unit.

[ctalledo]

FYI: the task remaining is to fix the Sysbox systemd service unit to ensure two things:

• Sysbox starts before Docker and containerd / CRI-O.
• Sysbox notifies systemd that it has initialized properly. Without this, we run the risk of having Docker/containerd start before Sysbox is ready, causing problems.

[jfmontanaro]

@ctalledo Perfect, after building from source and adjusting the service dependencies as you mentioned I am able to run sysbox containers with --restart always with no problems.

One note: The sysbox-mgr and sysbox-fs services both specified After=sysbox.service, which obviously conflicts with that service specifying After=sysbox-mgr.serfice sysbox-fs.service. The result was that those two services just didn't start at all. After removing that directive they started up just fine.

Thanks again for the rapid turnaround on this, I really appreciate it. Very impressed with Sysbox overall and happy to have it in my toolbox. Good luck with the business!

[ctalledo]

Thanks @jfmontanaro , we will take a close look at the Sysbox systemd service files before the upcoming release to make sure all is good.

Thank you very much for catching the problem and filing the issue, and very happy to hear that Sysbox is working well for you.

If there is any other feedback you have as far as use cases or features you need, do let us know please.

Thanks again!

[ctalledo]

This has been fixed in the sysbox repo, and the fix will be present in the upcoming Sysbox release (v0.3.0).

Closing.