Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

DietPi-Software | Docker APT failure after kernel upgrade #3126

Closed
theAkito opened this issue Sep 23, 2019 · 15 comments
Closed

DietPi-Software | Docker APT failure after kernel upgrade #3126

theAkito opened this issue Sep 23, 2019 · 15 comments
Labels
Milestone

Comments

@theAkito
Copy link

theAkito commented Sep 23, 2019

Creating a bug report/issue

Required Information

  • DietPi version:
G_DIETPI_VERSION_CORE=6
G_DIETPI_VERSION_SUB=25
G_DIETPI_VERSION_RC=3
G_GITBRANCH='master'
G_GITOWNER='MichaIng'
  • Distro version
buster 10.1
  • Kernel version
Linux hostname 4.19.66-v7l+ #1253 SMP Thu Aug 15 12:02:08 BST 2019 armv7l GNU/Linux
  • SBC device
RPi 4 Model B (armv7l)
  • Power supply used
5V 3A (not fake)
  • SDcard used
microSD Transcend 300S

Additional Information (if applicable)

  • Software title: docker-ce
  • Was the software title installed freshly or updated/migrated? Yes.
  • Can this issue be replicated on a fresh installation of DietPi? Yes.
  • Bug report ID | sed -n 5p /DietPi/dietpi/.hw_model

Steps to reproduce

Set dietpi.txt to install Docker for you.

Expected behaviour

Installation of docker-ce.

Actual behaviour

Installation loop during first boot of automated set up of DietPi prevents system from working.
The docker service fails to start after installation. (common issue)

Extra details

The issue with the docker service itself is common and usually easily fixable, by stopping and starting the service manually, but it is definitely not ideal to interrupt the first boot of DietPi when it tries to set up the system, before the first login.

@MichaIng
Copy link
Owner

@Akito13
Many thanks for your report.

Hmm, I just tested the Docker install on VM and did not run into any APT/dpkg error. Which device + distro version did you try this on?

Generally I aim to add some "Open shell to investigate/fix issue" option to our error prompt. Until then you can always simply open an additional TTY or SSH session, fix the issue there, and hit retry.

@theAkito
Copy link
Author

@MichaIng
Thanks for your response.

Well, I usually reboot the device and then hit CTRL+C at the time the error occurs. This is not ideal though, because it requires manual intervention, which is especially unpractical if you require the device to be set up automatically by the DietPi first boot script. I had to attach an extra monitor and change circumstances in my setup, to be able to fix the issue manually offline.

open an additional TTY or SSH session

If that would've been possible, the described issue would've been child's play for me. The fun stops when I can't SSH into a machine, at all.

Which device + distro version did you try this on?

I wasn't able to fill in the information at the time of writing the report, as I could not access the system, yet. I will add them now and you can check out the OP to see the results.

@MichaIng
Copy link
Owner

@Akito13
If you cannot SSH during a dietpi-software install (where network connectivity is assured already), then there is something else broken which would need investigation. Regardless it makes sense to check why Docker service is failing in the first place.

Okay RPi4 Buster. We did some fix back and forth since the official Docker installer first did not support Buster at all, then not Raspbian Buster, then no ARMv6 RPi models etc 😄. But that is all fixed now AFAIK, and as well the current DietPi master code does correct check to apply a workaround only if required, just verified that.

Will run some test on RPi2 Buster, if you can capture the error log you faced, that would be awesome.

@theAkito
Copy link
Author

if you can capture the error log you faced, that would be awesome.

It might be possible that I do a test installation with the same dietpi.txt on the same device. I will need to look into that.

We did some fix back and forth

Yes, I remember.

If you cannot SSH during
then there is something else broken

Yes, usually I can SSH during an installation but this time the device did not connect to my router (i.e. not visible on the router's web interface), at all, even though I had a LAN cable connected and I enabled LAN within dietpi.txt (i.e. it was already enabled).

@MichaIng
Copy link
Owner

@Akito13
Since DietPi whiptail dialogs contain the local IP as background title and the device itself has obviously network connectivity (APT installs, time sync etc run fine), then you should still be able to SSH.

Based on router settings and whether DHCP or static IP is used I as well see my devices sometimes not in the online list of the router, or not listed at all, even they are definite there with network access and SSH working well. If the router really somehow allows outgoing requests for these devices but block inbound requests from within local network, then this would be a strange and false router setup.

@theAkito
Copy link
Author

theAkito commented Sep 26, 2019

@MichaIng

APT installs

Ah right, completely forgot about that.

The thing is, if there is any type of connectivity, then all devices I ever used immediately show up in the router's list. Even if they aren't actually connected to the internet, or what else. If they are connected to the router and powered on, they are always shown. Additionally, I am always able to at least try to establish an SSH connection. This time though, it was like the device did not even exist. SSH gave me an error saying something like that, whereas usually if something goes wrong, it acknowledges the device, but refuses to connect.
This is some strange behaviour and it is not replicated. This happened only during this installation and never before.

block inbound requests from within local network, then this would be a strange and false router setup.

I doubt there is something wrong with the router, because all the other devices work as always and as expected and I have never seen such behaviour before. As I said, it has to at least be shown in the router's list and the device has to be at least knockable. That's how all other devices behaved I ever connected to that router.

@MichaIng
Copy link
Owner

Okay, it is a separate topic anyway. Just keep in mind that those router lists do not always show all attached devices correctly. The router DHCP might refuse to assign the expected IP, if some entry with different hostname or MAC already exist or for other reasons, or due to some doubled values, one hides the other one. These are finally array entries as well that can double, one overriding each other etc, what I have seen and manually created on Fritz!Box routers e.g 😉. So you can only know for sure when checking the apparent IP from the device itself and try to ping or SSH that.

However lets concentrate on the Docker issue now, I hope I find time today night for the test.

@theAkito
Copy link
Author

theAkito commented Sep 26, 2019

@MichaIng

Out of curiousity I ran the same image with all the same settings, except the network connection, as I had to change to Wi-Fi, on the Raspberry Pi 3 A+. The device is immediately shown in the router's list as the new DietPi device and upgrading through APT worked flawlessly....

...except the docker-ce installation.


It is looping and repeating this error message infinitely.

@MichaIng
Copy link
Owner

@Akito13
To further investigate the service start: journalctl -u docker

I just rechecked the open issues on Docker GitHub about Raspbian Buster. There was one reported issue similar to yours, although details logs are missing: docker/for-linux#709 (comment)
But later with current version people report this being fixed for RPi3+4 at least 🤔.

@MichaIng MichaIng changed the title "invoke-rc.d: inistscript docker, action start failed." creates loop during first boot DietPi-Software | Docker APT install fails on Raspbian Buster Sep 26, 2019
@theAkito
Copy link
Author

o further investigate the service start: journalctl -u docker

After SSHing:

-- Logs begin at Thu 2019-02-14 11:12:00 CET, end at Thu 2019-09-26 19:02:49 CEST. --
Sep 26 17:48:45 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.795194711+02:00" level=info msg="Starting up"
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.800075597+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.800209347+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.800321378+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.800432784+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:48:45 DietPi dockerd[5697]: time="2019-09-26T17:48:45.800656274+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x54fc850, CONNECTING" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.812610597+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x54fc850, READY" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.818993722+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.819160128+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.819291430+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.819388461+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.819685388+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5a0f1c0, CONNECTING" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.821489763+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5a0f1c0, READY" module=grpc
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.838690128+02: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
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.852422524+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 17:48:46 DietPi dockerd[5697]: time="2019-09-26T17:48:45.865860440+02: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=overlay
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.196139867+02:00" level=warning msg="Your kernel does not support swap memory limit"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.196255336+02:00" level=warning msg="Your kernel does not support cgroup cfs period"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.196297263+02:00" level=warning msg="Your kernel does not support cgroup cfs quotas"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.196338305+02:00" level=warning msg="Your kernel does not support cgroup rt period"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.196377367+02:00" level=warning msg="Your kernel does not support cgroup rt runtime"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.197126273+02:00" level=info msg="Loading containers: start."
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.212263565+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.226118200+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.239925596+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.290465232+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.614169659+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
Sep 26 17:48:47 DietPi dockerd[5697]: time="2019-09-26T17:48:47.614973669+02:00" level=info msg="stopping event stream following graceful shutdown" error="context canceled" module=libcontainerd namespace=plugins.moby
Sep 26 17:48:47 DietPi dockerd[5697]: failed to start daemon: Error initializing network controller: error obtaining controller instance: failed to create NAT chain DOCKER: iptables failed: iptables -t nat -N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported
Sep 26 17:48:47 DietPi dockerd[5697]:  (exit status 1)
Sep 26 17:48:47 DietPi systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 17:48:47 DietPi systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 17:48:47 DietPi systemd[1]: Failed to start Docker Application Container Engine.
Sep 26 17:48:49 DietPi systemd[1]: docker.service: Service RestartSec=2s expired, scheduling restart.
Sep 26 17:48:49 DietPi systemd[1]: docker.service: Scheduled restart job, restart counter is at 1.
Sep 26 17:48:49 DietPi systemd[1]: Stopped Docker Application Container Engine.
Sep 26 17:48:49 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.976010856+02:00" level=info msg="Starting up"
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.982885074+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.983026064+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.983152522+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.983221220+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.983536897+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x52087d0, CONNECTING" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.985590595+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x52087d0, READY" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.998538876+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.998723251+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.998867001+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.999054293+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:48:49 DietPi dockerd[5803]: time="2019-09-26T17:48:49.999422418+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5208a10, CONNECTING" module=grpc
Sep 26 17:48:50 DietPi dockerd[5803]: time="2019-09-26T17:48:50.003665439+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5208a10, READY" module=grpc
Sep 26 17:48:50 DietPi dockerd[5803]: time="2019-09-26T17:48:50.029161949+02: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
Sep 26 17:48:50 DietPi dockerd[5803]: time="2019-09-26T17:48:50.045416585+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 17:48:50 DietPi dockerd[5803]: time="2019-09-26T17:48:50.061024293+02: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=overlay
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.185871116+02:00" level=warning msg="Your kernel does not support swap memory limit"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.187563043+02:00" level=warning msg="Your kernel does not support cgroup cfs period"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.188124397+02:00" level=warning msg="Your kernel does not support cgroup cfs quotas"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.188527938+02:00" level=warning msg="Your kernel does not support cgroup rt period"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.188971480+02:00" level=warning msg="Your kernel does not support cgroup rt runtime"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.190158303+02:00" level=info msg="Loading containers: start."
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.207947522+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.224587522+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.240791220+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.280082886+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:48:51 DietPi dockerd[5803]: time="2019-09-26T17:48:51.631923615+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
Sep 26 17:48:51 DietPi dockerd[5803]: failed to start daemon: Error initializing network controller: error obtaining controller instance: failed to create NAT chain DOCKER: iptables failed: iptables -t nat -N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported
Sep 26 17:48:51 DietPi dockerd[5803]:  (exit status 1)
Sep 26 17:48:51 DietPi systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 17:48:51 DietPi systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 17:48:51 DietPi systemd[1]: Failed to start Docker Application Container Engine.
Sep 26 17:48:53 DietPi systemd[1]: docker.service: Service RestartSec=2s expired, scheduling restart.
Sep 26 17:48:53 DietPi systemd[1]: docker.service: Scheduled restart job, restart counter is at 2.
Sep 26 17:48:53 DietPi systemd[1]: Stopped Docker Application Container Engine.
Sep 26 17:48:53 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:48:54 DietPi dockerd[5866]: time="2019-09-26T17:48:54.044375958+02:00" level=info msg="Starting up"
Sep 26 17:48:59 DietPi dockerd[5866]: time="2019-09-26T17:48:59.598293664+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.600164394+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.600419550+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.600583925+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.600982727+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x44a8c40, CONNECTING" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.613373560+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x44a8c40, READY" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.619328248+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.619449498+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.619560279+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.619626164+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.620116737+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x48e6000, CONNECTING" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.621269498+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x48e6000, READY" module=grpc
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.636184446+02: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
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.648985279+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 17:49:00 DietPi dockerd[5866]: time="2019-09-26T17:48:59.661479914+02: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=overlay
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.054457622+02:00" level=warning msg="Your kernel does not support swap memory limit"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.054580174+02:00" level=warning msg="Your kernel does not support cgroup cfs period"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.054625538+02:00" level=warning msg="Your kernel does not support cgroup cfs quotas"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.054668507+02:00" level=warning msg="Your kernel does not support cgroup rt period"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.054708143+02:00" level=warning msg="Your kernel does not support cgroup rt runtime"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.055655591+02:00" level=info msg="Loading containers: start."
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.079388143+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.105059132+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.119521372+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.172518507+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:49:02 DietPi dockerd[5866]: time="2019-09-26T17:49:02.492666997+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
Sep 26 17:49:02 DietPi dockerd[5866]: failed to start daemon: Error initializing network controller: error obtaining controller instance: failed to create NAT chain DOCKER: iptables failed: iptables -t nat -N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported
Sep 26 17:49:02 DietPi dockerd[5866]:  (exit status 1)
Sep 26 17:49:02 DietPi systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 17:49:02 DietPi systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 17:49:02 DietPi systemd[1]: Failed to start Docker Application Container Engine.
Sep 26 17:49:04 DietPi systemd[1]: docker.service: Service RestartSec=2s expired, scheduling restart.
Sep 26 17:49:04 DietPi systemd[1]: docker.service: Scheduled restart job, restart counter is at 3.
Sep 26 17:49:04 DietPi systemd[1]: Stopped Docker Application Container Engine.
Sep 26 17:49:04 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.761922621+02:00" level=info msg="Starting up"
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.766684600+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.766822985+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.766943194+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.767027985+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.767257881+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5d17380, CONNECTING" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.778181058+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5d17380, READY" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.784747621+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.784879965+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.784984131+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.785048871+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.785327725+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5d16030, CONNECTING" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.785383402+02:00" level=info msg="blockingPicker: the picked transport is not ready, loop back to repick" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.787047256+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x5d16030, READY" module=grpc
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.802957829+02: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
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.816014444+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 17:49:04 DietPi dockerd[5960]: time="2019-09-26T17:49:04.829683871+02: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=overlay
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.178781319+02:00" level=warning msg="Your kernel does not support swap memory limit"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.178892152+02:00" level=warning msg="Your kernel does not support cgroup cfs period"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.178933819+02:00" level=warning msg="Your kernel does not support cgroup cfs quotas"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.178972985+02:00" level=warning msg="Your kernel does not support cgroup rt period"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.179011839+02:00" level=warning msg="Your kernel does not support cgroup rt runtime"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.179767516+02:00" level=info msg="Loading containers: start."
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.194432933+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.208132516+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.220933558+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.254291006+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:49:05 DietPi dockerd[5960]: time="2019-09-26T17:49:05.551204548+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
Sep 26 17:49:05 DietPi dockerd[5960]: failed to start daemon: Error initializing network controller: error obtaining controller instance: failed to create NAT chain DOCKER: iptables failed: iptables -t nat -N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported
Sep 26 17:49:05 DietPi dockerd[5960]:  (exit status 1)
Sep 26 17:49:05 DietPi systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 17:49:05 DietPi systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 17:49:05 DietPi systemd[1]: Failed to start Docker Application Container Engine.
Sep 26 17:49:07 DietPi systemd[1]: docker.service: Service RestartSec=2s expired, scheduling restart.
Sep 26 17:49:07 DietPi systemd[1]: docker.service: Scheduled restart job, restart counter is at 4.
Sep 26 17:49:07 DietPi systemd[1]: Stopped Docker Application Container Engine.
Sep 26 17:49:07 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.781811838+02:00" level=info msg="Starting up"
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.788067099+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.788258453+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.788387151+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.788474599+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.788853765+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x580f1d0, CONNECTING" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.813676995+02:00" level=info msg="blockingPicker: the picked transport is not ready, loop back to repick" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.845060328+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x580f1d0, READY" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.861777307+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.861939963+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.862116161+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.862207776+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.862498817+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x590e1f0, CONNECTING" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.873201213+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0x590e1f0, READY" module=grpc
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.899601317+02: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
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.916209286+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 17:49:07 DietPi dockerd[6033]: time="2019-09-26T17:49:07.929738557+02: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=overlay
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.025645692+02:00" level=warning msg="Your kernel does not support swap memory limit"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.025762255+02:00" level=warning msg="Your kernel does not support cgroup cfs period"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.025803921+02:00" level=warning msg="Your kernel does not support cgroup cfs quotas"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.025845015+02:00" level=warning msg="Your kernel does not support cgroup rt period"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.025891682+02:00" level=warning msg="Your kernel does not support cgroup rt runtime"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.026656421+02:00" level=info msg="Loading containers: start."
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.041644546+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.054806005+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.068064598+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.117472515+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.426256734+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby
Sep 26 17:49:09 DietPi dockerd[6033]: failed to start daemon: Error initializing network controller: error obtaining controller instance: failed to create NAT chain DOCKER: iptables failed: iptables -t nat -N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported
Sep 26 17:49:09 DietPi dockerd[6033]:  (exit status 1)
Sep 26 17:49:09 DietPi systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 17:49:09 DietPi systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 17:49:09 DietPi systemd[1]: Failed to start Docker Application Container Engine.
Sep 26 17:49:11 DietPi systemd[1]: docker.service: Service RestartSec=2s expired, scheduling restart.
Sep 26 17:49:11 DietPi systemd[1]: docker.service: Scheduled restart job, restart counter is at 5.
Sep 26 17:49:11 DietPi systemd[1]: Stopped Docker Application Container Engine.
Sep 26 17:49:11 DietPi systemd[1]: Starting Docker Application Container Engine...
Sep 26 17:49:11 DietPi dockerd[6227]: time="2019-09-26T17:49:11.811806420+02:00" level=info ms

@theAkito
Copy link
Author

theAkito commented Sep 26, 2019

@MichaIng

Sep 26 17:49:05 DietPi dockerd[5960]: failed to start daemon: 
Error initializing network controller: 
error obtaining controller instance: failed to create 
NAT chain DOCKER: iptables failed: iptables -t nat 
-N DOCKER: iptables/1.8.2 Failed to initialize nft: Protocol not supported

(I added some \n to make it more readable.)

Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.041644546+02:00" level=warning msg="Running modprobe bridge br_netfilter failed with message: modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module bridge not found in directory /lib/modules/4.19.57-v7+\nmodprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module br_netfilter not found in directory /lib/modules/4.19.57-v7+\n, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.054806005+02:00" level=warning msg="Running modprobe nf_nat failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module nf_nat not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.068064598+02:00" level=warning msg="Running modprobe xt_conntrack failed with message: `modprobe: ERROR: ../libkmod/libkmod.c:586 kmod_search_moddep() could not open moddep file '/lib/modules/4.19.57-v7+/modules.dep.bin'\nmodprobe: WARNING: Module xt_conntrack not found in directory /lib/modules/4.19.57-v7+`, error: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.117472515+02:00" level=warning msg="Failed to read iptables version: exit status 1"
Sep 26 17:49:09 DietPi dockerd[6033]: time="2019-09-26T17:49:09.426256734+02:00" level=info msg="stopping event stream following graceful shutdown" error="<nil>" module=libcontainerd namespace=moby

@MichaIng
Copy link
Owner

@Akito13
I think I know the reason for the error:

  • Docker requires some kernel features and modules, thus tries to enable them on startup.
  • On first boot, on RPi at least, kernel upgrades are installed, when available.
  • This removes the old /lib/modules/4.19.XX-v7+ dir, that fits the currently loaded kernel, and creates a new one for the new kernel version, which is loaded on next reboot.
  • When running modprobe to lead modules, it searches for modules in /lib/modules/$(uname -r). uname -r prints the kernel version of the currently loaded kernel, thus the above dir does not exist anymore, hence modprobe fails.

Can you verify that Docker start continues to fail until you do a reboot?

Although the final failure is indeed about nft support. This has indeed been added just recently to the RPi kernel. iptables should use netfilter as fallback, but probably it is a similar issue here about mismatch between loaded and installed/upgraded kernel.


I will try to replicate the issue on a virtual machine with downgraded kernel. In case we need to force a reboot after first run dietpi-update when a kernel upgrade was detected, or we check if /lib/modules/$(uname -r) exists when installing Docker and in case allow APT to fail (ignore failure) and rely on reboot after dietpi-software run fixing it.

@theAkito
Copy link
Author

@MichaIng

I issued a reboot over SSH. The docker service is now active automatically, after boot.

@MichaIng
Copy link
Owner

@Akito13
Yes this is how it should be. So looks like the kernel mismatch/failing modprobe is indeed the issue. I will add the mentioned workaround and report the issue to Docker devs as well. Probably this can be gracefully handled within the Docker postinst script or at least the output can be made more meaningful.

@MichaIng
Copy link
Owner

@Akito13
First of all I was able to replicate the service start error when having the kernel just upgraded (and old kernel autoremoved, which is included in the RPi kernel install script):

Linux VM-Buster 4.19.0-6-amd64 #1 SMP Debian 4.19.67-2+deb10u1 (2019-09-20) x86_64 GNU/Linux
Setting up linux-image-amd64 (5.2+106~bpo10+1) ...
Removing linux-image-4.19.0-6-amd64 (4.19.67-2+deb10u1) ...
  • Linux 5.2 is available via backports already 👍.
Sep 26 22:13:44 VM-Buster systemd[1]: Starting Docker Application Container Engine...
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.601462962+02:00" level=info msg="Starting up"
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.604216328+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.604545186+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.604863978+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.605137126+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.605636606+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0005e0ac0, CONNECTING" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.606667674+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0005e0ac0, READY" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.608893082+02:00" level=info msg="parsed scheme: \"unix\"" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.608941219+02:00" level=info msg="scheme \"unix\" not registered, fallback to default scheme" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.608995671+02:00" level=info msg="ccResolverWrapper: sending update to cc: {[{unix:///run/containerd/containerd.sock 0  <nil>}] }" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.609041503+02:00" level=info msg="ClientConn switching balancer to \"pick_first\"" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.609166608+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0005baf30, CONNECTING" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.609587294+02:00" level=info msg="pickfirstBalancer: HandleSubConnStateChange: 0xc0005baf30, READY" module=grpc
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.615934083+02: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
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.620492379+02:00" level=error msg="AUFS was not found in /proc/filesystems" storage-driver=aufs
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.624804952+02: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=overlay
Sep 26 22:13:44 VM-Buster dockerd[4373]: time="2019-09-26T22:13:44.644656068+02:00" level=error msg="There are no more loopback devices available."
Sep 26 22:13:44 VM-Buster dockerd[4373]: failed to start daemon: error initializing graphdriver: loopback attach failed
Sep 26 22:13:44 VM-Buster systemd[1]: docker.service: Main process exited, code=exited, status=1/FAILURE
Sep 26 22:13:44 VM-Buster systemd[1]: docker.service: Failed with result 'exit-code'.
Sep 26 22:13:44 VM-Buster systemd[1]: Failed to start Docker Application Container Engine.
  • The error logs are not exactly the same, but as well due to missing kernel features, which clearly enough is related to missing /lib/modules/$(uname -r).
  • Reboot resolves the issue, install without upgrading the kernel works well OOTB etc. So the issue is pretty clear.

I just wanted to implement the fix now, however I recognised that we did not do any error handling of the Docker installer: https://github.com/MichaIng/DietPi/blob/master/dietpi/dietpi-software#L6055-L6057
However I guess the failing APT install caused another APT install to fail, since APT always tries to resolve previous issues before running new installs. This then most likely triggered the first dietpi-software failure then, and the retry then failed on initial G_AGUG.

Error handling has already been implemented for v6.26, however exit code was not transferred to G_ERROR_HANDLER, so good that I had another look on it. Now this should work well.
Since we cannot control that docker-ce install within the Docker installer, I not included a check to in case prevent the install of Docker in the first place and instead inform user that a reboot needs to be done first: f563d9c

@MichaIng MichaIng added Bug 🐞 Solution available 🥂 Definite solution has been done and removed Investigating 🤔 labels Sep 26, 2019
@MichaIng MichaIng added this to the v6.26 milestone Sep 26, 2019
@MichaIng MichaIng changed the title DietPi-Software | Docker APT install fails on Raspbian Buster DietPi-Software | Docker APT failure after kernel upgrade Sep 26, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants