{"action":"created","issue":{"url":"https://api.github.com/repos/vmware/vic/issues/1645","repository_url":"https://api.github.com/repos/vmware/vic","labels_url":"https://api.github.com/repos/vmware/vic/issues/1645/labels{/name}","comments_url":"https://api.github.com/repos/vmware/vic/issues/1645/comments","events_url":"https://api.github.com/repos/vmware/vic/issues/1645/events","html_url":"https://github.com/vmware/vic/issues/1645","id":167311406,"number":1645,"title":"fails to delete container with run --rm","user":{"login":"hickeng","id":3923729,"avatar_url":"https://avatars.githubusercontent.com/u/3923729?v=3","gravatar_id":"","url":"https://api.github.com/users/hickeng","html_url":"https://github.com/hickeng","followers_url":"https://api.github.com/users/hickeng/followers","following_url":"https://api.github.com/users/hickeng/following{/other_user}","gists_url":"https://api.github.com/users/hickeng/gists{/gist_id}","starred_url":"https://api.github.com/users/hickeng/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/hickeng/subscriptions","organizations_url":"https://api.github.com/users/hickeng/orgs","repos_url":"https://api.github.com/users/hickeng/repos","events_url":"https://api.github.com/users/hickeng/events{/privacy}","received_events_url":"https://api.github.com/users/hickeng/received_events","type":"User","site_admin":false},"labels":[{"url":"https://api.github.com/repos/vmware/vic/labels/component/portlayer/execution","name":"component/portlayer/execution","color":"d4c5f9"}],"state":"open","locked":false,"assignee":{"login":"jzt","id":128130,"avatar_url":"https://avatars.githubusercontent.com/u/128130?v=3","gravatar_id":"","url":"https://api.github.com/users/jzt","html_url":"https://github.com/jzt","followers_url":"https://api.github.com/users/jzt/followers","following_url":"https://api.github.com/users/jzt/following{/other_user}","gists_url":"https://api.github.com/users/jzt/gists{/gist_id}","starred_url":"https://api.github.com/users/jzt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jzt/subscriptions","organizations_url":"https://api.github.com/users/jzt/orgs","repos_url":"https://api.github.com/users/jzt/repos","events_url":"https://api.github.com/users/jzt/events{/privacy}","received_events_url":"https://api.github.com/users/jzt/received_events","type":"User","site_admin":false},"assignees":[{"login":"jzt","id":128130,"avatar_url":"https://avatars.githubusercontent.com/u/128130?v=3","gravatar_id":"","url":"https://api.github.com/users/jzt","html_url":"https://github.com/jzt","followers_url":"https://api.github.com/users/jzt/followers","following_url":"https://api.github.com/users/jzt/following{/other_user}","gists_url":"https://api.github.com/users/jzt/gists{/gist_id}","starred_url":"https://api.github.com/users/jzt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jzt/subscriptions","organizations_url":"https://api.github.com/users/jzt/orgs","repos_url":"https://api.github.com/users/jzt/repos","events_url":"https://api.github.com/users/jzt/events{/privacy}","received_events_url":"https://api.github.com/users/jzt/received_events","type":"User","site_admin":false}],"milestone":{"url":"https://api.github.com/repos/vmware/vic/milestones/37","html_url":"https://github.com/vmware/vic/milestones/VIC%20GA%20Release","labels_url":"https://api.github.com/repos/vmware/vic/milestones/37/labels","id":1799354,"number":37,"title":"VIC GA Release","description":"Milestone for tracking all work towards the GA goal","creator":{"login":"mdubya66","id":15821624,"avatar_url":"https://avatars.githubusercontent.com/u/15821624?v=3","gravatar_id":"","url":"https://api.github.com/users/mdubya66","html_url":"https://github.com/mdubya66","followers_url":"https://api.github.com/users/mdubya66/followers","following_url":"https://api.github.com/users/mdubya66/following{/other_user}","gists_url":"https://api.github.com/users/mdubya66/gists{/gist_id}","starred_url":"https://api.github.com/users/mdubya66/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/mdubya66/subscriptions","organizations_url":"https://api.github.com/users/mdubya66/orgs","repos_url":"https://api.github.com/users/mdubya66/repos","events_url":"https://api.github.com/users/mdubya66/events{/privacy}","received_events_url":"https://api.github.com/users/mdubya66/received_events","type":"User","site_admin":false},"open_issues":248,"closed_issues":247,"state":"open","created_at":"2016-05-31T17:50:00Z","updated_at":"2016-09-15T19:26:12Z","due_on":"2016-11-07T00:00:00Z","closed_at":null},"comments":5,"created_at":"2016-07-25T08:30:19Z","updated_at":"2016-09-15T20:57:35Z","closed_at":null,"body":"There is a timing hole when deleting containers via `run --rm`. The rm occurs as soon as the connection drops in this scenario. Because the shutdown is initiated from within the container and there's an actual OS shutdown, the VM may not have finished powering off by the time the rm is dispatched.\r\n\r\nRecreate\r\n```\r\ndocker run -it --rm busybox /bin/bash\r\n# exit\r\nexit\r\nError response from daemon: server error from portlayer : [DELETE /containers/{id}][500] containerRemoveInternalServerError\r\n```\r\nport layer\r\n```\r\ntime=\"2016-07-17T22:18:49Z\" level=info msg=\"Finished copying stdout stream for container 97633e2f38093f0a3d069d822d67c034c2079dd216aeca305b5ba2e53a19b215\" \r\ntime=\"2016-07-17T22:18:49Z\" level=info msg=\"Finished copying stderr stream for container 97633e2f38093f0a3d069d822d67c034c2079dd216aeca305b5ba2e53a19b215\" \r\ntime=\"2016-07-17T22:18:49Z\" level=info msg=\"Done copying stdin\" \r\ntime=\"2016-07-17T22:18:49Z\" level=debug msg=\"[BEGIN] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).RemoveContainerHandler] Containers.RemoveContainerHandler\" \r\ntime=\"2016-07-17T22:18:49Z\" level=debug msg=\"[BEGIN] [github.com/vmware/vic/lib/portlayer/exec.(*Container).Remove] Container.Remove\" \r\ntime=\"2016-07-17T22:18:49Z\" level=error msg=\"Operation failed: The attempted operation cannot be performed in the current state (Powered on). - (&{{} %!!(MISSING)s(*types.InvalidPowerState=&{{{{<nil> []}}} poweredOff poweredOn}) The attempted operation cannot be performed in the current state (Powered on).})\" \r\ntime=\"2016-07-17T22:18:49Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/portlayer/exec.(*Container).Remove] [418.087372ms] Container.Remove\" \r\ntime=\"2016-07-17T22:18:49Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/apiservers/portlayer/restapi/handlers.(*ContainersHandlersImpl).RemoveContainerHandler] [419.482633ms] Containers.RemoveContainerHandler\" \r\n```\r\n\r\nThis may need some logic to allow for a delayed retry in this scenario - we should run some loop tests to determine how frequently this is seen."},"comment":{"url":"https://api.github.com/repos/vmware/vic/issues/comments/247453404","html_url":"https://github.com/vmware/vic/issues/1645#issuecomment-247453404","issue_url":"https://api.github.com/repos/vmware/vic/issues/1645","id":247453404,"user":{"login":"jzt","id":128130,"avatar_url":"https://avatars.githubusercontent.com/u/128130?v=3","gravatar_id":"","url":"https://api.github.com/users/jzt","html_url":"https://github.com/jzt","followers_url":"https://api.github.com/users/jzt/followers","following_url":"https://api.github.com/users/jzt/following{/other_user}","gists_url":"https://api.github.com/users/jzt/gists{/gist_id}","starred_url":"https://api.github.com/users/jzt/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/jzt/subscriptions","organizations_url":"https://api.github.com/users/jzt/orgs","repos_url":"https://api.github.com/users/jzt/repos","events_url":"https://api.github.com/users/jzt/events{/privacy}","received_events_url":"https://api.github.com/users/jzt/received_events","type":"User","site_admin":false},"created_at":"2016-09-15T20:57:35Z","updated_at":"2016-09-15T20:57:35Z","body":"This use case appears to be fixed by @cgtexmex's `ContainerWait` PR:\r\n\r\n```\r\nvagrant@devbox $ docker -H 192.168.218.235:2376 --tls run --rm -it busybox /bin/sh\r\n/ # exit\r\n```\r\n\r\nWe can see in the logs that `ContainerWait` is called by the client once `Attach` completed, before its call to remove:\r\n\r\n```\r\ntime=\"2016-05-26T14:00:19Z\" level=info msg=\"container attach: stderr (ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73) done: %!s(MISSING)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=error msg=\"container attach: stdin (ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73): context canceled\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"* stdout attach end Thu May 26 14:00:19 UTC 2016\"\r\ntime=\"2016-05-26T14:00:19Z\" level=info msg=\"container attach: stdout (ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73) done: %!s(MISSING)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=info msg=\"container attach:  cleaned up connections to ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73.\"\r\ntime=\"2016-05-26T14:00:19Z\" level=error msg=\"container attach error: context canceled\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerAttach] [22.707685041s] ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73\"\r\ntime=\"2016-05-26T14:00:19Z\" level=error msg=\"Handler for POST /v1.23/containers/ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73/attach returned error: context canceled\"\r\n2016/05/26 14:00:19 http: response.WriteHeader on hijacked connection\r\n2016/05/26 14:00:19 http: response.Write on hijacked connection\r\ntime=\"2016-05-26T14:00:19Z\" level=error msg=\"container attach: stdin err: read tcp 192.168.218.235:2376->192.168.218.180:54120: use of closed network connection\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Calling POST /v1.23/containers/ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73/wait\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Client and server don't have the same version (client: 1.11.2, server: 1.22)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[BEGIN] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerWait] name(ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73):timeout(-1s)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerWait] [275.257247ms] name(ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73):timeout(-1s)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Calling GET /v1.23/containers/ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73/json\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Client and server don't have the same version (client: 1.11.2, server: 1.22)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[BEGIN] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerInspect] ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73\"\r\n\r\n[ snip container inspect logs for brevity ]\r\n\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerInspect] [985.19µs] ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Calling DELETE /v1.23/containers/ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73?v=1\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"Client and server don't have the same version (client: 1.11.2, server: 1.22)\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[BEGIN] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerRm] ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73\"\r\ntime=\"2016-05-26T14:00:19Z\" level=debug msg=\"[ END ] [github.com/vmware/vic/lib/apiservers/engine/backends.(*Container).ContainerRm] [110.808738ms] ebdf4cfb94458b5f88b8ec50133e773bc197b640ca0ac43c37823bedc658fd73\"\r\n```\r\n\r\nThere is still an issue with short-lived containers along these lines. I've created a new issue to track it here:  https://github.com/vmware/vic/issues/2344\r\n\r\nClosing this as done."}}
{"actor":{"display_login":"jzt"}}