{"action":"created","issue":{"url":"https://api.github.com/repos/docker/docker/issues/15833","labels_url":"https://api.github.com/repos/docker/docker/issues/15833/labels{/name}","comments_url":"https://api.github.com/repos/docker/docker/issues/15833/comments","events_url":"https://api.github.com/repos/docker/docker/issues/15833/events","html_url":"https://github.com/docker/docker/issues/15833","id":103104710,"number":15833,"title":"Docker 1.8.1 push issue to Registry 2.1.1 with nfs filesystem","user":{"login":"cubfan20","id":13873549,"avatar_url":"https://avatars.githubusercontent.com/u/13873549?v=3","gravatar_id":"","url":"https://api.github.com/users/cubfan20","html_url":"https://github.com/cubfan20","followers_url":"https://api.github.com/users/cubfan20/followers","following_url":"https://api.github.com/users/cubfan20/following{/other_user}","gists_url":"https://api.github.com/users/cubfan20/gists{/gist_id}","starred_url":"https://api.github.com/users/cubfan20/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/cubfan20/subscriptions","organizations_url":"https://api.github.com/users/cubfan20/orgs","repos_url":"https://api.github.com/users/cubfan20/repos","events_url":"https://api.github.com/users/cubfan20/events{/privacy}","received_events_url":"https://api.github.com/users/cubfan20/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/docker/docker/labels/group/distribution","name":"group/distribution","color":"F6FBFF"}],"state":"open","locked":false,"assignee":null,"milestone":null,"comments":28,"created_at":"2015-08-25T20:03:35Z","updated_at":"2015-11-02T14:19:53Z","closed_at":null,"body":"The following issue is occurring while pushing to a 2.1.1 registry with the 1.8.1 client.  Pushing works fine from a 1.7 client.\r\n    \r\n    10.228.19.127 - - [24/Aug/2015:21:33:22 +0000] \"PATCH /v2/here_cme_techops/onboarding/blobs/uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a?_state=TPtR3EHnTTJvS8W1Y4d9P909abHfq-mzi6OLcmHi5p17Ik5hbWUiOiJoZXJlX2NtZV90ZWNob3BzL29uYm9hcmRpbmciLCJVVUlEIjoiZjQ5YzYwYzYtZmE0Zi00MmQwLTg0MDQtODc3ZTAzMDVhMzNhIiwiT2Zmc2V0IjowLCJTdGFydGVkQXQiOiIyMDE1LTA4LTI0VDIxOjMzOjIyLjg5MjkyOTE0MVoifQ%3D%3D HTTP/1.1\" 202 0 \"\" \"docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-229.el7.x86_64 os/linux arch/amd64\"\r\n    time=\"2015-08-24T21:33:23Z\" level=warning msg=\"the ResponseWriter does not implement CloseNotifier\" http.request.host=docker.cme.in.here.com http.request.id=9228f638-cbab-430c-9e07-dc6cf77260f7 http.request.method=PUT http.request.remoteaddr=\"10.228.19.127:44234\" http.request.uri=\"/v2/here_cme_techops/onboarding/blobs/uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a?_state=3_czVRweJjfpzyAbaEnD7p-wR4qKjkqHltBRYAs1qxF7Ik5hbWUiOiJoZXJlX2NtZV90ZWNob3BzL29uYm9hcmRpbmciLCJVVUlEIjoiZjQ5YzYwYzYtZmE0Zi00MmQwLTg0MDQtODc3ZTAzMDVhMzNhIiwiT2Zmc2V0IjozMiwiU3RhcnRlZEF0IjoiMjAxNS0wOC0yNFQyMTozMzoyMloifQ%3D%3D&digest=sha256%3Aa3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4\" http.request.useragent=\"docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-229.el7.x86_64 os/linux arch/amd64\" instance.id=506c18e6-6186-4adc-af49-288afbe7ce23 vars.name=\"here_cme_techops/onboarding\" vars.uuid=f49c60c6-fa4f-42d0-8404-877e0305a33a version=v2.1.1\r\n    time=\"2015-08-24T21:33:23Z\" level=error msg=\"unable to delete layer upload resources \\\"/docker/registry/v2/repositories/here_cme_techops/onboarding/_uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a\\\": remove /tmp/registry/docker/registry/v2/repositories/here_cme_techops/onboarding/_uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a: directory not empty\" http.request.host=docker.cme.in.here.com http.request.id=9228f638-cbab-430c-9e07-dc6cf77260f7 http.request.method=PUT http.request.remoteaddr=\"10.228.19.127:44234\" http.request.uri=\"/v2/here_cme_techops/onboarding/blobs/uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a?_state=3_czVRweJjfpzyAbaEnD7p-wR4qKjkqHltBRYAs1qxF7Ik5hbWUiOiJoZXJlX2NtZV90ZWNob3BzL29uYm9hcmRpbmciLCJVVUlEIjoiZjQ5YzYwYzYtZmE0Zi00MmQwLTg0MDQtODc3ZTAzMDVhMzNhIiwiT2Zmc2V0IjozMiwiU3RhcnRlZEF0IjoiMjAxNS0wOC0yNFQyMTozMzoyMloifQ%3D%3D&digest=sha256%3Aa3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4\" http.request.useragent=\"docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-229.el7.x86_64 os/linux arch/amd64\" instance.id=506c18e6-6186-4adc-af49-288afbe7ce23 vars.name=\"here_cme_techops/onboarding\" vars.uuid=f49c60c6-fa4f-42d0-8404-877e0305a33a version=v2.1.1\r\n    time=\"2015-08-24T21:33:23Z\" level=error msg=\"unknown error completing upload: &os.PathError{Op:\\\"remove\\\", Path:\\\"/tmp/registry/docker/registry/v2/repositories/here_cme_techops/onboarding/_uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a\\\", Err:0x27}\" http.request.host=docker.cme.in.here.com http.request.id=9228f638-cbab-430c-9e07-dc6cf77260f7 http.request.method=PUT http.request.remoteaddr=\"10.228.19.127:44234\" http.request.uri=\"/v2/here_cme_techops/onboarding/blobs/uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a?_state=3_czVRweJjfpzyAbaEnD7p-wR4qKjkqHltBRYAs1qxF7Ik5hbWUiOiJoZXJlX2NtZV90ZWNob3BzL29uYm9hcmRpbmciLCJVVUlEIjoiZjQ5YzYwYzYtZmE0Zi00MmQwLTg0MDQtODc3ZTAzMDVhMzNhIiwiT2Zmc2V0IjozMiwiU3RhcnRlZEF0IjoiMjAxNS0wOC0yNFQyMTozMzoyMloifQ%3D%3D&digest=sha256%3Aa3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4\" http.request.useragent=\"docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-229.el7.x86_64 os/linux arch/amd64\" instance.id=506c18e6-6186-4adc-af49-288afbe7ce23 vars.name=\"here_cme_techops/onboarding\" vars.uuid=f49c60c6-fa4f-42d0-8404-877e0305a33a version=v2.1.1\r\n    time=\"2015-08-24T21:33:23Z\" level=error msg=\"unable to delete layer upload resources \\\"/docker/registry/v2/repositories/here_cme_techops/onboarding/_uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a\\\": remove /tmp/registry/docker/registry/v2/repositories/here_cme_techops/onboarding/_uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a/.nfs00000000a18136c600000014: device or resource busy\" http.request.host=docker.cme.in.here.com http.request.id=9228f638-cbab-430c-9e07-dc6cf77260f7 http.request.method=PUT http.request.remoteaddr=\"10.228.19.127:44234\" http.request.uri=\"/v2/here_cme_techops/onboarding/blobs/uploads/f49c60c6-fa4f-42d0-8404-877e0305a33a?_state=3_czVRweJjfpzyAbaEnD7p-wR4qKjkqHltBRYAs1qxF7Ik5hbWUiOiJoZXJlX2NtZV90ZWNob3BzL29uYm9hcmRpbmciLCJVVUlEIjoiZjQ5YzYwYzYtZmE0Zi00MmQwLTg0MDQtODc3ZTAzMDVhMzNhIiwiT2Zmc2V0IjozMiwiU3RhcnRlZEF0IjoiMjAxNS0wOC0yNFQyMTozMzoyMloifQ%3D%3D&digest=sha256%3Aa3ed95caeb02ffe68cdd9fd84406680ae93d633cb16422d00e8a7c22955b46d4\" http.request.useragent=\"docker/1.8.1 go/go1.4.2 git-commit/d12ea79 kernel/3.10.0-229.el7.x86_64 os/linux arch/amd64\" instance.id=506c18e6-6186-4adc-af49-288afbe7ce23 vars.name=\"here_cme_techops/onboarding\" vars.uuid=f49c60c6-fa4f-42d0-8404-877e0305a33a version=v2.1.1\r\n\r\nThe last line shows an nfs file handle as the reason the directory couldn't be cleaned up.\r\n\r\nHere are the last couple of lines from the server running the push:\r\n\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.762420755Z\" level=debug msg=\"rendered layer for d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff of [32] size\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.762420755Z\" level=debug msg=\"rendered layer for d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff of [32] size\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.778998985Z\" level=debug msg=\"[devmapper] Unmount done\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.778998985Z\" level=debug msg=\"[devmapper] Unmount done\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.779022595Z\" level=debug msg=\"[devmapper] deactivateDevice(d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.779022595Z\" level=debug msg=\"[devmapper] deactivateDevice(d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.779078093Z\" level=debug msg=\"[devmapper] RemoveDeviceDeferred START(docker-253:0-4205-d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.779078093Z\" level=debug msg=\"[devmapper] RemoveDeviceDeferred START(docker-253:0-4205-d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.796983128Z\" level=debug msg=\"[devmapper] RemoveDeviceDeferred END(docker-253:0-4205-d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.797013465Z\" level=debug msg=\"[devmapper] deactivateDevice END(d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.796983128Z\" level=debug msg=\"[devmapper] RemoveDeviceDeferred END(docker-253:0-4205-d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.797013465Z\" level=debug msg=\"[devmapper] deactivateDevice END(d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff)\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.797026445Z\" level=debug msg=\"[devmapper] UnmountDevice(hash=d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff) END\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.797026445Z\" level=debug msg=\"[devmapper] UnmountDevice(hash=d1ee9017809a0d7959b96982fecd01a7c33edaa38351eeb21ba8b469a218e1ff) END\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker[17863]: time=\"2015-08-25T19:43:12.999716785Z\" level=debug msg=\"Not continuing with error: Received unexpected HTTP status: 500 Internal Server Error\"\r\n    Aug 25 19:43:12 pchivcpbat291 docker: time=\"2015-08-25T19:43:12.999716785Z\" level=debug msg=\"Not continuing with error: Received unexpected HTTP status: 500 Internal Server Error\"\r\n\r\nPlease let me know what other info is needed.  As I stated above, this works fine in 1.7.\r\n\r\nDocker info from server running the push:\r\n\r\nuname -a:\r\n\r\n    Linux pchivcpbat291.lnx.in.here.com 3.10.0-229.el7.x86_64 #1 SMP Fri Mar 6 11:36:42 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux\r\n\r\ndocker version:\r\n\r\n    Client:\r\n    Version:      1.8.1\r\n    API version:  1.20\r\n    Go version:   go1.4.2\r\n    Git commit:   d12ea79\r\n    Built:        Thu Aug 13 02:19:43 UTC 2015\r\n    OS/Arch:      linux/amd64\r\n\r\n    Server:\r\n    Version:      1.8.1\r\n    API version:  1.20\r\n    Go version:   go1.4.2\r\n    Git commit:   d12ea79\r\n    Built:        Thu Aug 13 02:19:43 UTC 2015\r\n    OS/Arch:      linux/amd64\r\n\r\ndocker info:\r\n\r\n    Containers: 2\r\n    Images: 97\r\n    Storage Driver: devicemapper\r\n     Pool Name: docker-253:0-4205-pool\r\n     Pool Blocksize: 65.54 kB\r\n     Backing Filesystem: xfs\r\n     Data file: /dev/loop0\r\n     Metadata file: /dev/loop1\r\n     Data Space Used: 3.526 GB\r\n     Data Space Total: 107.4 GB\r\n     Data Space Available: 81.03 GB\r\n     Metadata Space Used: 5.267 MB\r\n     Metadata Space Total: 2.147 GB\r\n     Metadata Space Available: 2.142 GB\r\n     Udev Sync Supported: true\r\n     Deferred Removal Enabled: true\r\n     Data loop file: /var/lib/docker/devicemapper/devicemapper/data\r\n     Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata\r\n     Library Version: 1.02.93-RHEL7 (2015-01-28)\r\n    Execution Driver: native-0.2\r\n    Logging Driver: json-file\r\n    Kernel Version: 3.10.0-229.el7.x86_64\r\n    Operating System: CentOS Linux 7 (Core)\r\n    CPUs: 4\r\n    Total Memory: 15.52 GiB\r\n    Name: pchivcpbat291.lnx.in.here.com\r\n    ID: 2LHS:WDGG:P2JN:SNYP:B3ZB:YW32:DUMO:2LNO:TFCV:CGYX:NJN4:63D6\r\n\r\nDocker info from server running the registry:\r\n\r\nuname -a:\r\n\r\n    Linux pchivcpapp02.lnx.in.here.com 3.10.0-229.el7.x86_64 #1 SMP Fri Mar 6 11:36:42 UTC 2015 x86_64 x86_64 x86_64 GNU/Linux\r\n\r\ndocker version:\r\n\r\n    Client:\r\n     Version:      1.8.1\r\n     API version:  1.20\r\n     Go version:   go1.4.2\r\n     Git commit:   d12ea79\r\n     Built:        Thu Aug 13 02:19:43 UTC 2015\r\n     OS/Arch:      linux/amd64\r\n    \r\n    Server:\r\n     Version:      1.8.1\r\n     API version:  1.20\r\n     Go version:   go1.4.2\r\n     Git commit:   d12ea79\r\n     Built:        Thu Aug 13 02:19:43 UTC 2015\r\n     OS/Arch:      linux/amd64\r\n\r\ndocker info:\r\n\r\n    Containers: 72\r\n    Images: 474\r\n    Storage Driver: devicemapper\r\n     Pool Name: docker-253:0-5572-pool\r\n     Pool Blocksize: 65.54 kB\r\n     Backing Filesystem: xfs\r\n     Data file: /dev/loop0\r\n     Metadata file: /dev/loop1\r\n     Data Space Used: 15.8 GB\r\n     Data Space Total: 107.4 GB\r\n     Data Space Available: 91.58 GB\r\n     Metadata Space Used: 25 MB\r\n     Metadata Space Total: 2.147 GB\r\n     Metadata Space Available: 2.122 GB\r\n     Udev Sync Supported: true\r\n     Deferred Removal Enabled: true\r\n     Data loop file: /var/lib/docker/devicemapper/devicemapper/data\r\n     Metadata loop file: /var/lib/docker/devicemapper/devicemapper/metadata\r\n     Library Version: 1.02.93-RHEL7 (2015-01-28)\r\n    Execution Driver: native-0.2\r\n    Logging Driver: json-file\r\n    Kernel Version: 3.10.0-229.el7.x86_64\r\n    Operating System: CentOS Linux 7 (Core)\r\n    CPUs: 24\r\n    Total Memory: 47 GiB\r\n    Name: pchivcpapp02.lnx.in.here.com\r\n    ID: USGU:JHWJ:SXZH:B6O6:IUTL:NR62:UL5F:VOWW:RFQN:ME5J:IH3S:XEPA\r\n\r\nEnvironment Details:\r\nThese are physical boxes. You will notice Deferred Removal was turned on.  I was hoping it would fix the issue, but it didn't.\r\n\r\nHow Reproducible:\r\nI haven't seen any other tickets on this, so maybe I am the only one using an NFS mount for the registry.  That would be the key here, make sure the registry is pointing at an NFS mounted filesystem."},"comment":{"url":"https://api.github.com/repos/docker/docker/issues/comments/153029208","html_url":"https://github.com/docker/docker/issues/15833#issuecomment-153029208","issue_url":"https://api.github.com/repos/docker/docker/issues/15833","id":153029208,"user":{"login":"psigen","id":2805291,"avatar_url":"https://avatars.githubusercontent.com/u/2805291?v=3","gravatar_id":"","url":"https://api.github.com/users/psigen","html_url":"https://github.com/psigen","followers_url":"https://api.github.com/users/psigen/followers","following_url":"https://api.github.com/users/psigen/following{/other_user}","gists_url":"https://api.github.com/users/psigen/gists{/gist_id}","starred_url":"https://api.github.com/users/psigen/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/psigen/subscriptions","organizations_url":"https://api.github.com/users/psigen/orgs","repos_url":"https://api.github.com/users/psigen/repos","events_url":"https://api.github.com/users/psigen/events{/privacy}","received_events_url":"https://api.github.com/users/psigen/received_events","type":"User","site_admin":false},"created_at":"2015-11-02T14:19:53Z","updated_at":"2015-11-02T14:19:53Z","body":"_(I posted this in https://github.com/docker/distribution/issues/1116#issuecomment-152881763, but since it suggests a code fix perhaps here is a better place.)_\r\n\r\nI just checked using `lsof` and determined that the registry itself is holding the stale file handle:\r\n```bash\r\nregistry  1161 1179             root    6r      REG               0,39        32      49743 /var/lib/registry/docker/registry/v2/repositories/test_image/_uploads/5ac646c9-dc2b-4378-87e0-4ec45c646192/.nfs000000000000c24f00000003\r\n```\r\n\r\nThis handle is kept around until I do *another* `docker push`, at which point it is **promptly deleted**, and a stale handle for the *new* image is now created:\r\n```bash\r\nregistry  1161 1179             root    6r      REG               0,39        32      49745 /var/lib/registry/docker/registry/v2/repositories/test_image2/_uploads/395cb041-4b23-4c60-8bc1-bca7e89ce952/.nfs000000000000c25100000004\r\n```\r\n\r\nOne cause of NFS stale file handles is when a file handle is still open when an OS call attempts to delete the file.  Is it possible that the reference to the file handle used for the upload is still in scope in the registry when the subsequent step of deleting the `_uploads/` directory occurs?\r\n\r\nOn a normal filesystem, this probably doesn't cause any issues because the OS can simply hang onto the inode, but since NFS creates an undeletable busy resource in the same directory when the file is deleted, it fails the directory delete operation.\r\n\r\nIf this is the case, adjusting the scope of the upload file handle might resolve the issue."}}