Cannot start container: Port has already been allocated

[discordianfish]

Hi,

docker 1.0.0 with aufs on 14.04 here.
I haven't found a way to reproduce it, but since upgrade to 1.0.0 I quite often get the error "port has already been allocated" when starting a container that was stopped earlier:

$ docker start n1
Error: Cannot start container n1: port has already been allocated
2014/06/17 13:07:09 Error: failed to start one or more containers

$ docker inspect n1|jq .[0].State.Running
false

$ docker inspect n1|jq .[0].HostConfig.PortBindings
{
  "7001/tcp": [
    {
      "HostPort": "7001",
      "HostIp": ""
    }
  ],
  "4001/tcp": [
    {
      "HostPort": "4001",
      "HostIp": ""
    }
  ],
  "10250/tcp": [
    {
      "HostPort": "10250",
      "HostIp": ""
    }
  ]
}

$ sudo netstat -lnp | egrep '10250|4001|7001'
$ sudo lsof -n | egrep '10250|4001|7001'

And the processes aren't running either:

$ ps -ef|grep etc[d]
$ ps -ef|grep kubele[t]

[discordianfish]

PS: The only way to recover is restarting docker after which everything works as expected.

[shykes]

Tentatively adding to 1.0.1 milestone (cc @vieux @crosbymichael @tibor @unclejack )

[LK4D4]

I see here, that if there is error during port allocations - already allocated ports never released. Maybe it is problem.

[crosbymichael]

@LK4D4 maybe we are hitting an error when we stop the container and the port is not being released?

[LK4D4]

@crosbymichael Yup, you are right. Then we should see errors in log on stop.
@discordianfish Can you pls record some logs?
Also I've discovered that ReleasePort never returns an error :)

[crosbymichael]

@LK4D4 are you looking into this issue or do you want me to take it?

[LK4D4]

@crosbymichael I almost asleep :) And have no progress on this issue, so feel free to take it.

[discordianfish]

I'll provide the logs as soon as I run into that again. But haven't so far..

[kruxik]

The issue can be reproduced easily. Whenever you try to allocate a port to a port which is already occupied, Docker complains since then even the port becomes free.

Tested with Docker 1.0 on Ubuntu 14.04

How to reproduce:

$ sudo service apache2 start #occupies port 80
$ sudo docker run -p 80:80 -i -t ubuntu:14.04 /bin/bash # first try

2014/06/19 15:53:59 Error: Cannot start container 2094c72e4485bd9f54e7f3f8de797845d6d8a43db37fd2f4f8231222e4bf377e: port has already been allocated

$ sudo service apache2 stop # frees port 80, can be verified by nmap
$ sudo docker run -p 80:80 -i -t ubuntu:14.04 /bin/bash # second try

2014/06/19 15:53:59 Error: Cannot start container 2094c72e4485bd9f54e7f3f8de797845d6d8a43db37fd2f4f8231222e4bf377e: port has already been

$ sudo service docker restart
$ docker run -p 80:80 -i -t ubuntu:14.04 /bin/bash # now it works
root@cc4847a4c37d:/#

[LK4D4]

@kruxik Wow, thank you

[LK4D4]

In bridge/driver.go in AllocatePort function we try to allocate port first time with success, then we try to map port without success, then we try to allocate same port second time - here we get port has already been allocated and exit. Port stays allocated forever.
@crosbymichael hope that I've helped :) Also I can try to fix this tomorrow if you have no time.

[kruxik]

Just verified, the issue is still in Docker 1.0.1

[LK4D4]

@kruxik yup, it will be fixed by #6555

[discordianfish]

@shykes I'm quite disappointed that this hasn't been fixed in 1.0.1. This is a severe bug for every production deployment.

[soichih]

I am having the same issue.. so I am subscribing to this thread.

[erikh]

@LK4D4 is this fully resolved by your patches? I was going to see if I could resolve this.

[LK4D4]

@erikh this is @icecrime patches in #6555, and yes them resolves this. I think it needs just a little polish before merge.

[danishabdullah]

+1...
having same issue

[meetri]

+1 ...
me too. Looking forward to a fix. I can't use this in production until this is resolved. :(

is there a known workaround for the time being?

[llonchj]

+1

[ku1ik]

Just hit the same thing with docker 1.0.0 on a production box...

[i0n]

+1

Client version: 1.1.2
Client API version: 1.13
Go version (client): go1.2
Git commit (client): d84a070
Server version: 1.1.2
Server API version: 1.13
Go version (server): go1.2
Git commit (server): d84a070

[katcipis]

+1

Client version: 1.0.1
Client API version: 1.12
Go version (client): go1.2.1
Git commit (client): 990021a
Server version: 1.0.1
Server API version: 1.12
Go version (server): go1.2.1
Git commit (server): 990021a

[phemmer]

Just an FYI as clarification for the new people coming to this bug. This has been fixed. It will be part of 1.2.1 which hasn't been released yet.

[luxn0429]

when will v1.2.1 be released?

[kriss9]

+1
Client version: 1.1.2
Client API version: 1.13
Go version (client): go1.2.2
Git commit (client): d84a070/1.1.2
Server version: 1.1.2
Server API version: 1.13
Go version (server): go1.2.2
Git commit (server): d84a070/1.1.2

[adamhadani]

@phemmer - any dates for 1.2.1? this is critical bug for us (and for many other folks it seems). few questions -

1. Any issues tagged for 1.2.1 milestone that could use community help in fixing / QAing?
2. any 1.2.1 RC thats available for community to test-drive and report feedback on?
3. if alot of open issues remaining, is it possible split em off into a future release so 1.2.1 can be released as is with this major bug fix?

[crosbymichael]

You can test 1.3.0 with this fix here:

#8323

[adamhadani]

@crosbymichael - thanks! have you been trying this? any regressions / other major issues already known with this RC to watch out for? will definitely take it for test drive

[crosbymichael]

Well, I would not push the RC to your production servers but this build should be stable for you to help test. If you have any problem please let us know before the release so we can get it fixed and you have a proper release to run in production.

[adamhadani]

@crosbymichael - Got it thanks, and one last Q before i get into this - Is there an updated CHANGELOG anywhere to look over? would be useful to know what new features / modifications / bug fixes there are in this release before I deploy it here

[crosbymichael]

The last commit in that branch includes a high level changelog. Docker is very active and there are too many commits in each release to include everything in the changelog. So just git log v1.2.0..

[adamhadani]

@crosbymichael - got it, thanks

[kung-foo]

+1

docker run --rm -it -p "8000:8080" mahcontainer
2014/10/15 22:17:49 Error response from daemon: Bind for 0.0.0.0:8000 failed: port is already allocated

Client version: 1.3.0
Client API version: 1.15
Go version (client): go1.3.3
Git commit (client): f1e7de2
OS/Arch (client): linux/amd64
Server version: 1.3.0
Server API version: 1.15
Go version (server): go1.3.3
Git commit (server): f1e7de2

[adamhadani]

@crosbymichael been running that binary RC for few days now, looking good so far. mostly doing login/pull/start/stop/rm flows as part of a deployment process and looks solid, containers restart well and haven't run into the "port already bound" issue so far.

[buzypi]

Faced this issue in CoreOS - Docker v 1.2.0.

No running or stopped container was claiming the port when I tried to run a new container using a port that was previously used.

[jessfraz]

@buzypi the issue was fixed in 1.3.0, let us know if you are still seeing it after upgrading

[soichih]

@jfrazelle Great! Do you know when will the fix be released on RHEL6 epel?

Actually, do you recommend compiling / installing Docker directly from docker.com?

[jessfraz]

you can download just the docker binary if you would like and swap that out
for now, this might be the easiest way.
https://docs.docker.com/installation/binaries/ Unsure when the RHEL package
will be updated.

On Fri, Nov 14, 2014 at 6:38 PM, Soichi Hayashi notifications@github.com
wrote:

@jfrazelle https://github.com/jfrazelle Great! Do you know when will
the fix be released on RHEL6 epel?

Actually, do you recommend compiling / installing Docker directly from
docker.com?

—
Reply to this email directly or view it on GitHub
#6476 (comment).

[wkf]

@jfrazelle was this actually fixed? It looks like @kung-foo is reporting the issue even in 1.3.0?

[jessfraz]

this issue has a lot of noise, @kung-foo if you are having a problem with ports in use on the latest version, please open a new issue, so it gets the attention it deserves.

[kung-foo]

In my case, I ended up rebuilding all of the containers and the problem was no longer reproducible.

[amalagaura]

I am still seeing this on version 1.4.1. It is unfortunate because I cannot restart docker since it is on production.

[LK4D4]

@amalagaura Can you open new issue and describe how you run containers? so we can find reproduction case. Thanks for report!

[devel0]

I have the issue, first of all my netstat -tlp not report any listen docker-proxy on the port I try to bind to ( port 50000 ) and docker fails with follow

root@phy:~# docker run -d -ti -h test -p "50000:22" ubuntu
2869b2513188e12061e8beaa65557e6edc882fd948522d6ae32a60c23a58ea50
docker: Error response from daemon: driver failed programming external connectivity on endpoint sick_kare (c4ce18c4382fdd948059e46a8c98fc29b886b1f55c9556a76ccc980916153eea): Bind for 0.0.0.0:50000 failed: port is already allocated.

/var/log/syslog reports:

Oct 12 21:32:53 phy kernel: [12170.580825] aufs au_opts_verify:1597:dockerd[2793]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:32:53 phy kernel: [12170.790935] aufs au_opts_verify:1597:dockerd[2793]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:32:53 phy kernel: [12170.903157] aufs au_opts_verify:1597:dockerd[2128]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:32:53 phy systemd-udevd[16847]: Could not generate persistent MAC address for veth1a0e9b6: No such file or directory
Oct 12 21:32:53 phy systemd-udevd[16849]: Could not generate persistent MAC address for vetha377cc4: No such file or directory
Oct 12 21:32:53 phy kernel: [12170.905898] device vetha377cc4 entered promiscuous mode
Oct 12 21:32:53 phy kernel: [12170.906016] IPv6: ADDRCONF(NETDEV_UP): vetha377cc4: link is not ready
Oct 12 21:32:53 phy dockerd[2109]: time="2016-10-12T21:32:53.874022431+02:00" level=warning msg="Failed to allocate and map port 50000-50000: Bind for 0.0.0.0:50000 failed: port is already allocated"
Oct 12 21:32:53 phy kernel: [12171.287673] docker0: port 1(vetha377cc4) entered disabled state
Oct 12 21:32:53 phy kernel: [12171.291129] device vetha377cc4 left promiscuous mode
Oct 12 21:32:53 phy kernel: [12171.291132] docker0: port 1(vetha377cc4) entered disabled state
Oct 12 21:32:54 phy dockerd[2109]: time="2016-10-12T21:32:54.204770029+02:00" level=error msg="Handler for POST /v1.24/containers/2869b2513188e12061e8beaa65557e6edc882fd948522d6ae32a60c23a58ea50/start returned error: driver failed programming external connectivity on endpoint sick_kare (c4ce18c4382fdd948059e46a8c98fc29b886b1f55c9556a76ccc980916153eea): Bind for 0.0.0.0:50000 failed: port is already allocated"

while if I try with a different port ( 50001 ) it works
and syslog reports

Oct 12 21:34:33 phy kernel: [12270.923521] aufs au_opts_verify:1597:dockerd[2793]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:34:33 phy kernel: [12271.186821] aufs au_opts_verify:1597:dockerd[2793]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:34:33 phy systemd-udevd[17015]: Could not generate persistent MAC address for vethc08dcd4: No such file or directory
Oct 12 21:34:33 phy kernel: [12271.290075] aufs au_opts_verify:1597:dockerd[2214]: dirperm1 breaks the protection by the permission bits on the lower branch
Oct 12 21:34:33 phy kernel: [12271.292078] device vethafba9bc entered promiscuous mode
Oct 12 21:34:33 phy kernel: [12271.292193] IPv6: ADDRCONF(NETDEV_UP): vethafba9bc: link is not ready
Oct 12 21:34:33 phy systemd-udevd[17016]: Could not generate persistent MAC address for vethafba9bc: No such file or directory
Oct 12 21:34:34 phy kernel: [12271.841888] eth0: renamed from vethc08dcd4
Oct 12 21:34:34 phy kernel: [12271.861628] IPv6: ADDRCONF(NETDEV_CHANGE): vethafba9bc: link becomes ready
Oct 12 21:34:34 phy kernel: [12271.861646] docker0: port 1(vethafba9bc) entered forwarding state
Oct 12 21:34:34 phy kernel: [12271.861653] docker0: port 1(vethafba9bc) entered forwarding state
Oct 12 21:34:49 phy kernel: [12286.910151] docker0: port 1(vethafba9bc) entered forwarding state

I think something stuck when I tried to create a 2th layer using port map 50000 with my previous tests and now I cannot use that port any more neither it is really free in the os.

any suggestion, workarounds ?

[aboch]

@devel0
workaround: remove the file /var/lib/docker/network/files/local-kv.db then restart the daemon.
(Be aware you'll have to recreate your networks)

Also, this problem has been reported in more recent issues, and it is liley not related to this old GH issue which is in closed state and it is related to docker 1.0.0.

Feel free to update anyof the existing issue with your docker version and steps to reproduce.
In particular the error you are facing seems related to some stale data in the local datastore.
This may happen becasue of an ungraceful shutdown of the daemon.

[mavenugo]

A lot has changed from docker 1.0.0 & using this issue for later versions isn't useful. I will lock this issue for now. we can unlock it if someone see a need for it.