From mboxrd@z Thu Jan 1 00:00:00 1970 From: Allan Adair Subject: bug#34333: Docker daemon failing to start on boot Date: Mon, 18 Mar 2019 14:47:48 +0100 Message-ID: <87zhps47ln.fsf@adair.io> References: <26bbaae65fb9ab18036684e9f676ac1e@adair.io> <87pns2vtaz.fsf@gnu.org> <20190211114651.2b32e555@scratchpost.org> <20190211183155.30861768@scratchpost.org> <8a67633984fd5547e69b09fff29223ba@adair.io> <20190212184517.77edfb58@scratchpost.org> <87imx5gvth.fsf@adair.io> <20190227165327.72fc918e@alma-ubu> <20190227163121.GA17110@jurong> <87pnrbotsj.fsf@adair.io> <20190301130932.GA1867@jurong> <20190301144324.75b81902@alma-ubu> <87d0na3dqo.fsf@adair.io> <20190301185944.550d0ee7@scratchpost.org> <87imwpeqhk.fsf@adair.io> <20190312204704.1d74475a@scratchpost.org> <87pnqoh46g.fsf@adair.io> <20190318115303.2c543d1d@scratchpost.org> Mime-Version: 1.0 Content-Type: text/plain Return-path: Received: from eggs.gnu.org ([209.51.188.92]:46939) by lists.gnu.org with esmtp (Exim 4.71) (envelope-from ) id 1h5sdU-0003zx-Kw for bug-guix@gnu.org; Mon, 18 Mar 2019 09:49:06 -0400 Received: from Debian-exim by eggs.gnu.org with spam-scanned (Exim 4.71) (envelope-from ) id 1h5sdS-00073K-QH for bug-guix@gnu.org; Mon, 18 Mar 2019 09:49:04 -0400 Received: from debbugs.gnu.org ([209.51.188.43]:34668) by eggs.gnu.org with esmtps (TLS1.0:RSA_AES_128_CBC_SHA1:16) (Exim 4.71) (envelope-from ) id 1h5sdS-00072w-C2 for bug-guix@gnu.org; Mon, 18 Mar 2019 09:49:02 -0400 Received: from Debian-debbugs by debbugs.gnu.org with local (Exim 4.84_2) (envelope-from ) id 1h5sdS-00017g-7D for bug-guix@gnu.org; Mon, 18 Mar 2019 09:49:02 -0400 Sender: "Debbugs-submit" Resent-Message-ID: In-reply-to: <20190318115303.2c543d1d@scratchpost.org> List-Id: Bug reports for GNU Guix List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: bug-guix-bounces+gcggb-bug-guix=m.gmane.org@gnu.org Sender: "bug-Guix" To: Danny Milosavljevic Cc: 34333@debbugs.gnu.org, 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. 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 }]" 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 }]" 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 }]" 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 }]" 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