docker support : strange behaviour

[dduportal]

Hi all !

With the recent Docker support, i got a strange beahviour : the docker daemon seems to stop itself at the end of my provisionning.

Given that's i'm using some private contents, i cannot give you a reproducible example "as it", but i'm going ti publish a method to reproduce the problem.

What's the matter ?

• Given a boot2docker basebox basebox (tested on mitchellh one, and mine - dduportal.boot2docker, reproduced on docker 0.9.1, docker 0.12, docker 1.0 and docker 1.0.1).
• My provisonning is a shell script who does only one kind of things : building and running containers (=> no Docker provisionner nor provider due to old vagrant version in my CI).
• All docker build and run takes place with no problem.
• After provisionning phase, it seems that Docker proxy configuration occurs, and the docker restart will just kill it, and never start.

=> Then, the docker is not accessible and my workflow is stuck.

I have to provide at least some logs and reproducible example. But my question is : is it normal that the proxy configuration occurs after the provisionning ?

[dduportal]

Some logs extracted from /var/log/docker.log :

[debug] server.go:1114 Registering DELETE, /images/{name:.*}
[debug] server.go:1114 Registering OPTIONS,
listen tcp 0.0.0.0:2375: bind: address already in use
[d058c223] -job serveapi(unix:///var/run/docker.sock, tcp://0.0.0.0:2375) = ERR (1)
2014/06/23 15:24:51 listen tcp 0.0.0.0:2375: bind: address already in use
                                                                                                                   [debug] server.go:999 Calling POST /images/create
2014/06/23 15:24:57 POST /images/create?fromImage=busybox&tag=
[ab8452f2] +job pull(busybox, )
Server is not running
[ab8452f2] -job pull(busybox, ) = ERR (1)
[error] server.go:1025 Error making handler: Server is not running
[error] server.go:90 HTTP Error: statusCode=500 Server is not running
[debug] daemon.go:894 starting clean shutdown of all containers...

It seems that the Unix socket hasn't been cleaned :

docker@boot2docker:/var/log$ ls -l /var/run/
total 16
...
srw-rw----    1 root     docker           0 Jun 23 15:20 docker.sock
...

after an rm, it works.

I can't determine if it is a bug from boot2docker (Unhandled error with init.d restart) or into the plugin vagrant-proxyconf workflow.

[tmatilai]

is it normal that the proxy configuration occurs after the provisionning ?

Yes, we want to configure it in case it is installed on a provisioner run. But maybe there should be a sentinel to do it only once per a Vagrant run.

My first impression of the actual issue is that the daemon is not killed before trying to start it again.

[otahi]

@dduportal Thank you for reporting, I will check it later

[otahi]

Vagrant-proxyconf,in recent docker support, restarts docker after setting proxy environment variable.

action/configure_docker_proxy.rb:51

            comm.sudo("service #{docker} restart || /etc/init.d/#{docker} restart")

Vagrant-proxyconf seems that hooks exist after provisionaction/configure_docker_proxy.rb:L51.

In this case, I think docker daemon needs to be restarted only once before provision. I need to check it further more.

@dduportal I want to reproduce this by myself. Can you show me your Vagrantfile?

[dduportal]

@otahi Here is sample :

# -*- mode: ruby -*-
# vi: set ft=ruby :

# Vagrantfile API/syntax version. Don't touch unless you know what you're doing!
VAGRANTFILE_API_VERSION = "2"

Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|

  config.vm.box = "dduportal/boot2docker"

  config.vm.network "forwarded_port", guest: 3306, host: 3306
  config.vm.network "forwarded_port", guest: 8234, host: 8234
  config.vm.network "forwarded_port", guest: 2202, host: 2202

  config.vm.provision "shell", path: "docker.sh"

end

the script docker.sh :

#!/bin/sh
set -e
docker build -t conf-image /vagrant/
docker run -d -v /home/install:/home/final --name configuration conf-image
docker build -t mysql-image /home/install/docker/mysql/
docker run -d --name mysql -p 3306:3306 mysql-image
docker build -t myapp-base /home/install/docker/myapp-base/
docker build -t myapp-image /home/install/docker/myapp/
docker run -d --link mysql:db --name myapp -p 8234:8234 -p 2202:22 -p 1199:1199 myapp-image

The end of the vagrant up :

==> default: Removing intermediate container 9ed5ca5d3835
==> default: Successfully built f2b307d9a7ce
==> default: b77a0a544bf9e350cec4ff43bba210fac0c10892e44465860c10a2eaae60a401
==> default: Configuring proxy for Docker...

D:\workspace\labs\docker-experiments\tracer-gitrepository-vagrant>vagrant ssh
                        ##        .
                  ## ## ##       ==
               ## ## ## ##      ===
           /""""""""""""""""\___/ ===
      ~~~ {~~ ~~~~ ~~~ ~~~~ ~~ ~ /  ===- ~~~
           \______ o          __/
             \    \        __/
              \____\______/
 _                 _   ____     _            _
| |__   ___   ___ | |_|___ \ __| | ___   ___| | _____ _ __
| '_ \ / _ \ / _ \| __| __) / _` |/ _ \ / __| |/ / _ \ '__|
| |_) | (_) | (_) | |_ / __/ (_| | (_) | (__|   <  __/ |
|_.__/ \___/ \___/ \__|_____\__,_|\___/ \___|_|\_\___|_|
boot2docker: 1.0.1
             HEAD : cad5ece - Sun Jun 22 08:57:24 UTC 2014
docker@boot2docker:~$ docker ps
2014/06/24 12:10:02 Error response from daemon: Server is not running
docker@boot2docker:~$

An extract of the /vaR/log/docker.log :

listen tcp 0.0.0.0:2375: bind: address already in use
[88f7a676] -job serveapi(unix:///var/run/docker.sock, tcp://0.0.0.0:2375) = ERR (1)
2014/06/24 12:13:50 listen tcp 0.0.0.0:2375: bind: address already in use
                                                                                                                              [debug] server.go:999 Calling GET /containers/json
2014/06/24 12:13:56 GET /v1.12/containers/json
[6be37484] +job containers()
Server is not running
[6be37484] -job containers() = ERR (1)
[error] server.go:1025 Error making handler: Server is not running
[error] server.go:90 HTTP Error: statusCode=500 Server is not running

[otahi]

@dduportal Thank you for your sample. I can reproduce it on my PC with following Vagantfile, now.

VAGRANTFILE_API_VERSION = "2"
Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|
  config.vm.box = "dduportal/boot2docker"
  config.proxy.http     = "http://192.168.1.10:3128/"
  config.vm.provision "shell", inline: 'docker run -d otahi/lbspec-test'
end

I think there are 2 problems:

1. Vagrant-proxyconf restarts docker twice
2. Docker fails when restarting

I will investigate that vagrant-proxyconf restarts docker twice.

2nd one is maybe docker problem, because docker daemon restarts successfully when sleeps 10.

VAGRANTFILE_API_VERSION = "2"
Vagrant.configure(VAGRANTFILE_API_VERSION) do |config|
  config.vm.box = "dduportal/boot2docker"
  config.proxy.http     = "http://192.168.1.10:3128/"
  config.vm.provision "shell", inline: 'docker run -d otahi/lbspec-test; sleep 10'
end

[otahi]

@dduportal I have just found a misstake. I will test it later. If possible, please try #73.

[dduportal]

73 seems resolving the problem. My tests are fine, i'm testing more widely.

Thanks for the work !

[otahi]

I conclude this issue as follows.

1. Vagrant-proxyconf restarts docker twice:
   • vagrant-proxyconf's issue
2. Docker fails when restarting:
   • maybe docker's issue, but it does not occur if vagrant-proxyconf restart docker only once at the beginning of provision

So, I will fix vagrant-proxyconf on #73 and it can close this issue.