bug#34333: Docker daemon failing to start on boot

[Allan Adair <allan@adair.io>]

Hi Danny. With great excitement I edited my config.scm to include kmod,
ran guix system reconfigure, and rebooted my machine. Unfortunately my
changes did not seem to fix the issue. I hope the session below can help
us further. Thanks so much for working on this issue.

allana@guixsd ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the docker daemon running?
allana@guixsd ~$ cat /var/log/docker.log 
time="2019-03-18T14:39:59.788932321+01:00" level=warning msg="Error while setting daemon root propagation, this is not generally critical but may cause some functionality to not work or fallback to less desirable behavior" dir=/var/lib/docker error="error writing file to signal mount cleanup on shutdown: open /var/run/docker/unmount-on-shutdown: no such file or directory"
time="2019-03-18T14:39:59.797964377+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:39:59.797982675+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:39:59.798127164+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:39:59.798220831+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:39:59.798291248+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000771980, CONNECTING" module=grpc
time="2019-03-18T14:39:59.800603937+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc000771980, READY" module=grpc
time="2019-03-18T14:39:59.801234292+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:39:59.801254794+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:39:59.801329244+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:39:59.801366954+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:39:59.801507445+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000d79d0, CONNECTING" module=grpc
time="2019-03-18T14:39:59.802331100+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000d79d0, READY" module=grpc
time="2019-03-18T14:39:59.815614194+01:00" level=error msg="'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded." storage-driver=overlay2
time="2019-03-18T14:39:59.815664314+01:00" level=error msg="[graphdriver] prior storage driver overlay2 failed: driver not supported"
Error starting daemon: error initializing graphdriver: driver not supported
allana@guixsd ~$ cat /etc/config.scm
(use-modules (gnu)
             (gnu system nss)
	     (gnu services))
(use-service-modules desktop docker)
(use-package-modules certs gnome linux)

(operating-system
 (host-name "guixsd")
 (timezone "Europe/Oslo")
 (locale "en_US.utf8")

  (bootloader (bootloader-configuration
               (bootloader grub-bootloader)
               (target "/dev/sda")))

  (file-systems (cons (file-system
		       (device (file-system-label "my-root"))
		       (mount-point "/")
		       (type "ext4"))
                      %base-file-systems))

  (users (cons (user-account
                (name "allana")
                (group "users")
                (supplementary-groups '("wheel"
					"docker"
					"netdev"
                                        "audio"
					"video"))
                (home-directory "/home/allana"))
               %base-user-accounts))

  ;; This is where we specify system-wide packages.
  (packages (cons* nss-certs         ;for HTTPS access
                   gvfs              ;for user mounts
		   kmod              ;for modprobe/dockerd
                   %base-packages))

  (services (cons* (console-keymap-service "no-latin1")
                   (gnome-desktop-service)
		   (service docker-service-type)
                   %desktop-services))

  ;; Allow resolution of '.local' host names with mDNS.
  (name-service-switch %mdns-host-lookup-nss))
allana@guixsd ~$ sudo herd start dockerd
Password: 
Service dockerd could not be started.
herd: failed to start service dockerd
allana@guixsd ~$ sudo guix system reconfigure /etc/config.scm > /dev/null 2>&1
allana@guixsd ~$ docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES
allana@guixsd ~$ cat /var/log/docker.log 
time="2019-03-18T14:43:00.850449641+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:43:00.850524161+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:43:00.850623186+01:00" level=info msg="parsed scheme: \"unix\"" module=grpc
time="2019-03-18T14:43:00.850638306+01:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
time="2019-03-18T14:43:00.850682621+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:43:00.850705685+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:43:00.850749857+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000496e0, CONNECTING" module=grpc
time="2019-03-18T14:43:00.850880352+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000496e0, READY" module=grpc
time="2019-03-18T14:43:00.851069787+01:00" level=info msg="ccResolverWrapper: sending new addresses to cc: [{unix:///run/containerd/containerd.sock 0  <nil>}]" module=grpc
time="2019-03-18T14:43:00.851088244+01:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
time="2019-03-18T14:43:00.851153314+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000499d0, CONNECTING" module=grpc
time="2019-03-18T14:43:00.851266607+01:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0000499d0, READY" module=grpc
time="2019-03-18T14:43:00.874110624+01:00" level=info msg="[graphdriver] using prior storage driver: overlay2"
time="2019-03-18T14:43:01.002014039+01:00" level=info msg="Graph migration to content-addressability took 0.00 seconds"
time="2019-03-18T14:43:01.002217610+01:00" level=warning msg="Your kernel does not support swap memory limit"
time="2019-03-18T14:43:01.002293632+01:00" level=warning msg="Your kernel does not support cgroup rt period"
time="2019-03-18T14:43:01.002307271+01:00" level=warning msg="Your kernel does not support cgroup rt runtime"
time="2019-03-18T14:43:01.002318768+01:00" level=warning msg="Your kernel does not support cgroup blkio weight"
time="2019-03-18T14:43:01.002328780+01:00" level=warning msg="Your kernel does not support cgroup blkio weight_device"
time="2019-03-18T14:43:01.002447782+01:00" level=warning msg="mountpoint for pids not found"
time="2019-03-18T14:43:01.002919567+01:00" level=info msg="Loading containers: start."
time="2019-03-18T14:43:01.596297744+01:00" 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 preferred IP address"
time="2019-03-18T14:43:01.664423600+01:00" level=info msg="Loading containers: done."
time="2019-03-18T14:43:01.672193823+01:00" level=warning msg="Could not get operating system name: Error opening /usr/lib/os-release: open /usr/lib/os-release: no such file or directory"
time="2019-03-18T14:43:01.735588173+01:00" level=warning msg="failed to retrieve /gnu/store/fxmfknby00xva6jlz3m4pjj2jyj2xxiw-runc-1.0.0-rc6/sbin/runc version: unknown output format: runc version 1.0.0-rc6\nspec: 1.0.1-dev\n"
time="2019-03-18T14:43:01.747943901+01:00" level=warning msg="failed to retrieve docker-init version: exec: \"docker-init\": executable file not found in $PATH"
time="2019-03-18T14:43:01.901777278+01:00" level=info msg="Docker daemon" commit=v18.09.3 graphdriver(s)=overlay2 version=dev
time="2019-03-18T14:43:01.911529576+01:00" level=info msg="Daemon has completed initialization"
time="2019-03-18T14:43:01.918913081+01:00" level=info msg="API listen on /var/run/docker.sock"


Danny Milosavljevic writes:

> Hi Allan,
>
> thanks for the logs!
>
> I've found the problem now.
>
> daemon/graphdriver/overlay2/overlay.go:
>
> func supportsOverlay() error {
>         // We can try to modprobe overlay first before looking at
>         // proc/filesystems for when overlay is supported
>         exec.Command("modprobe", "overlay").Run()
>
>         f, err := os.Open("/proc/filesystems")
>         if err != nil {
>                 return err
>         }
>         defer f.Close()
>
>         s := bufio.NewScanner(f)
>         for s.Scan() {
>                 if s.Text() == "nodev\toverlay" {
>                         return nil
>                 }
>         }
>         logrus.WithField("storage-driver", "overlay2").Error("'overlay' not found as a supported filesystem on this host. Please ensure kernel is new enough and has overlay support loaded.")
>         return graphdriver.ErrNotSupported
> }
>
> We don't load "overlay" explicitly.  The above is some weird contraption--loading kernel modules from random user space programs.  Seriously?
>
> And I suspect that modprobe is not found in your system profile.
>
> As a workaround, try adding "kmod" to the list of packages in your operating-system in your system configuration and reconfigure.
>
> But the real fix is for Docker to stop doing this weird thing in the first place.  Nowadays, modules are autoloaded when someone is accessing the thing (by udev, or just by using it etc).  
>
> In this case, they do
>
>         if err := mount("overlay", mountTarget, "overlay", 0, mountData); err != nil {
>
> later on.  And that's how it should have been detecting it, too.


-- 
Allan Adair
http://allan.adair.io