e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy #19997

erictune · 2016-01-22T17:38:50Z

Hit this twice since yesterday afternoon.
Example:
http://kubekins.dls.corp.google.com:8081/job/kubernetes-pull-build-test-e2e-gce/24671/#

Previous closed instances of this flake:
#19500 #17523 #15787 #15713

j3ffml · 2016-01-29T00:02:50Z

I can look at this.

lavalamp · 2016-01-29T19:27:07Z

This sounds very similar to one I recently added logs to. Looking...

lavalamp · 2016-01-29T19:36:12Z

My logs were added a few hours before @erictune made this bug. The jenkins link doesn't work anymore, though-- will dig and see if I can find the actual logs.

(@erictune-- I would have seen this earlier if you'd added the kind/flake label!)

lavalamp · 2016-01-29T19:38:40Z

@erictune do you recall what PR this flaked on?

j3ffml · 2016-01-29T19:46:32Z

Looking at test history this doesn't seem to be particularly flaky. I could find only one failure in the last 100 or so runs, and that appeared to be coincidental. I'm running it in a loop now to see if I can get a repro, but no failures so far.

lavalamp · 2016-01-29T19:48:30Z

@jlowdermilk That's why I added logs, and why I'd like to see the log messages I added in @erictune's reported flake.

j3ffml · 2016-01-30T01:08:20Z

Could not repro the flake in ~300 runs. Unless it shows up on pr-builder we can probably close this.

ixdy · 2016-01-30T02:16:51Z

I think this test may be hanging our e2e runs occasionally - see #13485 (comment).

I'm in well over my level of understanding, but my best guess is that the Post call isn't returning. @wojtek-t submitted #18340 to add timeouts to client calls, but in some of the original PRs adding this test, I see reference to util/httpstream/spdy, which may be lacking CancelRequest support?

cc @ashcrow for good measure.

ixdy · 2016-01-30T02:20:42Z

GCS permalinks for two failures I suspect recently: https://storage.cloud.google.com/kubernetes-jenkins/logs/kubernetes-e2e-gce/10591 and https://storage.cloud.google.com/kubernetes-jenkins/pr-logs/pull/19503/kubernetes-pull-build-test-e2e-gce/25721

j3ffml · 2016-02-02T17:53:36Z

Thanks for the links @ixdy. I'm still catching up on new issues and test flakes (buildcop), but I will look at the above.

j3ffml · 2016-02-03T02:26:30Z

After looking at above logs digging some more, it looks like this flake has the same root cause as #19466, namely kubectl exec hanging because of a race closing the spdystream connection. The fix there should also resolve this.

erictune · 2016-02-04T17:52:55Z

hit again.

lavalamp · 2016-02-09T04:48:49Z

#20444 has merged. Hopefully that fixes this.

mikedanese · 2016-02-09T23:23:13Z

Just hit this http://kubekins.dls.corp.google.com:8081/job/kubernetes-pull-build-test-e2e-gce/27742/#

j3ffml · 2016-02-09T23:49:34Z

Logs from above run: kubernetes-pull-build-test-e2e-gce/27742.

Failed test log:

------------------------------
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework.go:69
STEP: Creating a kubernetes client
Feb  9 23:01:32.815: INFO: >>> testContext.KubeConfig: /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config

STEP: Building a namespace api object
Feb  9 23:01:33.245: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-age9q
Feb  9 23:01:33.248: INFO: Get service account default in ns e2e-tests-kubectl-age9q failed, ignoring for 2s: serviceaccounts "default" not found
Feb  9 23:01:35.277: INFO: Service account default in ns e2e-tests-kubectl-age9q had 0 secrets, ignoring for 2s: <nil>
Feb  9 23:01:37.283: INFO: Service account default in ns e2e-tests-kubectl-age9q with secrets found. (4.038348944s)
STEP: Waiting for a default service account to be provisioned in namespace
Feb  9 23:01:37.283: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-age9q
Feb  9 23:01:37.286: INFO: Service account default in ns e2e-tests-kubectl-age9q with secrets found. (2.718452ms)
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:107
[BeforeEach] Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:177
STEP: creating the pod
Feb  9 23:01:37.286: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config create -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/docs/user-guide/pod.yaml --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:01:37.552: INFO: stdout: "pod \"nginx\" created\n"
Feb  9 23:01:37.552: INFO: stderr: ""
Feb  9 23:01:37.552: INFO: Waiting up to 5m0s for 1 pods to be running and ready: [nginx]
Feb  9 23:01:37.552: INFO: Waiting up to 5m0s for pod nginx status to be running and ready
Feb  9 23:01:37.556: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (3.74212ms elapsed)
Feb  9 23:01:39.563: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (2.011209597s elapsed)
Feb  9 23:01:41.567: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (4.014705485s elapsed)
Feb  9 23:01:43.570: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (6.018173033s elapsed)
Feb  9 23:01:45.574: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (8.021822512s elapsed)
Feb  9 23:01:47.607: INFO: Wanted all 1 pods to be running and ready. Result: true. Pods: [nginx]
[It] should support exec through an HTTP proxy
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:432
STEP: Finding a static kubectl for upload
STEP: Using the kubectl in /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/386/kubectl
Feb  9 23:01:47.608: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config create -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/test/images/netexec/pod.yaml --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:01:48.038: INFO: stdout: "pod \"netexec\" created\n"
Feb  9 23:01:48.038: INFO: stderr: ""
Feb  9 23:01:48.038: INFO: Waiting up to 5m0s for 1 pods to be running and ready: [netexec]
Feb  9 23:01:48.038: INFO: Waiting up to 5m0s for pod netexec status to be running and ready
Feb  9 23:01:48.047: INFO: Waiting for pod netexec in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (9.06086ms elapsed)
Feb  9 23:01:50.050: INFO: Waiting for pod netexec in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (2.012119805s elapsed)
Feb  9 23:01:52.057: INFO: Waiting for pod netexec in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (4.018890466s elapsed)
Feb  9 23:01:54.063: INFO: Waiting for pod netexec in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (6.025048644s elapsed)
Feb  9 23:01:56.068: INFO: Wanted all 1 pods to be running and ready. Result: true. Pods: [netexec]
STEP: uploading kubeconfig to netexec
STEP: uploading kubectl to netexec
STEP: Running kubectl in netexec via an HTTP proxy using https_proxy
Feb  9 23:02:01.252: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config create -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/test/images/goproxy/pod.yaml --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:01.541: INFO: stdout: "pod \"goproxy\" created\n"
Feb  9 23:02:01.541: INFO: stderr: ""
Feb  9 23:02:01.541: INFO: Waiting up to 5m0s for 1 pods to be running and ready: [goproxy]
Feb  9 23:02:01.542: INFO: Waiting up to 5m0s for pod goproxy status to be running and ready
Feb  9 23:02:01.550: INFO: Waiting for pod goproxy in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (8.06436ms elapsed)
Feb  9 23:02:03.554: INFO: Waiting for pod goproxy in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (2.012513529s elapsed)
Feb  9 23:02:05.558: INFO: Waiting for pod goproxy in namespace 'e2e-tests-kubectl-age9q' status to be 'running and ready'(found phase: "Pending", readiness: false) (4.015973151s elapsed)
Feb  9 23:02:07.561: INFO: Wanted all 1 pods to be running and ready. Result: true. Pods: [goproxy]
Feb  9 23:02:07.575: INFO: About to remote exec: https_proxy=http://10.245.4.5:8080 ./uploads/upload284164754 --kubeconfig=/uploads/upload171427391 --server=https://173.255.119.234:443 --namespace=e2e-tests-kubectl-age9q exec nginx echo running in container
Feb  9 23:02:39.812: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config log goproxy --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:40.036: INFO: stdout: "2016/02/09 23:02:08 [001] INFO: Running 0 CONNECT handlers\n2016/02/09 23:02:08 [001] INFO: Accepting CONNECT to 173.255.119.234:443\n2016/02/09 23:02:09 [002] INFO: Running 0 CONNECT handlers\n2016/02/09 23:02:09 [002] INFO: Accepting CONNECT to 173.255.119.234:443\n2016/02/09 23:02:10 [002] WARN: Error copying to client: read tcp 10.245.4.5:8080->10.245.2.18:47511: read tcp 10.245.4.5:47553->173.255.119.234:443: read: connection reset by peer\n2016/02/09 23:02:39 [002] WARN: Error copying to client: read tcp 10.245.4.5:47553->173.255.119.234:443: write tcp 10.245.4.5:47553->173.255.119.234:443: use of closed network connection\n"
Feb  9 23:02:40.036: INFO: stderr: ""
Feb  9 23:02:40.036: FAIL: Unexpected kubectl exec output. Wanted "running in container\n", got  "error: Timeout occured\n"
STEP: using delete to clean up resources
Feb  9 23:02:40.036: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config delete --grace-period=0 -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/test/images/netexec/pod.yaml --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:40.252: INFO: stdout: "pod \"netexec\" deleted\n"
Feb  9 23:02:40.252: INFO: stderr: ""
Feb  9 23:02:40.252: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config get rc,svc -l name=netexec --no-headers --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:40.459: INFO: stdout: ""
Feb  9 23:02:40.459: INFO: stderr: ""
Feb  9 23:02:40.459: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config get pods -l name=netexec --namespace=e2e-tests-kubectl-age9q -o go-template={{ range .items }}{{ if not .metadata.deletionTimestamp }}{{ .metadata.name }}{{ "\n" }}{{ end }}{{ end }}'
Feb  9 23:02:40.686: INFO: stdout: ""
Feb  9 23:02:40.686: INFO: stderr: ""
[AfterEach] Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:180
STEP: using delete to clean up resources
Feb  9 23:02:40.687: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config delete --grace-period=0 -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/docs/user-guide/pod.yaml --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:40.909: INFO: stdout: "pod \"nginx\" deleted\n"
Feb  9 23:02:40.909: INFO: stderr: ""
Feb  9 23:02:40.909: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config get rc,svc -l name=nginx --no-headers --namespace=e2e-tests-kubectl-age9q'
Feb  9 23:02:41.120: INFO: stdout: ""
Feb  9 23:02:41.143: INFO: stderr: ""
Feb  9 23:02:41.143: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://173.255.119.234 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config get pods -l name=nginx --namespace=e2e-tests-kubectl-age9q -o go-template={{ range .items }}{{ if not .metadata.deletionTimestamp }}{{ .metadata.name }}{{ "\n" }}{{ end }}{{ end }}'
Feb  9 23:02:41.370: INFO: stdout: ""
Feb  9 23:02:41.370: INFO: stderr: ""
[AfterEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework.go:70
STEP: Collecting events from namespace "e2e-tests-kubectl-age9q".
Feb  9 23:02:41.377: INFO: event for goproxy: {default-scheduler } Scheduled: Successfully assigned goproxy to e2e-gce-builder-4-2-minion-ude8
Feb  9 23:02:41.377: INFO: event for goproxy: {kubelet e2e-gce-builder-4-2-minion-ude8} Pulling: pulling image "gcr.io/google_containers/goproxy:0.1"
Feb  9 23:02:41.377: INFO: event for goproxy: {kubelet e2e-gce-builder-4-2-minion-ude8} Pulled: Successfully pulled image "gcr.io/google_containers/goproxy:0.1"
Feb  9 23:02:41.377: INFO: event for goproxy: {kubelet e2e-gce-builder-4-2-minion-ude8} Created: Created container with docker id d42ba866fe17
Feb  9 23:02:41.377: INFO: event for goproxy: {kubelet e2e-gce-builder-4-2-minion-ude8} Started: Started container with docker id d42ba866fe17
Feb  9 23:02:41.377: INFO: event for netexec: {default-scheduler } Scheduled: Successfully assigned netexec to e2e-gce-builder-4-2-minion-bmx8
Feb  9 23:02:41.377: INFO: event for netexec: {kubelet e2e-gce-builder-4-2-minion-bmx8} Pulled: Container image "gcr.io/google_containers/netexec:1.4" already present on machine
Feb  9 23:02:41.377: INFO: event for netexec: {kubelet e2e-gce-builder-4-2-minion-bmx8} Created: Created container with docker id 3455a49f48be
Feb  9 23:02:41.377: INFO: event for netexec: {kubelet e2e-gce-builder-4-2-minion-bmx8} Started: Started container with docker id 3455a49f48be
Feb  9 23:02:41.377: INFO: event for netexec: {kubelet e2e-gce-builder-4-2-minion-bmx8} Killing: Killing container with docker id 3455a49f48be: Need to kill pod.
Feb  9 23:02:41.377: INFO: event for nginx: {default-scheduler } Scheduled: Successfully assigned nginx to e2e-gce-builder-4-2-minion-y5o4
Feb  9 23:02:41.377: INFO: event for nginx: {kubelet e2e-gce-builder-4-2-minion-y5o4} Pulling: pulling image "nginx"
Feb  9 23:02:41.377: INFO: event for nginx: {kubelet e2e-gce-builder-4-2-minion-y5o4} Pulled: Successfully pulled image "nginx"
Feb  9 23:02:41.377: INFO: event for nginx: {kubelet e2e-gce-builder-4-2-minion-y5o4} Created: Created container with docker id 3ff3a5e58f54
Feb  9 23:02:41.377: INFO: event for nginx: {kubelet e2e-gce-builder-4-2-minion-y5o4} Started: Started container with docker id 3ff3a5e58f54
Feb  9 23:02:41.377: INFO: event for nginx: {kubelet e2e-gce-builder-4-2-minion-y5o4} Killing: Killing container with docker id 3ff3a5e58f54: Need to kill pod.
Feb  9 23:02:41.425: INFO: POD                                                      NODE                             PHASE      GRACE  CONDITIONS
Feb  9 23:02:41.425: INFO: dns-test-11633a60-cf81-11e5-b9d1-42010af0000e            e2e-gce-builder-4-2-minion-1rqj  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:35 +0000 UTC ContainersNotReady containers with unready status: [webserver querier jessie-querier]}]
Feb  9 23:02:41.426: INFO: downwardapi-volume-1281180f-cf81-11e5-ae72-42010af0000e  e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:41 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fail-once-local-hari1                                    e2e-gce-builder-4-2-minion-y5o4  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:36 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: fail-once-local-izd7q                                    e2e-gce-builder-4-2-minion-dm2a  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:39 +0000 UTC ContainersNotReady containers with unready status: [c]}]
Feb  9 23:02:41.426: INFO: fail-once-local-mzcyv                                    e2e-gce-builder-4-2-minion-y5o4  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:32 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: fail-once-local-wt03h                                    e2e-gce-builder-4-2-minion-ude8  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:32 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: rand-non-local-0v6bj                                     e2e-gce-builder-4-2-minion-ude8  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:34 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: rand-non-local-4yd0b                                     e2e-gce-builder-4-2-minion-ude8  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:14 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: rand-non-local-cabkw                                     e2e-gce-builder-4-2-minion-y5o4  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:19 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: rand-non-local-fuogu                                     e2e-gce-builder-4-2-minion-ude8  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:20 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: rand-non-local-hb9bv                                     e2e-gce-builder-4-2-minion-y5o4  Failed            [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:14 +0000 UTC ContainersNotReady containers with unready status: [c]}]
Feb  9 23:02:41.426: INFO: rand-non-local-tznrb                                     e2e-gce-builder-4-2-minion-y5o4  Failed            [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:27 +0000 UTC ContainersNotReady containers with unready status: [c]}]
Feb  9 23:02:41.426: INFO: scale-down-2wz4l                                         e2e-gce-builder-4-2-minion-34kl  Running    30s    [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:06 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: scale-down-4o58k                                         e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:05 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: frontend-eernr                                           e2e-gce-builder-4-2-minion-dm2a  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:52 +0000 UTC ContainersNotReady containers with unready status: [php-redis]}]
Feb  9 23:02:41.426: INFO: frontend-k9dh4                                           e2e-gce-builder-4-2-minion-1rqj  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:49 +0000 UTC ContainersNotReady containers with unready status: [php-redis]}]
Feb  9 23:02:41.426: INFO: frontend-ytqkl                                           e2e-gce-builder-4-2-minion-34kl  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:48 +0000 UTC ContainersNotReady containers with unready status: [php-redis]}]
Feb  9 23:02:41.426: INFO: redis-master-6o2u7                                       e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:18 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: redis-slave-mobis                                        e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:22 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: redis-slave-q86b7                                        e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:12 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: goproxy                                                  e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:06 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: redis-master-ucyqq                                       e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:37 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: nginx                                                    e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:20 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: run-test-2-pvlte                                         e2e-gce-builder-4-2-minion-bmx8  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:38 +0000 UTC ContainersNotReady containers with unready status: [run-test-2]}]
Feb  9 23:02:41.426: INFO: run-test-iqsdv                                           e2e-gce-builder-4-2-minion-dm2a  Succeeded         [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:38 +0000 UTC PodCompleted }]
Feb  9 23:02:41.426: INFO: redis-master-hiwb3                                       e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:37 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: pd-test-2b5c93a4-cf81-11e5-8f90-42010af0000e             e2e-gce-builder-4-2-minion-1rqj  Pending           [{Ready False 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:19 +0000 UTC ContainersNotReady containers with unready status: [mycontainer]}]
Feb  9 23:02:41.426: INFO: liveness-http                                            e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:59 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: pfpod                                                    e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:41 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: server                                                   e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:29 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: tester                                                   e2e-gce-builder-4-2-minion-ude8  Running    30s    [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:35 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: mutability-test-xelbc                                    e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:00 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: mutability-test-z8y0l                                    e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:47 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: execpod                                                  e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:41 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service1-4j83g                                           e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:44 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service1-rvubl                                           e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:57 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service1-wc250                                           e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:42 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service2-3euyh                                           e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:37 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service2-6vntc                                           e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:06 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: service2-k2iix                                           e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:05 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: svc-latency-rc-top2a                                     e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:02:12 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: elasticsearch-logging-v1-4tn0y                           e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:57 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: elasticsearch-logging-v1-buv0j                           e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:58 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-1rqj    e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:05 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-34kl    e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:48 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-bmx8    e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:43 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-dm2a    e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:50 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-ude8    e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:38 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-y5o4    e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:54 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: heapster-v14-2i8ag                                       e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:41 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kibana-logging-v1-02ghx                                  e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:32 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-dns-v10-q2un4                                       e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:04 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-1rqj               e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:26 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-34kl               e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:24 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-bmx8               e2e-gce-builder-4-2-minion-bmx8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:23 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-dm2a               e2e-gce-builder-4-2-minion-dm2a  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:23 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-ude8               e2e-gce-builder-4-2-minion-ude8  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:24 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kube-proxy-e2e-gce-builder-4-2-minion-y5o4               e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:38 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: kubernetes-dashboard-v0.1.0-oq3h4                        e2e-gce-builder-4-2-minion-y5o4  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:00:52 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: l7-lb-controller-ok8tp                                   e2e-gce-builder-4-2-minion-1rqj  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:24 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: monitoring-influxdb-grafana-v3-4ftn0                     e2e-gce-builder-4-2-minion-34kl  Running           [{Ready True 0001-01-01 00:00:00 +0000 UTC 2016-02-09 23:01:03 +0000 UTC  }]
Feb  9 23:02:41.426: INFO: 
Feb  9 23:02:41.433: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-1rqj
Feb  9 23:02:41.436: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-1rqj   /api/v1/nodes/e2e-gce-builder-4-2-minion-1rqj c79fdb02-cf80-11e5-a518-42010af00002 4783 0 2016-02-09 22:59:31 +0000 UTC <nil> <nil> map[failure-domain.alpha.kubernetes.io/region:us-central1 failure-domain.alpha.kubernetes.io/zone:us-central1-f kubernetes.io/hostname:e2e-gce-builder-4-2-minion-1rqj] map[]} {10.245.0.0/24 864382076483478507 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-1rqj false} {map[memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI}] map[pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI}]  [{OutOfDisk False 2016-02-09 23:02:32 +0000 UTC 2016-02-09 22:59:31 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:32 +0000 UTC 2016-02-09 23:00:07 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.4} {ExternalIP 104.197.132.49}] {{10250}} { 4FCB9CCA-F1DF-FEA4-FA08-A46EAE69DC4F 6c58f663-b554-4294-88bd-549ca8884ba9 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[<none>:<none>] 151289095} {[nginx:latest] 134481476} {[gcr.io/google_containers/glbc:0.5.2] 226351998} {[gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/defaultbackend:1.0] 7513643} {[gcr.io/google_containers/pause:2.0] 350164} {[gcr.io/google_containers/portforwardtester:1.0] 2296329} {[<none>:<none>] 321058253} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/kibana:1.3] 396897764} {[gcr.io/google_containers/dnsutils:latest] 141895666} {[gcr.io/google_containers/pause:0.8.0] 241656} {[<none>:<none>] 4522409} {[gcr.io/google_containers/test-webserver:latest] 4534272}]}}
Feb  9 23:02:41.437: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-1rqj
Feb  9 23:02:41.446: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-1rqj
Feb  9 23:02:41.484: INFO: redis-master-hiwb3 started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: redis-master-ucyqq started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-1rqj started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: kube-proxy-e2e-gce-builder-4-2-minion-1rqj started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: service2-3euyh started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: dns-test-11633a60-cf81-11e5-b9d1-42010af0000e started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: frontend-k9dh4 started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: kibana-logging-v1-02ghx started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.484: INFO: l7-lb-controller-ok8tp started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 20 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 32 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="logs"} => 1 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 4 @[0]
Feb  9 23:02:41.746: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:41.746: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-1rqj
Feb  9 23:02:41.746: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:57.877548s}
Feb  9 23:02:41.746: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:53.965226s}
Feb  9 23:02:41.746: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:53.95226s}
Feb  9 23:02:41.746: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:53.778084s}
Feb  9 23:02:41.746: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:52.925682s}
Feb  9 23:02:41.746: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:52.772491s}
Feb  9 23:02:41.746: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:49.392874s}
Feb  9 23:02:41.746: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:38.378984s}
Feb  9 23:02:41.746: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.039615s}
Feb  9 23:02:41.746: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.5 Latency:18.0255s}
Feb  9 23:02:41.746: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-34kl
Feb  9 23:02:41.750: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-34kl   /api/v1/nodes/e2e-gce-builder-4-2-minion-34kl c6eeb04f-cf80-11e5-a518-42010af00002 5375 0 2016-02-09 22:59:30 +0000 UTC <nil> <nil> map[failure-domain.alpha.kubernetes.io/region:us-central1 failure-domain.alpha.kubernetes.io/zone:us-central1-f kubernetes.io/hostname:e2e-gce-builder-4-2-minion-34kl] map[]} {10.245.1.0/24 17526180967821768467 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-34kl false} {map[cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI}] map[cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI}]  [{OutOfDisk False 2016-02-09 23:02:39 +0000 UTC 2016-02-09 22:59:29 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:39 +0000 UTC 2016-02-09 23:00:06 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.6} {ExternalIP 104.197.138.155}] {{10250}} { 21D49714-02EA-FF66-D3DE-920E92B7E98D 5bf0a660-d093-4603-9ae6-a3c85b7016bf 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[gcr.io/google_containers/netexec:1.4] 7297019} {[redis:latest] 151289204} {[gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/hostexec:1.2] 13209617} {[gcr.io/google_containers/mounttest-user:0.3] 1718853} {[gcr.io/google_containers/mounttest:0.5] 1718853} {[gcr.io/google_containers/heapster_grafana:v2.1.1] 206641132} {[gcr.io/google_containers/pause:2.0] 350164} {[gcr.io/google_containers/heapster_influxdb:v0.5] 251005705} {[<none>:<none>] 328223859} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/pause:0.8.0] 241656} {[gcr.io/google_containers/serve_hostname:1.1] 4522409} {[gcr.io/google_containers/nginx:1.7.9] 91664166}]}}
Feb  9 23:02:41.750: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-34kl
Feb  9 23:02:41.789: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-34kl
Feb  9 23:02:41.804: INFO: liveness-http started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: monitoring-influxdb-grafana-v3-4ftn0 started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-34kl started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: kube-proxy-e2e-gce-builder-4-2-minion-34kl started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: foo-9e3l6 started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: scale-down-2wz4l started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: scale-down-4o58k started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: frontend-ytqkl started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: mutability-test-z8y0l started at <nil> (0 container statuses recorded)
Feb  9 23:02:41.804: INFO: service1-4j83g started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 19 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 32 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 9 @[0]
Feb  9 23:02:42.056: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:42.056: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-34kl
Feb  9 23:02:42.056: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:48.52566s}
Feb  9 23:02:42.056: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.032882s}
Feb  9 23:02:42.056: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:34.564433s}
Feb  9 23:02:42.056: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:33.564429s}
Feb  9 23:02:42.056: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:32.071749s}
Feb  9 23:02:42.056: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:31.421178s}
Feb  9 23:02:42.056: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:30.691727s}
Feb  9 23:02:42.056: INFO: {Operation:stop_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:30.309226s}
Feb  9 23:02:42.056: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:28.474004s}
Feb  9 23:02:42.056: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:18.124505s}
Feb  9 23:02:42.056: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-bmx8
Feb  9 23:02:42.059: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-bmx8   /api/v1/nodes/e2e-gce-builder-4-2-minion-bmx8 c6d7ee1f-cf80-11e5-a518-42010af00002 5373 0 2016-02-09 22:59:30 +0000 UTC <nil> <nil> map[failure-domain.alpha.kubernetes.io/zone:us-central1-f kubernetes.io/hostname:e2e-gce-builder-4-2-minion-bmx8 failure-domain.alpha.kubernetes.io/region:us-central1] map[]} {10.245.2.0/24 11066584910670110555 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-bmx8 false} {map[memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI}] map[memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI}]  [{OutOfDisk False 2016-02-09 23:02:39 +0000 UTC 2016-02-09 22:59:29 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:39 +0000 UTC 2016-02-09 23:00:04 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.5} {ExternalIP 8.34.217.38}] {{10250}} { 2012EA5A-D304-7B21-C976-071F0C53E800 f6732a2d-7b96-40ab-9093-73557574750d 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[gcr.io/google_containers/netexec:1.4] 7297019} {[redis:latest] 151289204} {[gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/elasticsearch:1.8] 410989305} {[gcr.io/google_containers/mounttest:0.6] 2084693} {[gcr.io/google_containers/mounttest:0.5] 1718853} {[gcr.io/google_containers/pause:2.0] 350164} {[gcr.io/google_samples/gb-redisslave:v1] 109508753} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/mounttest:0.2] 1752375} {[gcr.io/google_containers/pause:0.8.0] 241656} {[gcr.io/google_containers/serve_hostname:1.1 b.gcr.io/k8s_authenticated_test/serve_hostname:1.1] 4522409} {[gcr.io/google_containers/update-demo:nautilus] 4555533}]}}
Feb  9 23:02:42.060: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-bmx8
Feb  9 23:02:42.071: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-bmx8
Feb  9 23:02:42.083: INFO: run-test-2-pvlte started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: execpod started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: redis-master-6o2u7 started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: mutability-test-xelbc started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: downwardapi-volume-1281180f-cf81-11e5-ae72-42010af0000e started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: server started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: redis-slave-mobis started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: foo-v81sg started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: elasticsearch-logging-v1-buv0j started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-bmx8 started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.083: INFO: kube-proxy-e2e-gce-builder-4-2-minion-bmx8 started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.482: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:42.482: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 20 @[0]
Feb  9 23:02:42.482: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 31 @[0]
Feb  9 23:02:42.482: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:42.483: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:42.483: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 7 @[0]
Feb  9 23:02:42.483: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:42.483: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-bmx8
Feb  9 23:02:42.483: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:48.986825s}
Feb  9 23:02:42.483: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.058775s}
Feb  9 23:02:42.483: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:30.420733s}
Feb  9 23:02:42.483: INFO: {Operation:stop_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:30.124161s}
Feb  9 23:02:42.483: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:28.796092s}
Feb  9 23:02:42.483: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:27.651514s}
Feb  9 23:02:42.483: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:26.938782s}
Feb  9 23:02:42.483: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:26.658614s}
Feb  9 23:02:42.483: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:24.20187s}
Feb  9 23:02:42.483: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:22.739981s}
Feb  9 23:02:42.483: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-dm2a
Feb  9 23:02:42.486: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-dm2a   /api/v1/nodes/e2e-gce-builder-4-2-minion-dm2a c6262829-cf80-11e5-a518-42010af00002 5446 0 2016-02-09 22:59:29 +0000 UTC <nil> <nil> map[failure-domain.alpha.kubernetes.io/region:us-central1 failure-domain.alpha.kubernetes.io/zone:us-central1-f kubernetes.io/hostname:e2e-gce-builder-4-2-minion-dm2a] map[]} {10.245.3.0/24 39572597696487018 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-dm2a false} {map[cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI}] map[cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI}]  [{OutOfDisk False 2016-02-09 23:02:40 +0000 UTC 2016-02-09 22:59:28 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:40 +0000 UTC 2016-02-09 23:00:05 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.3} {ExternalIP 104.197.114.34}] {{10250}} { F5FAD71A-5ABB-4803-A63B-CC2BE7965BF3 bb15fd10-05e3-43cf-88f6-0cb4706fbc3a 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[redis:latest] 151289204} {[nginx:latest] 134481476} {[gcr.io/google_containers/busybox:1.24 busybox:latest] 1113554} {[gcr.io/google_containers/elasticsearch:1.8] 410989305} {[gcr.io/google_containers/mounttest:0.6] 2084693} {[gcr.io/google_containers/mounttest:0.5] 1718853} {[gcr.io/google_containers/pause:2.0] 350164} {[<none>:<none>] 328223859} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/pause:0.8.0] 241656} {[gcr.io/google_containers/serve_hostname:1.1] 4522409} {[gcr.io/google_containers/nginx:1.7.9] 91664166}]}}
Feb  9 23:02:42.487: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-dm2a
Feb  9 23:02:42.661: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-dm2a
Feb  9 23:02:42.883: INFO: fail-once-local-izd7q started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: svc-latency-rc-top2a started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: service2-6vntc started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: frontend-eernr started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: service1-rvubl started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: elasticsearch-logging-v1-4tn0y started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-dm2a started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: kube-proxy-e2e-gce-builder-4-2-minion-dm2a started at <nil> (0 container statuses recorded)
Feb  9 23:02:42.883: INFO: nginx started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 20 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 32 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 4 @[0]
Feb  9 23:02:43.292: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:43.292: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-dm2a
Feb  9 23:02:43.292: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:48.86965s}
Feb  9 23:02:43.292: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:39.70154s}
Feb  9 23:02:43.292: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:39.663329s}
Feb  9 23:02:43.292: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:36.822046s}
Feb  9 23:02:43.292: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.036595s}
Feb  9 23:02:43.292: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:33.577225s}
Feb  9 23:02:43.292: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:30.4631s}
Feb  9 23:02:43.292: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:29.817443s}
Feb  9 23:02:43.292: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:22.9828s}
Feb  9 23:02:43.292: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.9 Latency:10.81012s}
Feb  9 23:02:43.292: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-ude8
Feb  9 23:02:43.297: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-ude8   /api/v1/nodes/e2e-gce-builder-4-2-minion-ude8 c6848443-cf80-11e5-a518-42010af00002 5316 0 2016-02-09 22:59:29 +0000 UTC <nil> <nil> map[failure-domain.alpha.kubernetes.io/region:us-central1 failure-domain.alpha.kubernetes.io/zone:us-central1-f kubernetes.io/hostname:e2e-gce-builder-4-2-minion-ude8] map[]} {10.245.4.0/24 277051281083834437 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-ude8 false} {map[pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI}] map[memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI}]  [{OutOfDisk False 2016-02-09 23:02:38 +0000 UTC 2016-02-09 22:59:29 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:38 +0000 UTC 2016-02-09 23:00:04 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.8} {ExternalIP 104.154.29.85}] {{10250}} { 7D557E14-7727-0EB3-95E5-9332576F5046 ba1ff374-eab3-4383-b1d3-0475a0c64bab 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/heapster:v0.20.0-alpha4] 84357500} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[nginx:latest] 134481476} {[gcr.io/google_containers/fakegitserver:0.1] 5007469} {[gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/mounttest-user:0.3] 1718853} {[gcr.io/google_containers/pause:2.0] 350164} {[gcr.io/google_containers/goproxy:0.1] 5489816} {[gcr.io/google_samples/gb-redisslave:v1] 109508753} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/pause:0.8.0] 241656} {[gcr.io/google_containers/serve_hostname:1.1 b.gcr.io/k8s_authenticated_test/serve_hostname:1.1] 4522409} {[gcr.io/google_containers/update-demo:nautilus] 4555533} {[gcr.io/google_containers/liveness:latest] 4387474}]}}
Feb  9 23:02:43.297: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-ude8
Feb  9 23:02:43.464: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-ude8
Feb  9 23:02:43.660: INFO: redis-slave-q86b7 started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: goproxy started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: service1-wc250 started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: heapster-v14-2i8ag started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-ude8 started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: kube-proxy-e2e-gce-builder-4-2-minion-ude8 started at <nil> (0 container statuses recorded)
Feb  9 23:02:43.660: INFO: tester started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 18 @[0]
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 32 @[0]
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:44.016: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 7 @[0]
Feb  9 23:02:44.017: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:44.017: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-ude8
Feb  9 23:02:44.017: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:49.704289s}
Feb  9 23:02:44.017: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.038084s}
Feb  9 23:02:44.017: INFO: {Operation:stop_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:29.308198s}
Feb  9 23:02:44.017: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:23.302326s}
Feb  9 23:02:44.017: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:21.697296s}
Feb  9 23:02:44.017: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:20.83437s}
Feb  9 23:02:44.017: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:18.67812s}
Feb  9 23:02:44.017: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:17.582879s}
Feb  9 23:02:44.017: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:17.268525s}
Feb  9 23:02:44.017: INFO: 
Logging node info for node e2e-gce-builder-4-2-minion-y5o4
Feb  9 23:02:44.059: INFO: Node Info: &{{ } {e2e-gce-builder-4-2-minion-y5o4   /api/v1/nodes/e2e-gce-builder-4-2-minion-y5o4 cd3e04c0-cf80-11e5-a518-42010af00002 5547 0 2016-02-09 22:59:41 +0000 UTC <nil> <nil> map[kubernetes.io/hostname:e2e-gce-builder-4-2-minion-y5o4 failure-domain.alpha.kubernetes.io/region:us-central1 failure-domain.alpha.kubernetes.io/zone:us-central1-f] map[]} {10.245.5.0/24 8361980913863901786 gce://kubernetes-jenkins-pull/us-central1-f/e2e-gce-builder-4-2-minion-y5o4 false} {map[cpu:{2.000 DecimalSI} memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI}] map[memory:{7864139776.000 BinarySI} pods:{110.000 DecimalSI} cpu:{2.000 DecimalSI}]  [{OutOfDisk False 2016-02-09 23:02:41 +0000 UTC 2016-02-09 22:59:41 +0000 UTC KubeletHasSufficientDisk kubelet has sufficient disk space available} {Ready True 2016-02-09 23:02:41 +0000 UTC 2016-02-09 23:00:17 +0000 UTC KubeletReady kubelet is posting ready status}] [{InternalIP 10.240.0.7} {ExternalIP 104.154.29.6}] {{10250}} { B06DC6DE-6A59-843A-070D-342DB87BEE1F f0d60788-2659-4ea6-9899-d9da1e12a64a 3.16.0-4-amd64 Debian GNU/Linux 7 (wheezy) docker://1.9.1 v1.2.0-alpha.7.535+411b3fc3d770ec v1.2.0-alpha.7.535+411b3fc3d770ec} [{[gcr.io/google_containers/kube-proxy:29a46455de4266fe8f67f22c83d28edf] 164605037} {[gcr.io/google_containers/fluentd-elasticsearch:1.14] 562034622} {[gcr.io/google_containers/kubernetes-dashboard-amd64:v0.1.0] 35409795} {[nginx:latest] 134481476} {[gcr.io/google_containers/busybox:1.24] 1113554} {[gcr.io/google_containers/kube2sky:1.12] 24482187} {[gcr.io/google_containers/mounttest:0.5] 1718853} {[gcr.io/google_containers/skydns:2015-10-13-8c72f8c] 40551394} {[gcr.io/google_containers/pause:2.0] 350164} {[gcr.io/google_containers/portforwardtester:1.0] 2296329} {[gcr.io/google_containers/nettest:1.6] 10374838} {[gcr.io/google_containers/exechealthz:1.0] 7099444} {[gcr.io/google_containers/etcd:2.0.9] 12819040} {[gcr.io/google_containers/pause:0.8.0] 241656} {[gcr.io/google_containers/serve_hostname:1.1] 4522409}]}}
Feb  9 23:02:44.060: INFO: 
Logging kubelet events for node e2e-gce-builder-4-2-minion-y5o4
Feb  9 23:02:44.261: INFO: 
Logging pods the kubelet thinks is on node e2e-gce-builder-4-2-minion-y5o4
Feb  9 23:02:44.473: INFO: fluentd-elasticsearch-e2e-gce-builder-4-2-minion-y5o4 started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.473: INFO: kubernetes-dashboard-v0.1.0-oq3h4 started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.473: INFO: kube-proxy-e2e-gce-builder-4-2-minion-y5o4 started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.473: INFO: service2-k2iix started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.473: INFO: kube-dns-v10-q2un4 started at <nil> (0 container statuses recorded)
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="info"} => 1 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="inspect_image"} => 17 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="list_containers"} => 32 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="list_images"} => 5 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="pull_image"} => 1 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="stop_container"} => 7 @[0]
Feb  9 23:02:44.828: INFO: ERROR kubelet_docker_errors{operation_type="version"} => 22 @[0]
Feb  9 23:02:44.828: INFO: 
Latency metrics for node e2e-gce-builder-4-2-minion-y5o4
Feb  9 23:02:44.828: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.99 Latency:51.315719s}
Feb  9 23:02:44.828: INFO: {Operation: Method:pod_worker_start_latency_microseconds Quantile:0.99 Latency:35.106947s}
Feb  9 23:02:44.828: INFO: {Operation:stop_container Method:docker_operations_latency_microseconds Quantile:0.99 Latency:29.023543s}
Feb  9 23:02:44.828: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.99 Latency:27.23921s}
Feb  9 23:02:44.828: INFO: {Operation:SyncPod Method:container_manager_latency_microseconds Quantile:0.99 Latency:27.213352s}
Feb  9 23:02:44.828: INFO: {Operation: Method:pod_start_latency_microseconds Quantile:0.9 Latency:17.989609s}
Feb  9 23:02:44.828: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.99 Latency:15.698118s}
Feb  9 23:02:44.828: INFO: {Operation:sync Method:pod_worker_latency_microseconds Quantile:0.99 Latency:15.032771s}
Feb  9 23:02:44.828: INFO: {Operation:pull_image Method:docker_operations_latency_microseconds Quantile:0.9 Latency:14.658258s}
Feb  9 23:02:44.828: INFO: {Operation:create Method:pod_worker_latency_microseconds Quantile:0.9 Latency:10.06315s}
Feb  9 23:02:44.828: INFO: Waiting up to 1m0s for all nodes to be ready
STEP: Destroying namespace "e2e-tests-kubectl-age9q" for this suite.


• Failure [77.568 seconds]
Kubectl client
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1030
  Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:502
    should support exec through an HTTP proxy [It]
    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:432

    Feb  9 23:02:40.036: Unexpected kubectl exec output. Wanted "running in container\n", got  "error: Timeout occured\n"

    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:420
------------------------------

ncdc · 2016-02-10T16:53:40Z

The root cause of the new failure is different. The new failure is Unexpected kubectl exec output. Wanted "running in container\n", got "error: Timeout occured\n". When I was working on #20444, I ran into this. A little history:

Before #20444 there was a bug in spdystream (sadly introduced by me 😦) where if a goaway frame was received, instead of breaking out of the loop that waits for new incoming frames, the connection just sat there waiting for new frames forever.

With spdystream fixed and the Godep updated in Kubernetes, I started seeing these Timeout occurred errors sporadically when running certain test cases. This is what was happening:

Client sends a "new stream" frame to server
Server receives "new stream" frame
New stream sent to channel in 1 goroutine
Race condition:
1. In 1 goroutine, test code instructs the server to close the connection (send a goaway frame)
2. In another goroutine, the server sends a "stream reply" frame to the client

If the server sends the goaway frame before it sends the stream reply frame, you'll get the Timeout occurred error because the client is sitting there waiting to get the reply frame before it proceeds, and it never gets it because it processes the goaway frame first.

In #20444 I added code to ensure that the stream reply frame is sent before the goaway frame. I will have to do some more digging to see why this is happening now.

ncdc · 2016-02-12T02:35:24Z

I looked at the big log above and extracted this info from the goproxy pod's log:

2016/02/09 23:02:08 [001] INFO: Running 0 CONNECT handlers
2016/02/09 23:02:08 [001] INFO: Accepting CONNECT to 173.255.119.234:443
2016/02/09 23:02:09 [002] INFO: Running 0 CONNECT handlers
2016/02/09 23:02:09 [002] INFO: Accepting CONNECT to 173.255.119.234:443
2016/02/09 23:02:10 [002] WARN: Error copying to client: read tcp 10.245.4.5:8080->10.245.2.18:47511: read tcp 10.245.4.5:47553->173.255.119.234:443: read: connection reset by peer
2016/02/09 23:02:39 [002] WARN: Error copying to client: read tcp 10.245.4.5:47553->173.255.119.234:443: write tcp 10.245.4.5:47553->173.255.119.234:443: use of closed network connection

The apiserver also shows this:

E0209 23:02:10.003146       6 proxy.go:172] Error proxying data from client to backend: read tcp 104.154.29.85:47553: connection reset by peer

This same "connection reset" error shows up several times in the log file, but I also see it in clean e2e runs, so it may be a red herring, or not...

mikedanese · 2016-02-12T21:39:28Z

This flake is currently blocking merges
http://kubekins.dls.corp.google.com/view/Critical%20Builds/job/kubernetes-e2e-gce/11466/

ncdc · 2016-02-12T21:44:40Z

@mikedanese my availability is limited for the next few days (personal reasons). I hesitate to suggest this, but you could temporarily skip this test until I have more time to research it.

ncdc · 2016-02-12T21:46:45Z

@mikedanese the link you just posted is a different root cause:

• Failure [61.683 seconds]
Kubectl client
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1030
  Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:502
    should support exec through an HTTP proxy [It]
    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:432

    Feb 12 13:18:54.221: Unexpected kubectl exec output. Wanted "running in container\n", got  "Unable to connect to the server: net/http: TLS handshake timeout\n"

    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:420
------------------------------

I think this issue has been repurposed a few times.... Should we create individual issues for each root cause?

ncdc · 2016-02-12T22:01:28Z

Is it possible the testbed was under so much load that the TLS handshake from kubectl (running in the netexec pod) through the goproxy pod to the apiserver didn't complete within the 10 second handshake timeout?

davidopp · 2016-02-15T02:19:31Z

Hit it again
pull/21057/kubernetes-pull-build-test-e2e-gce/28542

ixdy · 2016-03-07T21:47:15Z

Found new conclusive evidence of this test occasionally hanging. Forked off to #22671.

bprashanth · 2016-04-04T21:38:54Z

Also in https://pantheon.corp.google.com/storage/browser/kubernetes-jenkins/pr-logs/pull/23541/kubernetes-pull-build-test-e2e-gce/34143/

Apr  1 10:06:23.406: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://104.197.133.138 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config log goproxy --namespace=e2e-tests-kubectl-m7fxd'
Apr  1 10:06:23.721: INFO: stderr: ""
Apr  1 10:06:23.721: INFO: stdout: "2016/04/01 17:05:52 [001] INFO: Running 0 CONNECT handlers\n2016/04/01 17:05:52 [001] INFO: Accepting CONNECT to 104.197.133.138:443\n2016/04/01 17:05:53 [002] INFO: Running 0 CONNECT handlers\n2016/04/01 17:05:53 [002] INFO: Accepting CONNECT to 104.197.133.138:443\n2016/04/01 17:06:00 [002] WARN: Error copying to client: read tcp 10.245.6.4:8080->10.245.5.7:59190: read tcp 10.245.6.4:43550->104.197.133.138:443: read: connection reset by peer\n2016/04/01 17:06:23 [002] WARN: Error copying to client: read tcp 10.245.6.4:43550->104.197.133.138:443: write tcp 10.245.6.4:43550->104.197.133.138:443: use of closed network connection"
Apr  1 10:06:23.721: FAIL: Unexpected kubectl exec output. Wanted "running in container\n", got  "error: Timeout occured\n"
STEP: using delete to clean up resources
Apr  1 10:06:23.721: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://104.197.133.138 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/.kube/config delete --grace-period=0 -f /var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/test/images/netexec/pod.yaml --namespace=e2e-tests-kubectl-m7fxd'
Apr  1 10:06:24.009: INFO: stderr: ""
Apr  1 10:06:24.010: INFO: stdout: "pod \"netexec\" deleted"
Apr  1 10:06:24.010: INFO: Running '/var/lib/jenkins/workspace/kubernetes-pull-build-test-e2e-gce@2/kubernetes/platforms/linux/amd64/kubectl --server=https://104.197.133.138 --kubeconfig=/var/lib/jenkins/workspace/kubernetes-pull-build-te

piosz · 2016-04-25T10:23:32Z

closing in favor of #22671

fabioy added area/test kind/flake Categorizes issue or PR as related to a flaky test. labels Jan 28, 2016

j3ffml self-assigned this Jan 29, 2016

goltermann added the sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. label Jan 29, 2016

lavalamp mentioned this issue Jan 29, 2016

add instructions to ease follow-up #20342

Merged

ixdy mentioned this issue Jan 30, 2016

E2e: jenkins test run timeouts without clear reason #13485

Closed

erictune added the priority/important-soon Must be staffed and worked on either currently, or very soon, ideally in time for the next release. label Feb 4, 2016

erictune mentioned this issue Feb 4, 2016

Print line number of failed link conversion. #20592

Merged

yujuhong mentioned this issue Feb 5, 2016

Kubelet: Remove GetAPIPodStatus from runtime interface #20192

Merged

lavalamp closed this as completed Feb 9, 2016

mikedanese mentioned this issue Feb 9, 2016

add http handler to export configuration state #20528

Merged

j3ffml reopened this Feb 9, 2016

j3ffml assigned ncdc and unassigned j3ffml Feb 10, 2016

ixdy mentioned this issue Feb 10, 2016

occasional e2e suite timeouts #20778

Closed

davidopp mentioned this issue Feb 15, 2016

Comment out NodeAffinity.RequiredDuringSchedulingRequiredDuringExecution #21057

Merged

ncdc mentioned this issue Feb 22, 2016

New features in ResourceQuota #20446

Merged

wojtek-t mentioned this issue Feb 23, 2016

Ensure created service account tokens are available to the token controller #21706

Merged

gmarek changed the title ~~Flake: Simple pod should support exec through an HTTP proxy~~ e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy Mar 7, 2016

gmarek mentioned this issue Mar 7, 2016

Don't sync all objects for replenishment as often as ResourceQuota. #22628

Merged

ixdy mentioned this issue Mar 7, 2016

e2e flake: "Kubectl client Simple pod should support exec through an HTTP proxy" occasionally hangs #22671

Closed

spxtr mentioned this issue Mar 9, 2016

More GCE 1.2 jobs. #22753

Merged

This was referenced Mar 12, 2016

Version-skewed Kubectl client Simple pod should support exec through an HTTP proxy #22884

Closed

Adding FullyLabeledReplicas field to replicaset status #22847

Merged

0xmichalis mentioned this issue Mar 21, 2016

kubectl: print errors that wont be reloaded in the editor #22634

Merged

bprashanth mentioned this issue Apr 4, 2016

Default firewall port to TCP when unspecified. #23541

Merged

a-robinson mentioned this issue Apr 11, 2016

Add an e2e test suite for multi-zone GKE clusters. #24075

Merged

ixdy mentioned this issue Apr 13, 2016

Compute Jenkins job config XML changes easily #24068

Merged

mikedanese mentioned this issue Apr 14, 2016

don't ship kube-registry-proxy and pause images in tars. #23605

Merged

errm mentioned this issue Apr 19, 2016

Allow setting the Host header in a httpGet probe #24292

Merged

piosz closed this as completed Apr 25, 2016

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy #19997

e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy #19997

erictune commented Jan 22, 2016

j3ffml commented Jan 29, 2016

lavalamp commented Jan 29, 2016

lavalamp commented Jan 29, 2016

lavalamp commented Jan 29, 2016

j3ffml commented Jan 29, 2016

lavalamp commented Jan 29, 2016

j3ffml commented Jan 30, 2016

ixdy commented Jan 30, 2016

ixdy commented Jan 30, 2016

j3ffml commented Feb 2, 2016

j3ffml commented Feb 3, 2016

erictune commented Feb 4, 2016

lavalamp commented Feb 9, 2016

mikedanese commented Feb 9, 2016

j3ffml commented Feb 9, 2016

ncdc commented Feb 10, 2016

ncdc commented Feb 12, 2016

mikedanese commented Feb 12, 2016

ncdc commented Feb 12, 2016

ncdc commented Feb 12, 2016

ncdc commented Feb 12, 2016

davidopp commented Feb 15, 2016

ixdy commented Mar 7, 2016

bprashanth commented Apr 4, 2016

piosz commented Apr 25, 2016

e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy #19997

e2e flake: Kubectl client Simple pod [It] should support exec through an HTTP proxy #19997

Comments

erictune commented Jan 22, 2016

j3ffml commented Jan 29, 2016

lavalamp commented Jan 29, 2016

lavalamp commented Jan 29, 2016

lavalamp commented Jan 29, 2016

j3ffml commented Jan 29, 2016

lavalamp commented Jan 29, 2016

j3ffml commented Jan 30, 2016

ixdy commented Jan 30, 2016

ixdy commented Jan 30, 2016

j3ffml commented Feb 2, 2016

j3ffml commented Feb 3, 2016

erictune commented Feb 4, 2016

lavalamp commented Feb 9, 2016

mikedanese commented Feb 9, 2016

j3ffml commented Feb 9, 2016

ncdc commented Feb 10, 2016

ncdc commented Feb 12, 2016

mikedanese commented Feb 12, 2016

ncdc commented Feb 12, 2016

ncdc commented Feb 12, 2016

ncdc commented Feb 12, 2016

davidopp commented Feb 15, 2016

ixdy commented Mar 7, 2016

bprashanth commented Apr 4, 2016

piosz commented Apr 25, 2016