Reboot has a probability that docker can't start

[tieguoevan]

Hi,
I found that execute reboot in linux shell has a probability that docker can't start. It seems to be related to the filesystem, because I can found some error in dmesg:

root@sonic:/home/admin# dmesg | tail -n 10
[   13.576222] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   13.576224] 8021q: adding VLAN 0 to HW filter on device eth0
[   13.576253] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   14.922309] audit: type=1400 audit(1478292796.539:9): apparmor="DENIED" operation="open" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="sbin" pid=2287 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[   14.922319] audit: type=1400 audit(1478292796.539:10): apparmor="DENIED" operation="open" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="bin" pid=2287 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[   14.922327] audit: type=1400 audit(1478292796.539:11): apparmor="DENIED" operation="open" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="usr/sbin" pid=2287 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[   14.922334] audit: type=1400 audit(1478292796.539:12): apparmor="DENIED" operation="open" info="Failed name lookup - disconnected path" error=-13 profile="/usr/sbin/ntpd" name="usr/bin" pid=2287 comm="ntpd" requested_mask="r" denied_mask="r" fsuid=0 ouid=0
[  316.408867] EXT4-fs (loop1): error count since last fsck: 1
[  316.408896] EXT4-fs (loop1): initial error at time 949787565: ext4_ext_map_blocks:4301: inode 19
[  316.408906] EXT4-fs (loop1): last error at time 949787565: ext4_ext_map_blocks:4301: inode 19
root@sonic:/home/admin#

root@sonic:/home/admin# sudo journalctl -u docker.service
-- Logs begin at Sat 2016-11-05 04:53:05 CST, end at Sat 2016-11-05 07:30:49 CST. --
Nov 05 04:53:06 sonic systemd[1]: Starting Docker Application Container Engine...
Nov 05 04:53:06 sonic docker[674]: time="2016-11-05T04:53:06.825701426+08:00" level=info msg="New containerd process, pid: 686\n"
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:07.938119747+08:00" level=info msg="Graph migration to content-addressability took 0.00 seconds"
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:07.953930518+08:00" level=info msg="Firewalld running: false"
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:07.983691273+08:00" level=warning msg="Your kernel does not support swap memory limit."
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:07.985328337+08:00" level=info msg="Loading containers: start."
Nov 05 04:53:10 sonic docker[674]: ...........
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:08.001555607+08:00" level=info msg="Loading containers: done."
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:08.001588040+08:00" level=info msg="Daemon has completed initialization"
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:08.001609489+08:00" level=info msg="Docker daemon" commit=5604cbe graphdriver=overlay version=1.11.1
Nov 05 04:53:10 sonic docker[674]: time="2016-11-05T04:53:08.015608154+08:00" level=info msg="API listen on /var/run/docker.sock"
Nov 05 04:53:08 sonic systemd[1]: Started Docker Application Container Engine.
Nov 05 07:16:18 sonic docker[674]: time="2016-11-05T07:16:18.193778467+08:00" level=error msg="Error setting up exec command in container syncd: Container 646ec592eeaa9540e6d2e78045528c6141f222374048f5303bb6c028591ecf07 is not running"
Nov 05 07:16:18 sonic docker[674]: time="2016-11-05T07:16:18.193843803+08:00" level=error msg="Handler for POST /v1.23/containers/syncd/exec returned error: Container 646ec592eeaa9540e6d2e78045528c6141f222374048f5303bb6c028591ecf07 is not running"

I dont know whether it's related to debian:stretch but we didn't met the problem when using debian:jessie.

Any ideas about this problem? Thanks!

Steps to reproduce the issue:

1. reboot several times

[dawnbeauty]

We encountered a similar issue on branch 201811. Add more infos:

• Steps
  reboot several times
• What we found
  swss or syncd does not start its docker container as /usr/local/bin/swss.sh or syncd.sh hangs while executing docker exec database redis-cli commands.
  After that, all docker commands (eg: inspect, logs, exec, ps) for database container hang without any output. But redis server is ok since sonic-cfggen -d --print-data works as normal.

[jipanyang]

Which reboot command was used during the test, /usr/bin/reboot or /sbin/reboot or /sbin/shutdown -r ?

[dawnbeauty]

sudo reboot -> /usr/bin/reboot

[lguohan]

we have updated the 18.09 and it seems solve this issue, can you check if you still see this problem in latest image?

[jipanyang]

@dawnbeauty with recent docker engine update and containerd systemd service change, I didn't see docker start issue with reboot any more. Has that fixed your issue too?

[dawnbeauty]

@jipanyang, thanks for the reply.
I'll build and check again.

[dawnbeauty]

@jipanyang The change seems fixed the issue. I've tried 100+ times to reboot and didn't encounter any issue about docker start.

SONiC Software Version: SONiC.201811.0-dirty-20190216.015227
Distribution: Debian 9.7
Kernel: 4.9.0-8-amd64
Build commit: 4faa5f2
Build date: Sat Feb 16 10:57:27 UTC 2019

[jipanyang]

@dawnbeauty thanks for the update! I think we may close this issue.

[yxieca]

This issue has been addressed with docker engine upgrade.