Open files after docker containers removed

[tnachen]

docker version:

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

I ran out of file descriptors running docker run, and I realized docker daemon is holding on to a lot of file handles (11110 of them), while I only have 6 containers with docker ps -a

lots of them looks like this:

6c665c78a63396955dc76873bd8636bb642b38b43ec0e6-json.log (deleted)
docker 6937 root 329u unix 0xffff880166560e00 0t0 353408770 /var/run/docker.sock
docker 6937 root 330r REG 9,2 0 1627517 /var/lib/docker/containers/0734b3b41a4b039cf983cb690b1ad2814a8434289752f8082fd312e837f04672/0734b3b41a4b039cf9
83cb690b1ad2814a8434289752f8082fd312e837f04672-json.log (deleted)
docker 6937 root 331u unix 0xffff880166560a80 0t0 353427790 /var/run/docker.sock
docker 6937 root 332r REG 9,2 219 1627529 /var/lib/docker/containers/933d4e44aa370529284c40b5a1fae6ecf5e887e285d9860ba44ce61439c692f0/933d4e44aa37052928
4c40b5a1fae6ecf5e887e285d9860ba44ce61439c692f0-json.log (deleted)
docker 6937 root 333u unix 0xffff881024179c00 0t0 353428260 /var/run/docker.sock
docker 6937 root 334r REG 9,2 220 1627499 /var/lib/docker/containers/70607073f3aa18cfcd05d8a3ef52b15bc59d4dbafaacd2f45f39890c7eee19e3/70607073f3aa18cfcd
05d8a3ef52b15bc59d4dbafaacd2f45f39890c7eee19e3-json.log (deleted)
docker 6937 root 335u unix 0xffff8809fd121f80 0t0 353441825 /var/run/docker.sock
docker 6937 root 336u unix 0xffff880166562300 0t0 353426334 /var/run/docker.sock
docker 6937 root 337r REG 9,2 75 1627531 /var/lib/docker/containers/6695d56daf8b312e34b613c24e995d3c71d14fba0ee1189db74a189572f01a11/6695d56daf8b312e34
b613c24e995d3c71d14fba0ee1189db74a189572f01a11-json.log (deleted)
docker 6937 root 338r REG 9,2 107 1627524 /var/lib/docker/containers/e9305143bc65c98b116a38aa56d80813e74923d213a1d0c8c2096293fce6814b/e9305143bc65c98b11
6a38aa56d80813e74923d213a1d0c8c2096293fce6814b-json.log (deleted)
docker 6937 root 339u unix 0xffff8809fd124d00 0t0 353442787 /var/run/docker.sock
docker 6937 root 340r REG 9,2 74 1627530 /var/lib/docker/containers/f6ba7a20569957ccee8ea51fb3ea181e1107572217312645e003472933b47fce/f6ba7a20569957ccee
8ea51fb3ea181e1107572217312645e003472933b47fce-json.log (deleted)
docker 6937 root 341u unix 0xffff881024179180 0t0 353455659 /var/run/docker.sock
docker 6937 root 342r REG 9,2 107 1627520 /var/lib/docker/containers/7b692bbda1e77df58b75c78394f7cee05ab476bf665c9d5ea8e6c454be1253e7/7b692bbda1e77df58b
75c78394f7cee05ab476bf665c9d5ea8e6c454be1253e7-json.log (deleted)
docker 6937 root 343u unix 0xffff8809fd123800 0t0 353473830 /var/run/docker.sock
docker 6937 root 344u unix 0xffff880a2eda3100 0t0 353485041 /var/run/docker.sock
docker 6937 root 345r REG 9,2 107 1627532 /var/lib/docker/containers/7f9706c3eb50d0047f0a254fedd8cfcf3c24d5ce6beb30ac17e488c54e600b11/7f9706c3eb50d0047f
0a254fedd8cfcf3c24d5ce6beb30ac17e488c54e600b11-json.log (deleted)
docker 6937 root 346r REG 9,2 219 1627536 /var/lib/docker/containers/93e745632e8ced642b9f87a2a6991aace88e4e36172d430e09715d3d093ab0bd/93e745632e8ced642b
9f87a2a6991aace88e4e36172d430e09715d3d093ab0bd-json.log (deleted)
docker 6937 root 347u unix 0xffff88015c303100 0t0 353485124 /var/run/docker.sock
docker 6937 root 348u unix 0xffff8801b046c600 0t0 353487224 /var/run/docker.sock
docker 6937 root 349r REG 9,2 75 1627538 /var/lib/docker/containers/5951bc184d7678055eb63f0b561657e12831b04d40c1c8b8548ca29d32d8ea85/5951bc184d7678055e
b63f0b561657e12831b04d40c1c8b8548ca29d32d8ea85-json.log (deleted)
docker 6937 root 350u unix 0xffff880166567380 0t0 353476902 /var/run/docker.sock
docker 6937 root 351r REG 9,2 107 1627534 /var/lib/docker/containers/4e3be7bcc0f2e3cc59f68191ed005ef2152821845cca2a16f94c1ea84d4cfb2f/4e3be7bcc0f2e3cc59
f68191ed005ef2152821845cca2a16f94c1ea84d4cfb2f-json.log (deleted)
docker 6937 root 352r REG 9,2 75 1627526 /var/lib/docker/containers/c1f591f680628cc90f0a7bde12d9defc17911cbaf2c8b4a01414cdeff2f30d90/c1f591f680628cc90f
0a7bde12d9defc17911cbaf2c8b4a01414cdeff2f30d90-json.log (deleted)

[tnachen]

Just a bit more context, we're calling docker logs --follow on the container, and after the container is removed also do a kill -TERM on the docker logs --follow process since there is an existing bug where docker logs --follow hangs forever if the container doesn't exist.
Not sure if it's related though.

[jessfraz]

are you able to reproduce on the latest version of docker and if so can you please give exact steps to do so

[jessfraz]

closing as stale please ping me with exact steps to reproduce on the latest version and I will reopen

[timothysc]

Not so quick on the draw @jfrazelle, here is your repo https://bugzilla.redhat.com/show_bug.cgi?id=1189028 , happens on 1.5 too.

[jeremyeder]

• Comparing static binary with dynbinary...try latest docker (non-dynbinary):

# date
Fri Mar 13 15:28:44 EDT 2015
# wget https://get.docker.com/builds/Linux/x86_64/docker-latest -O docker

# DEBUG=1 ./docker -d --storage-opt dm.metadatadev=/dev/docker/metadata --storage-opt dm.datadev=/dev/docker/data --selinux-enabled

# DEBUG=1 ./docker info | grep -i fd
Fds: 11
# ./docker run -t -i --rm busybox /bin/true
# DEBUG=1 ./docker info | grep -i fd
Fds: 12
# ./docker run -t -i --rm busybox /bin/true
# DEBUG=1 ./docker info | grep -i fd
Fds: 12
# ./docker run -t -i --rm busybox /bin/true
# DEBUG=1 ./docker info | grep -i fd
Fds: 12

# ls -al /proc/`pidof docker`/fd
total 0
dr-x------. 2 root root  0 Mar 13 15:21 .
dr-xr-xr-x. 8 root root  0 Mar 13 15:21 ..
lr-x------. 1 root root 64 Mar 13 15:21 0 -> /dev/null
lrwx------. 1 root root 64 Mar 13 15:21 1 -> socket:[157480]
lrwx------. 1 root root 64 Mar 13 15:21 14 -> socket:[174651]
lrwx------. 1 root root 64 Mar 13 15:21 18 -> socket:[177423]
lrwx------. 1 root root 64 Mar 13 15:21 2 -> socket:[157480]
lr-x------. 1 root root 64 Mar 13 15:21 3 -> /dev/urandom
lrwx------. 1 root root 64 Mar 13 15:21 4 -> /dev/mapper/control
lrwx------. 1 root root 64 Mar 13 15:21 5 -> socket:[183012]
lrwx------. 1 root root 64 Mar 13 15:21 6 -> /var/lib/docker/linkgraph.db
lrwx------. 1 root root 64 Mar 13 15:21 7 -> anon_inode:[eventpoll]
lr-x------. 1 root root 64 Mar 13 15:21 8 -> anon_inode:inotify

• After creating/destroying a few containers the FD count remains constant.

---

• Now with the dynbinary:

# systemctl start docker
# ls -al /proc/`pidof docker`/fd
total 0
dr-x------. 2 root root  0 Mar 13 15:23 .
dr-xr-xr-x. 8 root root  0 Mar 13 15:23 ..
lr-x------. 1 root root 64 Mar 13 15:23 0 -> /dev/null
lrwx------. 1 root root 64 Mar 13 15:23 1 -> socket:[211719]
lrwx------. 1 root root 64 Mar 13 15:23 2 -> socket:[211719]
lr-x------. 1 root root 64 Mar 13 15:23 3 -> /dev/urandom
lrwx------. 1 root root 64 Mar 13 15:23 4 -> /dev/mapper/control
lrwx------. 1 root root 64 Mar 13 15:23 5 -> /var/lib/docker/linkgraph.db
lr-x------. 1 root root 64 Mar 13 15:23 6 -> anon_inode:inotify
lrwx------. 1 root root 64 Mar 13 15:23 7 -> socket:[191437]
lrwx------. 1 root root 64 Mar 13 15:23 8 -> anon_inode:[eventpoll]
lrwx------. 1 root root 64 Mar 13 15:23 9 -> socket:[191439]

# for i in $(seq 10); do ./docker run -t -i --rm busybox /bin/true ; done

# ls -al /proc/`pidof docker`/fd
total 0
dr-x------. 2 root root  0 Mar 13 15:23 .
dr-xr-xr-x. 8 root root  0 Mar 13 15:23 ..
lr-x------. 1 root root 64 Mar 13 15:23 0 -> /dev/null
lrwx------. 1 root root 64 Mar 13 15:23 1 -> socket:[211719]
lrwx------. 1 root root 64 Mar 13 15:23 14 -> socket:[202348]
lrwx------. 1 root root 64 Mar 13 15:23 15 -> socket:[216107]
lrwx------. 1 root root 64 Mar 13 15:23 17 -> socket:[220181]
lrwx------. 1 root root 64 Mar 13 15:23 19 -> socket:[216153]
lrwx------. 1 root root 64 Mar 13 15:23 2 -> socket:[211719]
lrwx------. 1 root root 64 Mar 13 15:23 20 -> socket:[197957]
lrwx------. 1 root root 64 Mar 13 15:23 21 -> socket:[210670]
lrwx------. 1 root root 64 Mar 13 15:23 22 -> socket:[216488]
lrwx------. 1 root root 64 Mar 13 15:23 24 -> socket:[212262]
lrwx------. 1 root root 64 Mar 13 15:23 25 -> socket:[222317]
lrwx------. 1 root root 64 Mar 13 15:23 26 -> socket:[201685]
lrwx------. 1 root root 64 Mar 13 15:23 27 -> socket:[225364]
lr-x------. 1 root root 64 Mar 13 15:23 3 -> /dev/urandom
lrwx------. 1 root root 64 Mar 13 15:23 4 -> /dev/mapper/control
lrwx------. 1 root root 64 Mar 13 15:23 5 -> /var/lib/docker/linkgraph.db
lr-x------. 1 root root 64 Mar 13 15:23 6 -> anon_inode:inotify
lrwx------. 1 root root 64 Mar 13 15:23 7 -> socket:[191437]
lrwx------. 1 root root 64 Mar 13 15:23 8 -> anon_inode:[eventpoll]

• All these extra sockets don't seem to ever close, and they keep growing as containers come and go...only seems to happen with dynbinary.

# for i in $(seq 100); do ./docker run -t -i --rm busybox /bin/true ; done
# DEBUG=1 docker info | grep Fd
Fds: 122
# ls -al /proc/`pidof docker`/fd | wc -l
123

[tianon]

Do we open a socket to talk to dockerinit, or does that happen through some other means?

[rhvgoyal]

@jeremyeder

I can't seem to reproduce this using your test case. Once for loop exits, number of Fds open still remain the same. I am using latest docker dynamically build binary on lvm thin pool as graphdriver.

[jeremyeder]

@rhvgoyal not sure if there are other parts to the puzzle, seemed pretty cut and dry to me. We have several other reports noted in https://bugzilla.redhat.com/show_bug.cgi?id=1189028

[rhvgoyal]

@jeremyeder

That report also says that "It doesn't happen on RHEL7 + docker 1.4.1"

So looks like it does not happen on all combinations. I guess it is a good thing as it should help us pin point the problem. BTW, I am using upstream kernel 4.0.-rc2 and latest docker. Following is how my docker info looks like.

Containers: 0
Images: 130
Storage Driver: devicemapper
Pool Name: docker-docker--pool
Pool Blocksize: 65.54 kB
Backing Filesystem: extfs
Data file:
Metadata file:
Data Space Used: 4.518 GB
Data Space Total: 489.6 GB
Data Space Available: 485.1 GB
Metadata Space Used: 11.5 MB
Metadata Space Total: 503.3 MB
Metadata Space Available: 491.8 MB
Udev Sync Supported: true
Library Version: 1.02.93 (2015-01-30)
Execution Driver: native-0.2
Kernel Version: 4.0.0-rc2+
Operating System: Fedora 21 (Twenty One)
CPUs: 24
Total Memory: 31.1 GiB

[42wim]

Same issue here, using latest docker running on RHEL6.6.
Doesn't matter if using static binary from docker or dynbinary from EPEL

# for i in $(seq 100); do docker run -t -i --rm busybox /bin/true ; done
# /proc/`pidof docker`/fd 21:42 # ls -al|wc
    247    2816   26061

Containing this stuff:

lr-x------ 1 root root 64 Mar 19 21:41 224 -> /cgroup/memory/docker/4702d400101a5c598181d37711049343263910e2876f161b46241c5e9dbdcff2/memory.oom_control (deleted)
lr-x------ 1 root root 64 Mar 19 21:41 226 -> /cgroup/memory/docker/952f932435c2b6bf9c11181a9a1e9fc0a4534134a1a789f05a87a12c22da4e7c/memory.oom_control (deleted)
lrwx------ 1 root root 64 Mar 19 21:41 227 -> [eventfd]
lr-x------ 1 root root 64 Mar 19 21:41 228 -> /cgroup/memory/docker/12f831d86f76ba5a02bee444625feb5779f6d76508f0788d3436e3c57ef36c89/memory.oom_control (deleted)

# ./docker --version
Docker version 1.5.0, build a8a31ef

# ./docker info
Containers: 150
Images: 436
Storage Driver: devicemapper
 Pool Name: docker-253:5-73734-pool
 Pool Blocksize: 65.54 kB
 Backing Filesystem: extfs
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data Space Used: 36.89 GB
 Data Space Total: 107.4 GB
 Metadata Space Used: 42.81 MB
 Metadata Space Total: 2.147 GB
 Udev Sync Supported: false
 Data loop file: /var/lib/docker/devicemapper/devicemapper/data
 Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata
 Library Version: 1.02.82-git (2013-10-04)
Execution Driver: native-0.2
Kernel Version: 2.6.32-504.8.1.el6.x86_64
Operating System: <unknown>
CPUs: 8
Total Memory: 7.684 GiB

[iangkent]

We are experiencing the same issue with docker 1.4.1 on RHEL 6.5 (2.6.32-504.8.1.el6.x86_64).
Our current workaround is to restart docker daemon.

Is there a better recommend workaround?

[amaltson]

I'm experiencing the exact same problem with Docker 1.6 and RHEL 6.6. We ran into this when the docker user reached it's limit on open files. I took a look at lsof and found a lot of the (deleted) file descriptors pointing to removed Docker containers.

# lsof -nP | grep docker
docker     2725      root  cwd       DIR              253,0       4096          2 /
docker     2725      root  rtd       DIR              253,0       4096          2 /
docker     2725      root  txt       REG              253,0   15443675     149299 /usr/bin/docker
docker     2725      root    1w      REG              253,0   14221171     815016 /var/log/docker
docker     2725      root    2w      REG              253,0   14221171     815016 /var/log/docker
docker     2725      root    3r      CHR                1,9        0t0       4170 /dev/urandom
docker     2725      root    4u      CHR              10,58        0t0       6084 /dev/mapper/control
docker     2725      root    5r      REG               0,28          0   19076234 /cgroup/memory/docker/8b155e930840e09e36ad7ddb65598e7412dbddf2a64add39fe0775ab7ef02e37/memory.oom_control (deleted)
docker     2725      root    6u     unix 0xffff880236faeb00        0t0      16234 /var/run/docker.sock
docker     2725      root    7u      REG                0,9          0       4163 [eventpoll]
docker     2725      root    8u      REG              253,2      26624   29633572 /transient/opt/docker/linkgraph.db
docker     2725      root    9u      REG              253,2      26624   29633572 /transient/opt/docker/linkgraph.db
docker     2725      root   10r      DIR               0,10          0          1 inotify
docker     2725      root   11r      REG               0,28          0   32400713 /cgroup/memory/docker/0ad1fc937d3ed540a2ab1656059d6205e739fa079d539a6740d4d6d542cfd3d1/memory.oom_control (deleted)
docker     2725      root   12r      REG               0,28          0   17925027 /cgroup/memory/docker/33dcb46c0d288198318c7e9f901b8e0ba7b6a5c390828529d7c9bfcb385b9d2f/memory.oom_control (deleted)
docker     2725      root   13u      REG                0,9          0       4163 [eventfd]
....
< over a 1000 more here>

Here's the docker info

# docker info
Containers: 2
Images: 114
Storage Driver: devicemapper
 Pool Name: docker-253:2-29633562-pool
 Pool Blocksize: 65.54 kB
 Backing Filesystem: extfs
 Data file: /dev/loop0
 Metadata file: /dev/loop1
 Data Space Used: 9.234 GB
 Data Space Total: 107.4 GB
 Data Space Available: 98.14 GB
 Metadata Space Used: 10.08 MB
 Metadata Space Total: 2.147 GB
 Metadata Space Available: 2.137 GB
 Udev Sync Supported: false
 Data loop file: /transient/opt/docker/devicemapper/devicemapper/data
 Metadata loop file: /transient/opt/docker/devicemapper/devicemapper/metadata
 Library Version: 1.02.82-git (2013-10-04)
Execution Driver: native-0.2
Kernel Version: 2.6.32-504.16.2.el6.x86_64
Operating System: <unknown>
CPUs: 4
Total Memory: 7.681 GiB
Name: devbuild1
ID: BURZ:PUHG:ECHK:KRO2:7N3L:HD7O:TJZE:VQP2:LFQL:3N3R:STCS:LBSE

[JohnMorales]

@iangkent: Another work around is to attach to the docker process and tell it to close the file descriptors.

I'm doing something like this:

gdb --batch-silent -p $(cat /var/run/docker.pid) <<< "$( ls /proc/$(cat /var/run/docker.pid)/fd -l --time-style=+'%s' | grep -E 'deleted' | awk '{ printf("p close(%s)\n", $7)}')"

Note: what I'm doing here is attaching to the docker daemon using gdb, and telling it to close file descriptors that have 'deleted' in the file listing..

It's ugly but better than restarting the containers that I want to keep running.

UPDATE: I noticed that killing eventfd descriptors can cause a tainted panic. Updated command to not remove those eventfd