Docker service is not properly restarted when updating docker.io package

Bug #1658691 reported by Claudio Kuenzler on 2017-01-23
34
This bug affects 5 people
Affects Status Importance Assigned to Milestone
docker.io (Ubuntu)
Undecided
Unassigned

Bug Description

After the docker.io package was updated last Friday (Jan 20 2017) we started experiencing issues and getting errors when new containers should be launched.

Here's an excerpt of errors found in syslog:

Jan 23 06:25:07 dockerserver kernel: [7751793.479504] aufs au_opts_verify:1597:dockerd[10676]: dirperm1 breaks the protection by the permission bits on the
lower branch
Jan 23 06:25:07 dockerserver dockerd[13066]: time="2017-01-23T06:25:07.616134541+01:00" level=error msg="containerd: start container" error="oci runtime err
or: process_linux.go:330: running prestart hook 0 caused \"fork/exec /usr/bin/dockerd (deleted): no such file or directory: \"" id=e20acb788ee6554bb1240bc7c07
bd033a8d15d8e4f246c553120beba4bfbcb2f
Jan 23 06:25:07 dockerserver dockerd[13066]: time="2017-01-23T06:25:07.627421952+01:00" level=error msg="Create container failed with error: oci runtime err
or: process_linux.go:330: running prestart hook 0 caused \"fork/exec /usr/bin/dockerd (deleted): no such file or directory: \""
Jan 23 06:25:07 dockerserver dockerd[13066]: time="2017-01-23T06:25:07.647734613+01:00" level=warning msg="Couldn't run auplink before unmount /var/lib/dock
er/aufs/mnt/e513ea71816cd308e5815c5b24ce34833f1de4e6d4f700de090c50c70b050678: exec: \"auplink\": executable file not found in $PATH"
Jan 23 06:25:07 dockerserver dockerd[13066]: time="2017-01-23T06:25:07.664973641+01:00" level=error msg="Handler for POST /v1.22/containers/e20acb788ee6554b
b1240bc7c07bd033a8d15d8e4f246c553120beba4bfbcb2f/start returned error: oci runtime error: process_linux.go:330: running prestart hook 0 caused \"fork/exec /us
r/bin/dockerd (deleted): no such file or directory: \""
Jan 23 06:25:07 dockerserver kernel: [7751793.760983] aufs au_opts_verify:1597:dockerd[30845]: dirperm1 breaks the protection by the permission bits on the
lower branch
Jan 23 06:25:07 dockerserver dockerd[13066]: time="2017-01-23T06:25:07.902874678+01:00" level=error msg="containerd: start container" error="oci runtime err
or: process_linux.go:330: running prestart hook 0 caused \"fork/exec /usr/bin/dockerd (deleted): no such file or directory: \"" id=e20acb788ee6554bb1240bc7c07
bd033a8d15d8e4f246c553120beba4bfbcb2f

It looks like the update was installed correctly and afterwards started the Docker service (engine) - but there was no stop before applying the update (which could be added in a docker.io.preinst file).

apt history shows:

Start-Date: 2017-01-20 15:04:06
Commandline: /usr/bin/apt-get -y -o Dpkg::Options::=--force-confdef -o Dpkg::Options::=--force-confold install docker.io
Requested-By: ansible (1001)
Upgrade: runc:amd64 (1.0.0~rc1-0ubuntu1~16.04, 1.0.0~rc1-0ubuntu2~16.04.1), docker.io:amd64 (1.12.1-0ubuntu13~16.04.1, 1.12.3-0ubuntu4~16.04.2)
End-Date: 2017-01-20 15:04:10

syslog shows for that timeframe (15.04:06 to 15:04:10):

Jan 20 15:04:03 dockerserver systemd[1]: Created slice User Slice of ansible.
Jan 20 15:04:03 dockerserver systemd[1]: Starting User Manager for UID 1001...
Jan 20 15:04:03 dockerserver systemd[1]: Started Session 14956 of user ansible.
Jan 20 15:04:03 dockerserver systemd[18545]: Reached target Sockets.
Jan 20 15:04:03 dockerserver systemd[18545]: Reached target Timers.
Jan 20 15:04:03 dockerserver systemd[18545]: Reached target Paths.
Jan 20 15:04:03 dockerserver systemd[18545]: Reached target Basic System.
Jan 20 15:04:03 dockerserver systemd[18545]: Reached target Default.
Jan 20 15:04:03 dockerserver systemd[18545]: Startup finished in 22ms.
Jan 20 15:04:03 dockerserver systemd[1]: Started User Manager for UID 1001.
Jan 20 15:04:08 dockerserver systemd[1]: Reloading.
Jan 20 15:04:09 dockerserver systemd[1]: apt-daily.timer: Adding 37min 2.565881s random time.
Jan 20 15:04:09 dockerserver systemd[1]: Started ACPI event daemon.
Jan 20 15:04:09 dockerserver systemd[1]: Reloading.
Jan 20 15:04:09 dockerserver systemd[1]: apt-daily.timer: Adding 5h 27min 32.130480s random time.
Jan 20 15:04:09 dockerserver systemd[1]: Started ACPI event daemon.
Jan 20 15:04:10 dockerserver systemd[1]: Reloading.
Jan 20 15:04:10 dockerserver systemd[1]: apt-daily.timer: Adding 11h 55min 14.530665s random time.
Jan 20 15:04:10 dockerserver systemd[1]: Started ACPI event daemon.
Jan 20 15:04:10 dockerserver systemd[1]: Reloading.
Jan 20 15:04:10 dockerserver systemd[1]: apt-daily.timer: Adding 11h 16min 17.514645s random time.
Jan 20 15:04:10 dockerserver systemd[1]: Started ACPI event daemon.
Jan 20 15:04:10 dockerserver systemd[1]: Started Docker Application Container Engine.
Jan 20 15:04:10 dockerserver systemd[1]: Reloading.
Jan 20 15:04:10 dockerserver systemd[1]: apt-daily.timer: Adding 11h 42min 36.963745s random time.
Jan 20 15:04:10 dockerserver systemd[1]: Started ACPI event daemon.

So there's indeed a Start of Docker at 15:04:10 but where's the stop prior to that?

If I manually restart the Docker service, syslog entries look like:

Jan 23 09:54:38 dockerserver systemd[1]: Stopping Docker Application Container Engine...
Jan 23 09:54:50 dockerserver systemd[1]: Stopped Docker Application Container Engine.
Jan 23 09:54:50 dockerserver systemd[1]: Closed Docker Socket for the API.
Jan 23 09:54:50 dockerserver systemd[1]: Stopping Docker Socket for the API.
Jan 23 09:54:50 dockerserver systemd[1]: Starting Docker Socket for the API.
Jan 23 09:54:50 dockerserver systemd[1]: Listening on Docker Socket for the API.
Jan 23 09:54:50 dockerserver systemd[1]: Starting Docker Application Container Engine...
Jan 23 09:54:54 dockerserver dockerd[26724]: time="2017-01-23T09:54:54.088301837+01:00" level=info msg="Docker daemon" commit=6b644ec graphdriver=aufs version=1.12.3
Jan 23 09:54:54 dockerserver systemd[1]: Started Docker Application Container Engine.

Please confirm or let me know if I'm mistaken.

ProblemType: Bug
DistroRelease: Ubuntu 16.04
Package: docker.io 1.12.3-0ubuntu4~16.04.2
ProcVersionSignature: Ubuntu 4.4.0-45.66-generic 4.4.21
Uname: Linux 4.4.0-45-generic x86_64
ApportVersion: 2.20.1-0ubuntu2.4
Architecture: amd64
Date: Mon Jan 23 14:52:40 2017
InstallationDate: Installed on 2016-10-25 (90 days ago)
InstallationMedia: Ubuntu-Server 16.04 LTS "Xenial Xerus" - Release amd64 (20160420.3)
ProcEnviron:
 LANGUAGE=en_US:en
 TERM=xterm
 PATH=(custom, no user)
 LANG=en_US.UTF-8
 SHELL=/bin/bash
SourcePackage: docker.io
UpgradeStatus: No upgrade log present (probably fresh install)

Claudio Kuenzler (napsty) wrote :
Launchpad Janitor (janitor) wrote :

Status changed to 'Confirmed' because the bug affects multiple users.

Changed in docker.io (Ubuntu):
status: New → Confirmed
Michael Hudson-Doyle (mwhudson) wrote :

It would be technically easy to fix this bug, i.e. restart the docker daemon on package upgrade.

The impact of this is that the docker containers will be restarted when the package is upgraded.

We need to decide if this impact outweighs the benefit.

Claudio Kuenzler (napsty) wrote :

Either a restart after the package upgrade or nothing at all. But not a 'start' of Docker as it is was when I opened the bug. Don't know if that has changed since, almost a year has passed by.

Launchpad Janitor (janitor) wrote :

This bug was fixed in the package docker.io - 17.03.2-0ubuntu3

---------------
docker.io (17.03.2-0ubuntu3) bionic; urgency=medium

  * d/tests/docker-in-lxd: set DEBIAN_FRONTEND=noninteractive when installing
    docker in the lxd container

 -- Michael Hudson-Doyle <email address hidden> Wed, 21 Feb 2018 10:49:58 +1300

Changed in docker.io (Ubuntu):
status: Confirmed → Fix Released
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Duplicates of this bug

Other bug subscribers