Snappy

Low timeout in docker start script

Bug #1482685 reported by Federico Gimenez
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Snappy
Invalid
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

Tags: docker

Related branches

lp:~fgimenez/snappy-hub/increase-start-timeout
Snappy Developers: Pending requested
Diff: 12 lines (+1/-1)
1 file modified
package-dir/bin/docker.start (+1/-1)
Revision history for this message
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!

Revision history for this message
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/

Federico Gimenez (fgimenez)
tags: added: docker
Changed in snappy:
status: New → Fix Committed
Changed in snappy-hub:
status: New → Fix Committed
Michael Vogt (mvo)
Changed in snappy:
importance: Undecided → Medium
Leo Arias (elopio)
Changed in snappy:
status: Fix Committed → Invalid
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.