Low timeout in docker start script

Bug #1482685 reported by Federico Gimenez on 2015-08-07
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Snappy
Medium
Unassigned
snappy-hub
Fix Committed
Undecided
Unassigned

Bug Description

Hi, the docker service is eventually not starting on slow systems (tested on canonistack region 1 and 2, snappy 1504/edge, #133) after a reboot, this is the output of journald:

-- Logs begin at Thu 2015-08-06 11:13:46 UTC, end at Thu 2015-08-06 11:19:48 UTC. --
Aug 06 11:14:13 test systemd[1]: Started The docker app deployment mechanism.
Aug 06 11:14:13 test systemd[1]: Starting The docker app deployment mechanism...
Aug 06 11:14:14 test ubuntu-core-launcher[739]: DEBUG: snappy_udev_setup_required
Aug 06 11:14:14 test ubuntu-core-launcher[739]: DEBUG: looking for: '{
Aug 06 11:14:14 test ubuntu-core-launcher[739]: "write_path": [
Aug 06 11:14:14 test ubuntu-core-launcher[739]: "/dev/**"
Aug 06 11:14:14 test ubuntu-core-launcher[739]: ],
Aug 06 11:14:14 test ubuntu-core-launcher[739]: "read_path": [
Aug 06 11:14:14 test ubuntu-core-launcher[739]: "/run/udev/data/*"
Aug 06 11:14:14 test ubuntu-core-launcher[739]: ]
Aug 06 11:14:14 test ubuntu-core-launcher[739]: }'
Aug 06 11:14:14 test ubuntu-core-launcher[739]: DEBUG: seccomp_load_filters docker_docker-daemon_1.6.1.002
Aug 06 11:14:16 test ubuntu-core-launcher[756]: DEBUG: snappy_udev_setup_required
Aug 06 11:14:16 test ubuntu-core-launcher[756]: DEBUG: looking for: '{
Aug 06 11:14:16 test ubuntu-core-launcher[756]: "write_path": [
Aug 06 11:14:16 test ubuntu-core-launcher[756]: "/dev/**"
Aug 06 11:14:16 test ubuntu-core-launcher[756]: ],
Aug 06 11:14:16 test ubuntu-core-launcher[756]: "read_path": [
Aug 06 11:14:16 test ubuntu-core-launcher[756]: "/run/udev/data/*"
Aug 06 11:14:16 test ubuntu-core-launcher[756]: ]
Aug 06 11:14:16 test ubuntu-core-launcher[756]: }'
Aug 06 11:14:16 test ubuntu-core-launcher[756]: DEBUG: seccomp_load_filters docker_docker-daemon_1.6.1.002
Aug 06 11:14:16 test ubuntu-core-launcher[756]: Docker daemon is not running

When the service starts properly this is the output:

-- Logs begin at Thu 2015-08-06 14:23:45 UTC, end at Thu 2015-08-06 14:24:54 UTC. --
Aug 06 14:24:37 test systemd[1]: Started The docker app deployment mechanism.
Aug 06 14:24:37 test systemd[1]: Starting The docker app deployment mechanism...
Aug 06 14:24:37 test ubuntu-core-launcher[736]: DEBUG: snappy_udev_setup_required
Aug 06 14:24:37 test ubuntu-core-launcher[736]: DEBUG: looking for: '{
Aug 06 14:24:37 test ubuntu-core-launcher[736]: "write_path": [
Aug 06 14:24:37 test ubuntu-core-launcher[736]: "/dev/**"
Aug 06 14:24:37 test ubuntu-core-launcher[736]: ],
Aug 06 14:24:37 test ubuntu-core-launcher[736]: "read_path": [
Aug 06 14:24:37 test ubuntu-core-launcher[736]: "/run/udev/data/*"
Aug 06 14:24:37 test ubuntu-core-launcher[736]: ]
Aug 06 14:24:37 test ubuntu-core-launcher[736]: }'
Aug 06 14:24:37 test ubuntu-core-launcher[736]: DEBUG: seccomp_load_filters docker_docker-daemon_1.6.1.002
Aug 06 14:24:43 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:43Z" level=debug msg="waiting for daemon to initialize"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=info msg="+job serveapi(unix:///var/run/docker.sock)"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=info msg="Listening for HTTP on unix (/var/run/docker.sock)"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=debug msg="Registering DELETE, /containers/{name:.*}"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=debug msg="Registering DELETE, /images/{name:.*}"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=debug msg="Registering OPTIONS, "
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=debug msg="Registering GET, /images/{name:.*}/json"
Aug 06 14:24:44 test ubuntu-core-launcher[736]: time="2015-08-06T14:24:44Z" level=debug msg="Registering GET, /containers/{name:.*}/attach/ws"
.....

Increasing the timeout value in [1] seems to solve the problem.

Thanks!

[1] http://bazaar.launchpad.net/~snappy-dev/snappy-hub/docker/view/head:/package-dir/bin/docker.start#L37

Related branches

Federico Gimenez (fgimenez) wrote :

The second long in the bug description correspond to a system booted after manually increasing the timeout in /apps/docker/current/bin/docker.start to 8, in that case the service started after 6 seconds.

With the default timeout this is the log for a successful service setup (which happens randomly in a slow system as the one depicted in the description):

-- Logs begin at Wed 2015-08-05 07:02:06 UTC, end at Wed 2015-08-05 07:02:48 UTC. --
    Aug 05 07:02:29 test-16732 systemd[1]: Started The docker app deployment mechanism.
    Aug 05 07:02:29 test-16732 systemd[1]: Starting The docker app deployment mechanism...
    Aug 05 07:02:31 test-16732 ubuntu-core-launcher[761]: time="2015-08-05T07:02:31Z" level=info msg="+job serveapi(unix:///var/run/docker.sock)"
    Aug 05 07:02:31 test-16732 ubuntu-core-launcher[761]: time="2015-08-05T07:02:31Z" level=info msg="Listening for HTTP on unix (/var/run/docker.sock)"
...

All these logs have been collected with the debug flag activated for both docker and ubuntu-core-launcher.

Thanks!

Federico Gimenez (fgimenez) wrote :

This is already fixed with the 1.6.2 version of the docker framework, now the test results are consistent [1]

Thanks!

[1] http://10.55.32.19:8080/job/daily-1504/

tags: added: docker
Changed in snappy:
status: New → Fix Committed
Changed in snappy-hub:
status: New → Fix Committed
Michael Vogt (mvo) on 2015-08-25
Changed in snappy:
importance: Undecided → Medium
Leo Arias (elopio) on 2016-04-08
Changed in snappy:
status: Fix Committed → Invalid
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers