Starting and restarting docker rapidly breaks it

[stpierre]

Version: Docker version 0.10.0, build dc9c28f/0.10.0
OS: CentOS 6 (2.6.32-431.1.2.0.1.el6.x86_64)

Docker is working:

# docker images
REPOSITORY          TAG                 IMAGE ID            CREATED             VIRTUAL SIZE

But if you start and restart it in rapid succession, it breaks:

# service docker stop
Stopping docker:                                           [  OK  ]
# service docker status
docker is stopped
# service docker start; service docker restart
Starting docker:                                           [  OK  ]
Stopping docker:                                           [FAILED]
Starting docker:                                           [  OK  ]
# service docker status
docker (pid  3254) is running...
# docker images
2014/04/23 10:33:53 Cannot connect to the Docker daemon. Is 'docker -d' running on this host?

Docker is running, of course:

# ps -ef | grep docker
root      3254     1  0 10:33 pts/1    00:00:00 /usr/bin/docker -d -e lxc -D

/var/log/docker contains no smoking guns, but I've included it below for posterity.

\nWed Apr 23 10:37:50 EDT 2014\n
2014/04/23 10:37:50 WARNING: You are running linux kernel version 2.6.32-431.1.2.0.1.el6.x86_64, which might be unstable running docker. Please upgrade your kernel to 3.8.0.
[/var/lib/docker|d091b8bc] +job serveapi(unix:///var/run/docker.sock)
[/var/lib/docker|d091b8bc] +job initserver()
[/var/lib/docker|d091b8bc.initserver()] Creating server
2014/04/23 10:37:50 Listening for HTTP on unix (/var/run/docker.sock)
[debug] server.go:1048 Registering GET, /images/{name:.*}/json
[debug] server.go:1048 Registering GET, /containers/{name:.*}/export
[debug] server.go:1048 Registering GET, /containers/{name:.*}/top
[debug] server.go:1048 Registering GET, /events
[debug] server.go:1048 Registering GET, /info
[debug] server.go:1048 Registering GET, /images/{name:.*}/get
[debug] server.go:1048 Registering GET, /images/{name:.*}/history
[debug] server.go:1048 Registering GET, /images/viz
[debug] server.go:1048 Registering GET, /containers/json
[debug] server.go:1048 Registering GET, /containers/{name:.*}/changes
[debug] server.go:1048 Registering GET, /version
[debug] server.go:1048 Registering GET, /images/json
[debug] server.go:1048 Registering GET, /images/search
[debug] server.go:1048 Registering GET, /containers/ps
[debug] server.go:1048 Registering GET, /containers/{name:.*}/json
[debug] server.go:1048 Registering GET, /containers/{name:.*}/attach/ws
[debug] server.go:1048 Registering POST, /images/{name:.*}/insert
[debug] server.go:1048 Registering POST, /images/{name:.*}/tag
[debug] server.go:1048 Registering POST, /containers/{name:.*}/start
[debug] server.go:1048 Registering POST, /containers/{name:.*}/wait
[debug] server.go:1048 Registering POST, /containers/{name:.*}/resize
[debug] server.go:1048 Registering POST, /containers/{name:.*}/copy
[debug] server.go:1048 Registering POST, /build
[debug] server.go:1048 Registering POST, /images/load
[debug] server.go:1048 Registering POST, /images/{name:.*}/push
[debug] server.go:1048 Registering POST, /containers/create
[debug] server.go:1048 Registering POST, /containers/{name:.*}/restart
[debug] server.go:1048 Registering POST, /containers/{name:.*}/stop
[debug] server.go:1048 Registering POST, /containers/{name:.*}/attach
[debug] server.go:1048 Registering POST, /images/create
[debug] server.go:1048 Registering POST, /auth
[debug] server.go:1048 Registering POST, /commit
[debug] server.go:1048 Registering POST, /containers/{name:.*}/kill
[debug] driver.go:78 Error loading driver aufs: AUFS was not found in /proc/filesystems
[debug] driver.go:78 Error loading driver btrfs: No such driver: btrfs
[debug] deviceset.go:528 Generated prefix: docker-202:65-360797
[debug] deviceset.go:531 Checking for existence of the pool 'docker-202:65-360797-pool'
[debug] deviceset.go:545 Pool doesn't exist. Creating it.
[debug] attach_loopback.go:91 Error retrieving the next available loopback: open /dev/loop-control: no such file or directory
[debug] attach_loopback.go:91 Error retrieving the next available loopback: open /dev/loop-control: no such file or directory
[debug] server.go:1048 Registering DELETE, /containers/{name:.*}
[debug] server.go:1048 Registering DELETE, /images/{name:.*}
[debug] server.go:1048 Registering OPTIONS, 
[debug] server.go:1138 docker group found. gid: 498
\nWed Apr 23 10:37:50 EDT 2014\n
[debug] deviceset.go:286 loadMetadata()
[debug] deviceset.go:329 loadMetadata END
[debug] runtime.go:690 Using graph driver devicemapper
2014/04/23 10:37:50 WARNING: You are running linux kernel version 2.6.32-431.1.2.0.1.el6.x86_64, which might be unstable running docker. Please upgrade your kernel to 3.8.0.
[/var/lib/docker|44012956] +job serveapi(unix:///var/run/docker.sock)
2014/04/23 10:37:50 Listening for HTTP on unix (/var/run/docker.sock)
[debug] server.go:1048 Registering GET, /images/json
[debug] server.go:1048 Registering GET, /images/search
[debug] server.go:1048 Registering GET, /images/{name:.*}/json
[debug] server.go:1048 Registering GET, /events
[debug] server.go:1048 Registering GET, /version
[debug] server.go:1048 Registering GET, /images/{name:.*}/get
[debug] runtime.go:707 Creating images graph
[debug] graph.go:63 Restored 0 elements
[debug] runtime.go:719 Creating volumes graph
[debug] graph.go:63 Restored 0 elements
[debug] runtime.go:724 Creating repository list
[/var/lib/docker|d091b8bc] +job init_networkdriver()
[DEBUG] [iptables]: /sbin/iptables, [-C POSTROUTING -t nat -s 172.17.42.1/16 ! -d 172.17.42.1/16 -j MASQUERADE]
[DEBUG] [iptables]: /sbin/iptables, [-I POSTROUTING -t nat -s 172.17.42.1/16 ! -d 172.17.42.1/16 -j MASQUERADE]
[/var/lib/docker|44012956] +job initserver()
[/var/lib/docker|44012956.initserver()] Creating server
[debug] server.go:1048 Registering GET, /containers/json
[debug] server.go:1048 Registering GET, /containers/{name:.*}/json
[debug] server.go:1048 Registering GET, /info
[debug] server.go:1048 Registering GET, /images/viz
[debug] server.go:1048 Registering GET, /images/{name:.*}/history
[debug] server.go:1048 Registering GET, /containers/ps
[debug] server.go:1048 Registering GET, /containers/{name:.*}/changes
[debug] server.go:1048 Registering GET, /containers/{name:.*}/top
[debug] server.go:1048 Registering GET, /containers/{name:.*}/export
[debug] server.go:1048 Registering GET, /containers/{name:.*}/attach/ws
[debug] server.go:1048 Registering POST, /images/{name:.*}/insert
[debug] server.go:1048 Registering POST, /images/load
[debug] server.go:1048 Registering POST, /containers/create
[debug] server.go:1048 Registering POST, /containers/{name:.*}/wait
[debug] server.go:1048 Registering POST, /containers/{name:.*}/attach
[debug] server.go:1048 Registering POST, /containers/{name:.*}/copy
[debug] server.go:1048 Registering POST, /commit
[debug] server.go:1048 Registering POST, /images/create
[debug] server.go:1048 Registering POST, /images/{name:.*}/tag
[debug] server.go:1048 Registering POST, /containers/{name:.*}/resize
[debug] server.go:1048 Registering POST, /build
[debug] server.go:1048 Registering POST, /containers/{name:.*}/kill
[debug] server.go:1048 Registering POST, /containers/{name:.*}/restart
[debug] server.go:1048 Registering POST, /containers/{name:.*}/start
[debug] server.go:1048 Registering POST, /auth
[debug] server.go:1048 Registering POST, /images/{name:.*}/push
[DEBUG] [iptables]: /sbin/iptables, [-D FORWARD -i docker0 -o docker0 -j DROP]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -i docker0 -o docker0 -j ACCEPT]
[debug] driver.go:183 Enable inter-container communication
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -i docker0 -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -i docker0 ! -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -i docker0 ! -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
[debug] driver.go:78 Error loading driver aufs: AUFS was not found in /proc/filesystems
[debug] driver.go:78 Error loading driver btrfs: No such driver: btrfs
[debug] deviceset.go:528 Generated prefix: docker-202:65-360797
[debug] deviceset.go:531 Checking for existence of the pool 'docker-202:65-360797-pool'
[debug] deviceset.go:286 loadMetadata()
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
[debug] server.go:1048 Registering POST, /containers/{name:.*}/stop
[debug] server.go:1048 Registering DELETE, /containers/{name:.*}
[debug] server.go:1048 Registering DELETE, /images/{name:.*}
[debug] server.go:1048 Registering OPTIONS, 
[debug] server.go:1138 docker group found. gid: 498
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D PREROUTING -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -F DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -X DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -N DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -A OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
[/var/lib/docker|d091b8bc] -job init_networkdriver() = OK (0)
[debug] deviceset.go:329 loadMetadata END
[debug] runtime.go:690 Using graph driver devicemapper
[debug] runtime.go:707 Creating images graph
[debug] graph.go:63 Restored 0 elements
[debug] runtime.go:719 Creating volumes graph
[debug] graph.go:63 Restored 0 elements
[debug] runtime.go:724 Creating repository list
[/var/lib/docker|44012956] +job init_networkdriver()
[DEBUG] [iptables]: /sbin/iptables, [-C POSTROUTING -t nat -s 172.17.42.1/16 ! -d 172.17.42.1/16 -j MASQUERADE]
[DEBUG] [iptables]: /sbin/iptables, [-I POSTROUTING -t nat -s 172.17.42.1/16 ! -d 172.17.42.1/16 -j MASQUERADE]
[DEBUG] [iptables]: /sbin/iptables, [-D FORWARD -i docker0 -o docker0 -j DROP]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -i docker0 -o docker0 -j ACCEPT]
[debug] driver.go:183 Enable inter-container communication
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -i docker0 -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -i docker0 ! -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -i docker0 ! -o docker0 -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-C FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-I FORWARD -o docker0 -m conntrack --ctstate RELATED,ESTABLISHED -j ACCEPT]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D PREROUTING -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -D OUTPUT -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -F DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -X DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -N DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -A PREROUTING -m addrtype --dst-type LOCAL -j DOCKER]
[DEBUG] [iptables]: /sbin/iptables, [-t nat -A OUTPUT -m addrtype --dst-type LOCAL ! --dst 127.0.0.0/8 -j DOCKER]
[/var/lib/docker|44012956] -job init_networkdriver() = OK (0)
[/var/lib/docker|d091b8bc.initserver()] Creating pidfile
[/var/lib/docker|d091b8bc.initserver()] Setting up signal traps
[/var/lib/docker|d091b8bc] -job initserver() = OK (0)
[/var/lib/docker|d091b8bc] +job acceptconnections()
[/var/lib/docker|d091b8bc] -job acceptconnections() = OK (0)
[/var/lib/docker|44012956.initserver()] Creating pidfile
2014/04/23 10:37:51 pid file found, ensure docker is not running or delete /var/run/docker.pid

[crosbymichael]

Is this a real issue for docker or something faulty in your tool starting it? I'm not sure I see this as a docker issue.

[stpierre]

The "tool" in this case is the init script, and it turns out that you're right. The init script just backgrounds docker, so service docker start returns before the pidfile exists. Then service docker restart tries to restart it, but since the pidfile doesn't exist, the init script silently assumes it's not running, and tries to start another instance, but by that time the first instance has written its pidfile and things come crashing down. I'll submit a PR to make the init script wait until the pidfile exists to return from start.

[crosbymichael]

@stpierre Why is the init script launching docker in the background and using a pid file instead of holding onto the process in the foreground?

[stpierre]

No idea. @maxamillion might be better able to answer that -- he's the
original author according to git blame. If there's a better way to do
this (i.e., if docker will daemonize itself, which it sure seems like it
should do), I'm all about doing it right.

On Fri, May 16, 2014 at 1:31 PM, Michael Crosby notifications@github.comwrote:

@stpierre https://github.com/stpierre Why is the init script launching
docker in the background and using a pid file instead of holding onto the
process in the foreground?

—
Reply to this email directly or view it on GitHubhttps://github.com//issues/5359#issuecomment-43357980
.

Chris St. Pierre

[maxamillion]

No hard reason and I'm definitely open to suggestion to change it. It basically happened that at first pass I did it that way, it worked, I submitted for review, everyone else who looked at it gave it a +1 and here we are but I'm by no means married to the method.

[crosbymichael]

ping @tianon

[tianon]

@maxamillion is start-stop-daemon not a normal thing to use in the world of RHEL sysvinit scripts?

It does seem kind of odd that the init script itself is just doing standard shell backgrounding of the Docker daemon directly, but I'm not familiar with what "best practice" is in the world of RHEL sysvinit scripts.

[stpierre]

start-stop-daemon pulls in all of the LSB stuff, which tends to be avoided on RHEL in favor of the init script functions in /etc/init.d/functions. The daemon function in that file doesn't background the command -- it expects the command to daemonize itself.

I think the strange thing here is that docker -d does not actually fork a daemon -- it runs the daemon in the foreground. The RHEL /etc/init.d/functions file doesn't seem to have a function to handle that scenario, which is why I suspect @maxamillion did what he did, as strange as it seems at first glance.

Ultimately it'd be nice for docker to daemonize itself so it didn't have to be backgrounded, but for now I think this is probably the best we're likely to get in the RHEL world (without pulling in tons of LSB stuff). (It chagrins me to be to dismissive of LSB, but it's really a pain, especially on older RHEL versions where it's a single monolithic package, to pull in CUPS when all you want is to run an init script.)

[tianon]

Ah ok, thanks for the explanation @stpierre (that makes sense).

See #2758 for a description of why we don't daemonize (basically boils down to not being a supported thing in Go yet because goroutines make forking complicated).