Bug 1437121

Created attachment 1267310 [details]
desc build

Created attachment 1267311 [details]
desc pod

This seems like a scheduler problem..  the pod is stuck in pending and never got scheduled/rescheduled after the initial failure to start the container.

Either the pod should be getting marked failed, or it should eventually get run.  The build can't do much about it if it sits in pending indefinitely.

The describe output for the pod in question:

Error syncing pod, skipping: failed to "StartContainer" for "sti-build" with RunContainerError$
 "runContainer: Error response from daemon: {\"message\":\"devmapper: Thin Pool has 6075 free data blocks which is less than minimum required 6083 free data blocks. Create more free space in thin pool or use dm.min_free_space option to change behavior\$


Was this error actually fixed?  It looks like you are still consuming too much disk space.

The reason the thin pool is full is there are a lot of dangling layers being stored by docker i.e. thin devices that don't correlate to any container/image.

docker containers:
http://pastebin.test.redhat.com/469849

there were only 2 images with -a

docker layers:
http://pastebin.test.redhat.com/469960

yet there are almost 700 thin devices (layers)

Could be the result of failed builds.

docker is not cleaning these up and once they are orphaned like this, I'm not sure how to clean them up.

Moving to Containers for more investigation.

I deleted all the project here are the stats after that

docker ps -a 
root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # docker ps -a
CONTAINER ID        IMAGE               COMMAND             CREATED             STATUS              PORTS               NAMES


root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # ls -l | wc -l
652

root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # ~/get-thin-ls.sh | wc -l
652

root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # lvs
  LV          VG        Attr       LSize  Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  docker-pool docker_vg twi-a-t--- 29.70g             86.61  53.91                           
root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # vgs
  VG        #PV #LV #SN Attr   VSize  VFree  
  docker_vg   1   1   0 wz--n- 30.00g 236.00m

Specially after deleting the projects it should have reclaimed the space. Please let me know if there is anything else needed, I still have the env.

Please attach the output from $(docker info).  We are looking for dead containers.

Docker info on both the worker nodes

root@ip-172-31-8-87: /var/lib/docker/devicemapper/mnt # docker info
Containers: 0
 Running: 0
 Paused: 0
 Stopped: 0
Images: 0
Server Version: 1.12.6
Storage Driver: devicemapper
 Pool Name: docker_vg-docker--pool
 Pool Blocksize: 524.3 kB
 Base Device Size: 10.74 GB
 Backing Filesystem: xfs
 Data file: 
 Metadata file: 
 Data Space Used: 27.62 GB
 Data Space Total: 31.89 GB
 Data Space Available: 4.27 GB
 Metadata Space Used: 18.09 MB
 Metadata Space Total: 33.55 MB
 Metadata Space Available: 15.47 MB
 Thin Pool Minimum Free Space: 3.189 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: true
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Library Version: 1.02.135-RHEL7 (2016-11-16)
Logging Driver: journald
Cgroup Driver: systemd
Plugins:
 Volume: local
 Network: overlay host bridge null
 Authorization: rhel-push-plugin
Swarm: inactive
Runtimes: docker-runc runc
Default Runtime: docker-runc
Security Options: seccomp selinux
Kernel Version: 3.10.0-514.10.2.el7.x86_64
Operating System: Red Hat Enterprise Linux Server 7.3 (Maipo)
OSType: linux
Architecture: x86_64
Number of Docker Hooks: 2
CPUs: 4
Total Memory: 15.26 GiB
Name: ip-172-31-8-87.us-west-2.compute.internal
ID: VHAL:ZTY2:A33U:LPS5:F437:E7LG:MLOZ:YLIW:AG5G:XPNJ:OQOR:PICC
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://registry.ops.openshift.com/v1/
Insecure Registries:
 registry.ops.openshift.com
 127.0.0.0/8
Registries: registry.ops.openshift.com (insecure), registry.access.redhat.com (secure), docker.io (secure)



root@ip-172-31-34-20: ~ # docker info
Containers: 2
 Running: 2
 Paused: 0
 Stopped: 0
Images: 2
Server Version: 1.12.6
Storage Driver: devicemapper
 Pool Name: docker_vg-docker--pool
 Pool Blocksize: 524.3 kB
 Base Device Size: 10.74 GB
 Backing Filesystem: xfs
 Data file: 
 Metadata file: 
 Data Space Used: 26.36 GB
 Data Space Total: 31.89 GB
 Data Space Available: 5.536 GB
 Metadata Space Used: 14.86 MB
 Metadata Space Total: 33.55 MB
 Metadata Space Available: 18.69 MB
 Thin Pool Minimum Free Space: 3.189 GB
 Udev Sync Supported: true
 Deferred Removal Enabled: true
 Deferred Deletion Enabled: false
 Deferred Deleted Device Count: 0
 Library Version: 1.02.135-RHEL7 (2016-11-16)
Logging Driver: journald
Cgroup Driver: systemd
Plugins:
 Volume: local
 Network: host bridge null overlay
 Authorization: rhel-push-plugin
Swarm: inactive
Runtimes: docker-runc runc
Default Runtime: docker-runc
Security Options: seccomp selinux
Kernel Version: 3.10.0-514.10.2.el7.x86_64
Operating System: Red Hat Enterprise Linux Server 7.3 (Maipo)
OSType: linux
Architecture: x86_64
Number of Docker Hooks: 2
CPUs: 4
Total Memory: 15.26 GiB
Name: ip-172-31-34-20.us-west-2.compute.internal
ID: VHAL:ZTY2:A33U:LPS5:F437:E7LG:MLOZ:YLIW:AG5G:XPNJ:OQOR:PICC
Docker Root Dir: /var/lib/docker
Debug Mode (client): false
Debug Mode (server): false
Registry: https://registry.ops.openshift.com/v1/
Insecure Registries:
 registry.ops.openshift.com
 127.0.0.0/8
Registries: registry.ops.openshift.com (insecure), registry.access.redhat.com (secure), docker.io (secure)

Are you doing forced removal of container. I suspect forced removal might be going on. That means container will disappear from "docker info" view but it will still be with deivcemapper graph driver and will keep thin pool full.

If yes, we need to stop doing force removal of containers.

Ben already checked containers are not force removed.

if this is the conversation i remember from IRC i was asked if we force delete pods, which we don't.

We do force delete containers, at least until the recent changes to s2i are propagated into origin (as dug up by Jhon).

I'll make a pull to bump s2i tomorrow.

If we think that's the only issue here, please feel free to assign the bug to me.

s2i bump here: 
https://github.com/openshift/origin/pull/13633

I believe this issue is happening due to force container removal. Another way to verify this is to look into /var/lib/docker/devicemapper/metadata/ directory and if you see bunch of files having "-init" as suffix in their name, you know these are container metadata files.

For example.

c26669fe1dd29a6b0268a63072edd22a588151e60c47ef97ba49b53350b01752-init

If that's the case, there is a chance this is leftover from forced container removal and that's consuming space in thin pool.

I see 429 *-init files on one node and 259 on another one.

e8ecd1344de5f381dcbfca75619fe3ff31189c0fd753c2ad086521f73e10ff93-init
e98efcd0e01611fc889e60b98f23f9dbbe9b36f58d6e5588adc13dec80861842-init
eb19b2cfd5e5655ebb89fc079de6094a8886bd5ab9e18e19c2856920106021e7-init
eb455a45a32dfb89e230b012c14966b8fb76e389c89122df9892ec404f9b7700-init
ebb80ecca6d87ecbe183231ed3e3c53eca38d9021f6c6df6491183c62168efb4-init
ebebae8d818a8d26191ea89c94886d49ee69e5caade69f2e52db8c541a7b905d-init
ec993c8e3225a023f806d106b00fc125bcb811928a06a4489993059e135ab047-init
ed03d3f07d20040fea4ceef770509b4109561b261eceff9877d2c268d7af64b3-init
ee1a34ffa5d7e2a600be014481e707288feb9c3fcde6c61105f288ebe3e14bdc-init
efd1639dc9a921873f174624e584987919d857bd069ea14517440869a1402a9b-init
efdc99a4d6e742a42be8c57ecbf60745ab2c7ffd48894612cd9bf282c988b54b-init
f06fd584d21b608b5cff06b701b826399fc34162c9369801578ed6b5bf6a72d9-init
f0c59543627c4e9e0be4a652b395d88e636459f50357807084acae9957cf2d46-init
f12ca63c98bcbf11fbfa569e7adf3f20f236ddca228ddb32f8ced09463362935-init
f4d2ffe51cbe09102be559c285f7131cbce6384cb6f2e855ccc08b83a2d730d2-init
f54bef1e9308f2211d7de0eb036f801792e2e1b902f063871168c10fd3e389d1-init
f638ddbea61ddcd46a36e61e46695228c56a02b5cdec6b5cc0814e9d247520cc-init
f8b295891d2ad650e06f8c3fc374ba0c919587878ed94cb23eaef031203a7b76-init
f8ce10e254918339c14e13cdccebe34ffef2e502574b8feb93b854040cd7a5b7-init
fb4a4c0c6c23fcec4e59b1d1babc900ddcee6f851bed78e1e10045e983e6d36a-init
fd16a5c26652e21242704fefabd7b6b05e0c24d82450683205a15893d1f75869-init
fef53ef677614303086b5ea7c30f58baf0a205c9a8fd85368057cafb4977a2de-init
ff31c0dfa6588e570ebf71e47d8d132d1aac6bf139985a5c3b05a39f2b80fcc4-init
ffaae4fe1dcd687dd32cd1e549ac8a7babfc202c30c6f66502ea9e4fe04062c4-init
ffd178798f92d49eab7ad5c0854af990b49f03afa52724223f1ccd583d9b6dd8-init

So this is the case of left over containers after forced removal. Lets fix that and re-run and see if problem is still visible.

k, assigning to me, the PR is already created, i'll move this to on_qa for re-testing once it merges.

(In reply to Vikas Laad from comment #14)
> I see 429 *-init files on one node and 259 on another one.

Vikas, 

Remember, just presence of -init file itself does not mean we have the case
of forced remove container. It just means that this belongs to
container metadata (and not image metadata)

If these containers are not visible in "docker ps -a" output, that means
that devicemapper has data about some container which is not visible
to docker upper layer. And that means that somebody did a force removal
of container.

(In reply to Vivek Goyal from comment #17)

Right, "docker ps -a" returns 2 containers total from both the nodes.

Hello Vikas,could you help verify this bug?

Wei, I started my tests to verify this.

I tested again on following openshift version
openshift v3.5.5.5
kubernetes v1.5.2+43a9be4
etcd 3.1.0

Did lots of cakephp app builds, after some time nodes started running out of disk space and builds started failing. Here are the completed and failed builds numbers
root@ip-172-31-22-217: ~ # oc get build --all-namespaces | wc -l
2550
root@ip-172-31-22-217: ~ # oc get build --all-namespaces | grep Complete |wc -l                                                                               
1334
root@ip-172-31-22-217: ~ # oc get build --all-namespaces | grep Failed |wc -l                                                                                 
1216

stats on one of the worker nodes
root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # ls -l *-init | wc -l
63
root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # lvs
  LV          VG        Attr       LSize  Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  docker-pool docker_vg twi-aot--- 29.70g             88.82  46.51                           
root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # vgs
  VG        #PV #LV #SN Attr   VSize  VFree  
  docker_vg   1   1   0 wz--n- 30.00g 236.00m

After checking I deleted all the projects, and now I do not see any running containers on the worker nodes. Here are the stats after deleting projects

root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # lvs
  LV          VG        Attr       LSize  Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  docker-pool docker_vg twi-a-t--- 29.70g             75.60  38.12                           
root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # vgs
  VG        #PV #LV #SN Attr   VSize  VFree  
  docker_vg   1   1   0 wz--n- 30.00g 236.00m
root@ip-172-31-34-80: /var/lib/docker/devicemapper/metadata # ls -l *-init | wc -l
69

As we can see above there are still *-init files exists in docker director and disk space is also not claimed by docker.

Ben, please let me know if I am running a old build or there is something wrong.

The change to not force kill containers was put into origin(https://github.com/openshift/origin/pull/13633), it was not backported to 3.5.

Verification of this bug is blocked by https://bugzilla.redhat.com/show_bug.cgi?id=1442875

I am able to run my tests with docker version 

root@ip-172-31-4-211: ~ # docker version
Client:
 Version:         1.12.6
 API version:     1.24
 Package version: docker-common-1.12.6-16.el7.x86_64
 Go version:      go1.7.4
 Git commit:      3a094bd/1.12.6
 Built:           Tue Mar 21 13:30:59 2017
 OS/Arch:         linux/amd64

Server:
 Version:         1.12.6
 API version:     1.24
 Package version: docker-common-1.12.6-16.el7.x86_64
 Go version:      go1.7.4
 Git commit:      3a094bd/1.12.6
 Built:           Tue Mar 21 13:30:59 2017
 OS/Arch:         linux/amd64

There were many build failures, here are the stats on both the nodes. I see less number of -init files
root@ip-172-31-17-182: /var/lib/docker/devicemapper/metadata # docker ps -a | wc -l
43
root@ip-172-31-17-182: /var/lib/docker/devicemapper/metadata # ls *-init | wc -l   
52

Another node
root@ip-172-31-43-54: /var/lib/docker/devicemapper/metadata # docker ps -a | wc -l
55
root@ip-172-31-43-54: /var/lib/docker/devicemapper/metadata # ls *-init | wc -l
81

I am still running tests, will close it after couple of cycles.

Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2017:1425