{"action":"created","issue":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/53327","repository_url":"https://api.github.com/repos/kubernetes/kubernetes","labels_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/53327/labels{/name}","comments_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/53327/comments","events_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/53327/events","html_url":"https://github.com/kubernetes/kubernetes/issues/53327","id":262086484,"number":53327,"title":"Large kubemark performance tests failing with timeout during ns deletion","user":{"login":"shyamjvs","id":4333971,"avatar_url":"https://avatars3.githubusercontent.com/u/4333971?v=4","gravatar_id":"","url":"https://api.github.com/users/shyamjvs","html_url":"https://github.com/shyamjvs","followers_url":"https://api.github.com/users/shyamjvs/followers","following_url":"https://api.github.com/users/shyamjvs/following{/other_user}","gists_url":"https://api.github.com/users/shyamjvs/gists{/gist_id}","starred_url":"https://api.github.com/users/shyamjvs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shyamjvs/subscriptions","organizations_url":"https://api.github.com/users/shyamjvs/orgs","repos_url":"https://api.github.com/users/shyamjvs/repos","events_url":"https://api.github.com/users/shyamjvs/events{/privacy}","received_events_url":"https://api.github.com/users/shyamjvs/received_events","type":"User","site_admin":false},"labels":[{"id":105146071,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/kind/bug","name":"kind/bug","color":"e11d21","default":false},{"id":114528068,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/priority/critical-urgent","name":"priority/critical-urgent","color":"e11d21","default":false},{"id":496752468,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/priority/failing-test","name":"priority/failing-test","color":"e11d21","default":false},{"id":173493665,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/sig/node","name":"sig/node","color":"d2b48c","default":false},{"id":125010198,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/sig/scalability","name":"sig/scalability","color":"d2b48c","default":false},{"id":125550211,"url":"https://api.github.com/repos/kubernetes/kubernetes/labels/sig/scheduling","name":"sig/scheduling","color":"d2b48c","default":false}],"state":"open","locked":false,"assignee":{"login":"shyamjvs","id":4333971,"avatar_url":"https://avatars3.githubusercontent.com/u/4333971?v=4","gravatar_id":"","url":"https://api.github.com/users/shyamjvs","html_url":"https://github.com/shyamjvs","followers_url":"https://api.github.com/users/shyamjvs/followers","following_url":"https://api.github.com/users/shyamjvs/following{/other_user}","gists_url":"https://api.github.com/users/shyamjvs/gists{/gist_id}","starred_url":"https://api.github.com/users/shyamjvs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shyamjvs/subscriptions","organizations_url":"https://api.github.com/users/shyamjvs/orgs","repos_url":"https://api.github.com/users/shyamjvs/repos","events_url":"https://api.github.com/users/shyamjvs/events{/privacy}","received_events_url":"https://api.github.com/users/shyamjvs/received_events","type":"User","site_admin":false},"assignees":[{"login":"shyamjvs","id":4333971,"avatar_url":"https://avatars3.githubusercontent.com/u/4333971?v=4","gravatar_id":"","url":"https://api.github.com/users/shyamjvs","html_url":"https://github.com/shyamjvs","followers_url":"https://api.github.com/users/shyamjvs/followers","following_url":"https://api.github.com/users/shyamjvs/following{/other_user}","gists_url":"https://api.github.com/users/shyamjvs/gists{/gist_id}","starred_url":"https://api.github.com/users/shyamjvs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shyamjvs/subscriptions","organizations_url":"https://api.github.com/users/shyamjvs/orgs","repos_url":"https://api.github.com/users/shyamjvs/repos","events_url":"https://api.github.com/users/shyamjvs/events{/privacy}","received_events_url":"https://api.github.com/users/shyamjvs/received_events","type":"User","site_admin":false}],"milestone":null,"comments":59,"created_at":"2017-10-02T13:34:32Z","updated_at":"2017-11-28T20:04:37Z","closed_at":null,"author_association":"MEMBER","body":"We've been seeing these failures continuously in kubemark-5000 for quite some now - https://k8s-testgrid.appspot.com/sig-scalability#kubemark-5000\r\nEven in kubemark-500 we're occasionally seeing flakes - https://k8s-gubernator.appspot.com/build/kubernetes-jenkins/logs/ci-kubernetes-kubemark-500-gce/8806\r\n\r\nOn first look I'm seeing that hollow-nodes are going pending during test namespace deletion:\r\n\r\n```\r\nI1002 02:45:51.134] Oct  2 02:45:51.134: INFO: POD                     NODE               PHASE    GRACE  CONDITIONS\r\nI1002 02:45:51.135] Oct  2 02:45:51.134: INFO: load-small-14408-4r45s  hollow-node-lmblz  Pending  1s     [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC ContainersNotReady containers with unready status: [load-small-14408]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC  }]\r\nI1002 02:45:51.135] Oct  2 02:45:51.134: INFO: load-small-14408-q8tfd  hollow-node-lm9c4  Pending  1s     [{Initialized True 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC  } {Ready False 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC ContainersNotReady containers with unready status: [load-small-14408]} {PodScheduled True 0001-01-01 00:00:00 +0000 UTC 2017-10-01 20:26:46 +0000 UTC  }]\r\n```\r\n\r\nDigging into it now. Sorry for the delay, I've been busy with release scalability validation.\r\n\r\ncc @kubernetes/sig-scalability-bugs @wojtek-t @gmarek "},"comment":{"url":"https://api.github.com/repos/kubernetes/kubernetes/issues/comments/347646931","html_url":"https://github.com/kubernetes/kubernetes/issues/53327#issuecomment-347646931","issue_url":"https://api.github.com/repos/kubernetes/kubernetes/issues/53327","id":347646931,"user":{"login":"shyamjvs","id":4333971,"avatar_url":"https://avatars3.githubusercontent.com/u/4333971?v=4","gravatar_id":"","url":"https://api.github.com/users/shyamjvs","html_url":"https://github.com/shyamjvs","followers_url":"https://api.github.com/users/shyamjvs/followers","following_url":"https://api.github.com/users/shyamjvs/following{/other_user}","gists_url":"https://api.github.com/users/shyamjvs/gists{/gist_id}","starred_url":"https://api.github.com/users/shyamjvs/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/shyamjvs/subscriptions","organizations_url":"https://api.github.com/users/shyamjvs/orgs","repos_url":"https://api.github.com/users/shyamjvs/repos","events_url":"https://api.github.com/users/shyamjvs/events{/privacy}","received_events_url":"https://api.github.com/users/shyamjvs/received_events","type":"User","site_admin":false},"created_at":"2017-11-28T20:04:36Z","updated_at":"2017-11-28T20:04:36Z","author_association":"MEMBER","body":"I digged up the logs a bit, and found that the following series of events happened:\r\n\r\n- pod was recieved\r\n- syncloop saw the pod and started doing operations to start sandbox\r\n- netowrk plugin `kubernetes.io/no-op` was called as part of some sandbox setup\r\n- pod sandbox got created\r\n- kuberuntime_manager started to 'Creating container ...'\r\n- 'Pulled container image' event recorded (actually the image was already present on the machine)\r\n- syncloop saw (DELETE, \"api\") for the pod\r\n- 'Container created' event recorded (note that this happened after pod was started to be processed for deletion by syncloop)\r\n- status for pod was updated to the following (had to manually prettify it):\r\n\r\n```\r\n{\r\n  Phase:Pending\r\n  Conditions:[\r\n    {\r\n      Type:Initialized\r\n      Status:True\r\n      LastProbeTime:0001-01-01 00:00:00 +0000 UTC\r\n      LastTransitionTime:2017-11-23 11:47:46 +0000 UTC\r\n      Reason: \r\n      Message:\r\n    }\r\n    {\r\n      Type:Ready\r\n      Status:False\r\n      LastProbeTime:0001-01-01 00:00:00 +0000 UTC\r\n      LastTransitionTime:2017-11-23 11:47:46 +0000 UTC\r\n      Reason:ContainersNotReady\r\n      Message:containers with unready status: [load-small-3703]\r\n    }\r\n    {\r\n      Type:PodScheduled\r\n      Status:True\r\n      LastProbeTime:0001-01-01 00:00:00 +0000 UTC\r\n      LastTransitionTime:2017-11-23 11:47:46 +0000 UTC\r\n      Reason:\r\n      Message:\r\n    }\r\n  ]\r\n  Message:\r\n  Reason:\r\n  HostIP:10.64.1.50\r\n  PodIP:\r\n  StartTime:2017-11-23 11:47:46 +0000 UTC\r\n  InitContainerStatuses:[]\r\n  ContainerStatuses:[\r\n    {\r\n      Name:load-small-3703\r\n      State:{\r\n        Waiting:nil\r\n        Running:nil\r\n        Terminated:&ContainerStateTerminated{\r\n          ExitCode:0,\r\n          Signal:0,\r\n          Reason:,\r\n          Message:,\r\n          StartedAt:0001-01-01 00:00:00 +0000 UTC,\r\n          FinishedAt:0001-01-01 00:00:00 +0000 UTC,\r\n          ContainerID:,\r\n        }\r\n      }\r\n      LastTerminationState:{\r\n        Waiting:nil\r\n        Running:nil\r\n        Terminated:nil\r\n      }\r\n      Ready:false\r\n      RestartCount:0\r\n      Image:gcr.io/kubernetes-e2e-test-images/serve-hostname-amd64:1.0\r\n      ImageID:\r\n      ContainerID:\r\n    }\r\n  ]\r\n  QOSClass:Burstable\r\n}\r\n```\r\n\r\nthis shows that the pod was unready because the container was unready. And the container seems unready because it has been terminated.\r\nHowever, what's interesting to note here is that the containerID field is empty.\r\n\r\nFor another pod (load-medium-456) which seemed fine, the container ID has that value:\r\n\r\n```\r\nStatus for pod \"load-medium-396-wfx2c_e2e-tests-load-30-nodepods-17-scsfz(9424a239-d03d-11e7-931a-42010a8e0023)\" updated successfully: (4, {Phase:Running \r\n...bla\r\nStartedAt:2017-11-23 11:00:56 +0000 UTC,\r\nFinishedAt:2017-11-23 11:20:29 +0000 UTC,\r\nContainerID:docker://857170eaf7a0e9a8\r\n...bla\r\n```\r\n\r\n- then it says pod is terminated but some volumes have not been cleaned up\r\n- syncloop is called on the pod with (RECONCILE, \"api\") and then a 'started container' event is recorded (this is super strange! Why is the container started now, after the pod has been deleted?)\r\n- GenericPLEG: 1f777d1f-d044-11e7-931a-42010a8e0023/a2666a5eb5b04764: non-existent -> running (I don't understand this too well, but seems like the pod went from non-existent state to running?)\r\n- then it complains saying that the pod is terminated, but some containers have not been cleaned up\r\n- Killing unwanted pod \"load-small-3703-crjjs\"\r\n- GenericPLEG: 1f777d1f-d044-11e7-931a-42010a8e0023/aa4959d0d2215e81: running -> exited\r\n- then it continues to keep complaining \"pod is terminated, but some containers have not been cleaned up\" forever\r\n"}}
{"actor":{"display_login":"shyamjvs"}}