nvidia-docker on Azure broken after restart

[adinin]

We run a few machines on Azure with nvidia-docker on them. Instances get restarted overnight (they are used on demand). After starting instances today, we started to experience problems with docker instances (launched with nvidia-docker) not being able to access nvidia drivers.

Running nvidia-smi on host comes back with proper results,

>nvidia-smi
Thu Mar 23 20:22:57 2017
+-----------------------------------------------------------------------------+
| NVIDIA-SMI 375.39                 Driver Version: 375.39                    |
|-------------------------------+----------------------+----------------------+
| GPU  Name        Persistence-M| Bus-Id        Disp.A | Volatile Uncorr. ECC |
| Fan  Temp  Perf  Pwr:Usage/Cap|         Memory-Usage | GPU-Util  Compute M. |
|===============================+======================+======================|
|   0  Tesla K80           Off  | B60C:00:00.0     Off |                    0 |
| N/A   39C    P8    27W / 149W |      0MiB / 11439MiB |      0%      Default |
+-------------------------------+----------------------+----------------------+

+-----------------------------------------------------------------------------+
| Processes:                                                       GPU Memory |
|  GPU       PID  Type  Process name                               Usage      |
|=============================================================================|
|  No running processes found                                                 |
+-----------------------------------------------------------------------------+

Running nvidia-smi inside nvidia/cuda comes back with the following:

>nvidia-docker run --rm nvidia/cuda nvidia-smi
container_linux.go:247: starting container process caused "exec: \"nvidia-smi\": executable file not found in $PATH"
docker: Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "exec: \"nvidia-smi\": executable file not found in $PATH".

We have previously dealt with the issue of nvidia drivers disappearing after restart, but this issue is different due to nvidia-smi working perfectly on host after restart.

We tried removing nvidia-docker, uninstalling nvidia drivers, restarting and installing everything over. That didn't help. Everything was installed according to wiki/azure instructions on this repo.

Appreciate any help you can provide.

[flx42]

What's the log of nvidia-docker? journalctl -n -u nvidia-docker if you are using systemd.

Try also to inspect the volume and see what's in there:

$ ls -R `docker volume inspect -f "{{ .Mountpoint }}" nvidia_driver_375.39`

[adinin]

$ sudo journalctl -n -u nvidia-docker
-- Logs begin at Thu 2017-03-23 20:08:28 UTC, end at Thu 2017-03-23 22:56:03 UTC. --
Mar 23 20:08:50 master0 systemd[1]: Starting NVIDIA Docker plugin...
Mar 23 20:08:50 master0 systemd[1]: Started NVIDIA Docker plugin.
Mar 23 20:08:50 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:50 Loading NVIDIA unified memory
Mar 23 20:08:50 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:50 Loading NVIDIA management library
Mar 23 20:08:54 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:54 Discovering GPU devices
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Provisioning volumes at /var/lib/nvidia-docker/volumes
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Serving plugin API at /var/lib/nvidia-docker
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Serving remote API at localhost:3476
Mar 23 20:09:09 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:09:09 Received activate request
Mar 23 20:09:09 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:09:09 Plugins activated [VolumeDriver]

$ sudo ls -R `docker volume inspect -f "{{ .Mountpoint }}" nvidia_driver_375.39`
/var/lib/docker/volumes/nvidia_driver_375.39/_data:

[flx42]

Somehow the volume was created but it's empty, not sure how it happened, try removing the volume then launch another container:

docker volume rm -f nvidia_driver_375.39
nvidia-docker run --rm nvidia/cuda nvidia-smi

Also, take a look at journalctl -u nvidia-docker (without the -n to get the full log) and check if there is any error.

[adinin]

That helped. Thank you very much!

Interestingly enough, it only worked the second time I did it.

cluster@master0:~$ docker volume rm -f nvidia_driver_375.39
nvidia_driver_375.39
cluster@master0:~$ nvidia-docker run --rm nvidia/cuda nvidia-smi
container_linux.go:247: starting container process caused "exec: \"nvidia-smi\": executable file not found in $PATH"
docker: Error response from daemon: oci runtime error: container_linux.go:247: starting container process caused "exec: \"nvidia-smi\": executable file not found in $PATH".
cluster@master0:~$ sudo journalctl -u nvidia-docker
-- Logs begin at Thu 2017-03-23 20:08:28 UTC, end at Thu 2017-03-23 23:06:55 UTC. --
Mar 23 20:08:50 master0 systemd[1]: Starting NVIDIA Docker plugin...
Mar 23 20:08:50 master0 systemd[1]: Started NVIDIA Docker plugin.
Mar 23 20:08:50 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:50 Loading NVIDIA unified memory
Mar 23 20:08:50 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:50 Loading NVIDIA management library
Mar 23 20:08:54 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:54 Discovering GPU devices
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Provisioning volumes at /var/lib/nvidia-docker/volumes
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Serving plugin API at /var/lib/nvidia-docker
Mar 23 20:08:57 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:08:57 Serving remote API at localhost:3476
Mar 23 20:09:09 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:09:09 Received activate request
Mar 23 20:09:09 master0 nvidia-docker-plugin[1310]: /usr/bin/nvidia-docker-plugin | 2017/03/23 20:09:09 Plugins activated [VolumeDriver]
cluster@master0:~$ sudo ls -R `docker volume inspect -f "{{ .Mountpoint }}" nvidia_driver_375.39`
/var/lib/docker/volumes/nvidia_driver_375.39/_data:
cluster@master0:~$ docker volume rm -f nvidia_driver_375.39
nvidia_driver_375.39
cluster@master0:~$ nvidia-docker run --rm nvidia/cuda nvidia-smi
Thu Mar 23 23:09:43 2017
+-----------------------------------------------------------------------------+
| NVIDIA-SMI 375.39                 Driver Version: 375.39                    |
|-------------------------------+----------------------+----------------------+
| GPU  Name        Persistence-M| Bus-Id        Disp.A | Volatile Uncorr. ECC |
| Fan  Temp  Perf  Pwr:Usage/Cap|         Memory-Usage | GPU-Util  Compute M. |
|===============================+======================+======================|
|   0  Tesla K80           Off  | B60C:00:00.0     Off |                    0 |
| N/A   39C    P8    26W / 149W |      0MiB / 11439MiB |      0%      Default |
+-------------------------------+----------------------+----------------------+

+-----------------------------------------------------------------------------+
| Processes:                                                       GPU Memory |
|  GPU       PID  Type  Process name                               Usage      |
|=============================================================================|
|  No running processes found                                                 |
+-----------------------------------------------------------------------------+

[3XX0]

Can you include the docker logs as well?

This is weird, you should see the mount requests in the nvidia-docker-plugin logs.
There is only one nvidia-docker-plugin running on the machine right?

[adinin]

Looks like there is only one running

$ ps aux | grep nvidia-docker-plugin
nvidia-+   1310  0.0  0.0 80084252 21340 ?      Ssl  Mar23   0:04 /usr/bin/nvidia-docker-plugin -s /var/lib/nvidia-docker

$ sudo journalctl -n -u nvidia-docker output is pasted above. Are there other things you wanted me to run to provide you with more information?

[flx42]

Above is the log for nvidia-docker, @3XX0 was asking the log for docker, they are different services.
So: journalctl -u docker

[adinin]

Thanks for clarifying @flx42

It doesn't look like I have logs from previous boots. I have the following logs, but they are probably pretty useless because machine was shutdown overnight. Everything is working on this boot, so these logs don't really correspond with the time when we experienced the problem.

If I will be able to recreate the problem, I will happily add more to this thread.

$ sudo journalctl -u docker
-- Logs begin at Fri 2017-03-24 14:24:41 UTC, end at Fri 2017-03-24 15:11:45 UTC. --
Mar 24 14:25:12 master0 systemd[1]: Starting Docker Application Container Engine...
Mar 24 14:25:15 master0 dockerd[1345]: time="2017-03-24T14:25:15.405308066Z" level=info msg="libcontainerd: new containerd process, pid: 1721"
Mar 24 14:25:16 master0 dockerd[1345]: time="2017-03-24T14:25:16.916512587Z" level=info msg="[graphdriver] using prior storage driver: aufs"
Mar 24 14:25:58 master0 dockerd[1345]: time="2017-03-24T14:25:58.101213572Z" level=info msg="Graph migration to content-addressability took 0.00 seconds"
Mar 24 14:25:58 master0 dockerd[1345]: time="2017-03-24T14:25:58.101412773Z" level=warning msg="Your kernel does not support swap memory limit"
Mar 24 14:25:58 master0 dockerd[1345]: time="2017-03-24T14:25:58.101461848Z" level=warning msg="Your kernel does not support cgroup rt period"
Mar 24 14:25:58 master0 dockerd[1345]: time="2017-03-24T14:25:58.101471043Z" level=warning msg="Your kernel does not support cgroup rt runtime"
Mar 24 14:25:58 master0 dockerd[1345]: time="2017-03-24T14:25:58.101872343Z" level=info msg="Loading containers: start."
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.592620250Z" level=warning msg="libcontainerd: client is out of sync, restore was called on a fully synced container (1e0e324de7fc1539fd079b
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.592846137Z" level=warning msg="libcontainerd: failed to retrieve container 1e0e324de7fc1539fd079be0bd047172db92caebaff4a62aa147e9118ce4f37c
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.592903708Z" level=warning msg="failed to cleanup ipc mounts:\nfailed to umount /var/lib/docker/containers/1e0e324de7fc1539fd079be0bd047172d
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.856658465Z" level=warning msg="libcontainerd: client is out of sync, restore was called on a fully synced container (bcfb20740e239531889353
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.856869259Z" level=warning msg="libcontainerd: failed to retrieve container bcfb20740e239531889353dad75e641e23b549de5feca20f6a1175f5b31b2c5e
Mar 24 14:26:32 master0 dockerd[1345]: time="2017-03-24T14:26:32.856932827Z" level=warning msg="failed to cleanup ipc mounts:\nfailed to umount /var/lib/docker/containers/bcfb20740e239531889353dad75e641e2
Mar 24 14:26:33 master0 dockerd[1345]: time="2017-03-24T14:26:33.028044529Z" level=warning msg="libcontainerd: client is out of sync, restore was called on a fully synced container (31ab5f30612a55136ffcc3
Mar 24 14:26:33 master0 dockerd[1345]: time="2017-03-24T14:26:33.028445528Z" level=warning msg="libcontainerd: failed to retrieve container 31ab5f30612a55136ffcc3cc6de05b0db17a3ae7a02a364775479ad721517057
Mar 24 14:26:33 master0 dockerd[1345]: time="2017-03-24T14:26:33.028509796Z" level=warning msg="failed to cleanup ipc mounts:\nfailed to umount /var/lib/docker/containers/31ab5f30612a55136ffcc3cc6de05b0db
Mar 24 14:26:33 master0 dockerd[1345]: time="2017-03-24T14:26:33.908694983Z" level=info msg="Firewalld running: false"
Mar 24 14:26:34 master0 dockerd[1345]: time="2017-03-24T14:26:34.817742432Z" level=info msg="Default bridge (docker0) is assigned with an IP address 172.17.0.0/16. Daemon option --bip can be used to set a
Mar 24 14:26:49 master0 dockerd[1345]: time="2017-03-24T14:26:49.996199636Z" level=error msg="Failed to start container 49b1ba56edaec12356c448ec15f9447292deed18a659d904092ae7927fa6f010: get nvidia_driver_
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.230532011Z" level=error msg="Failed to start container 31ab5f30612a55136ffcc3cc6de05b0db17a3ae7a02a364775479ad721517057: get nvidia_driver_
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.308512301Z" level=error msg="Failed to start container 1e0e324de7fc1539fd079be0bd047172db92caebaff4a62aa147e9118ce4f37c: get nvidia_driver_
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.376862409Z" level=error msg="Failed to start container bcfb20740e239531889353dad75e641e23b549de5feca20f6a1175f5b31b2c5e: get nvidia_driver_
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.512069771Z" level=error msg="Failed to start container 0c94bd6654ed2c475f1d39b6c1da3072d4361bb59316530c6204255401a2f864: get nvidia_driver_
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.513171121Z" level=error msg="get nvidia_driver_375.39: volume not found"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.513254579Z" level=error msg="get nvidia_driver_375.39: volume not found"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.513746833Z" level=error msg="get nvidia_driver_375.39: volume not found"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.513965223Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.514241185Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.514465973Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.514717347Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.514912449Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.515096957Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.515303554Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.515500455Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.515699256Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.515884763Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516064373Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516246982Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516473269Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516650580Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516820695Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.516993308Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.517183014Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.517372219Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"
Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.517548631Z" level=error msg="get nvidia_driver_375.26: no such volume: nvidia_driver_375.26"

[flx42]

I would guess the error occurred on your machine after the upgrade of the driver package nvidia-375 by Canonical. You should be safe until a new driver version, but I'm still not certain how this happened anyway.

Your log above is truncated:

Mar 24 14:26:50 master0 dockerd[1345]: time="2017-03-24T14:26:50.512069771Z" level=error msg="Failed to start container 0c94bd6654ed2c475f1d39b6c1da3072d4361bb59316530c6204255401a2f864: get nvidia_driver_

[dashesy]

This broke our setup too. It was a security update, which is a good idea to enable but has to for now disable all updates on the server!! Any plans to upstream the driver to the kernel? This looks like a hack not comfortable to use in any production environment.

[flx42]

@dashesy I don't see how upstreaming the driver to the kernel is relevant here. This was an official driver update from Canonical.
Also, since I don't have a repro (I tried a few upgrades, without success), I'm not sure what caused the issue here: a bug in the driver packaging, a bug in Docker, or a bug in nvidia-docker. It's probably not caused by the driver itself.

[dashesy]

In case it might help: Also some of the machines with Ubuntu (no docker) stopped working (nvidia-smi returned nothing). Then I rebooted them and they worked. Considering that it was a security update (minor version) it was not expected.