bug#34333: Docker daemon failing to start on boot

[Allan Adair]

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.

address@hidden ~$ docker ps
Cannot connect to the Docker daemon at unix:///var/run/docker.sock. Is the 
docker daemon running?
address@hidden ~$ 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
address@hidden ~$ 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))
address@hidden ~$ sudo herd start dockerd
Password: 
Service dockerd could not be started.
herd: failed to start service dockerd
address@hidden ~$ sudo guix system reconfigure /etc/config.scm > /dev/null 2>&1
address@hidden ~$ docker ps
CONTAINER ID        IMAGE               COMMAND             CREATED             
STATUS              PORTS               NAMES
address@hidden ~$ 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