v1.2 "Kubectl client Simple pod should support port-forward" hanging when run with v1.3 Kubectl #26594

ikehz · 2016-05-31T22:14:00Z

Kubectl client Simple pod 
  should support port-forward
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework.go:100
STEP: Creating a kubernetes client
May 31 15:09:49.323: INFO: >>> testContext.KubeConfig: /usr/local/google/home/ihmccreery/.kube/config

STEP: Building a namespace api object
May 31 15:09:49.377: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-uc5qv
May 31 15:09:49.418: INFO: Service account default in ns e2e-tests-kubectl-uc5qv with secrets found. (40.713401ms)
STEP: Waiting for a default service account to be provisioned in namespace
May 31 15:09:49.418: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-uc5qv
May 31 15:09:49.459: INFO: Service account default in ns e2e-tests-kubectl-uc5qv with secrets found. (40.667732ms)
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:120
[BeforeEach] Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:190
STEP: creating the pod from /usr/local/google/home/ihmccreery/Documents/kubernetes-alt/test/e2e/testing-manifests/kubectl/pod-with-readiness-probe.yaml
May 31 15:09:49.459: INFO: Running '/usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh --server=https://146.148.104.150 --kubeconfig=/usr/local/google/home/ihmccreery/.kube/config create -f /usr/local/google/home/ihmccreery/Documents/kubernetes-alt/test/e2e/testing-manifests/kubectl/pod-with-readiness-probe.yaml --namespace=e2e-tests-kubectl-uc5qv'
May 31 15:09:50.066: INFO: stderr: ""
May 31 15:09:50.066: INFO: stdout: "pod \"nginx\" created\n"
May 31 15:09:50.066: INFO: Waiting up to 5m0s for 1 pods to be running and ready: [nginx]
May 31 15:09:50.066: INFO: Waiting up to 5m0s for pod nginx status to be running and ready
May 31 15:09:50.107: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-uc5qv' status to be 'running and ready'(found phase: "Pending", readiness: false) (40.643351ms elapsed)
May 31 15:09:52.151: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-uc5qv' status to be 'running and ready'(found phase: "Running", readiness: false) (2.084719295s elapsed)
May 31 15:09:54.193: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-uc5qv' status to be 'running and ready'(found phase: "Running", readiness: false) (4.126926727s elapsed)
May 31 15:09:56.236: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-uc5qv' status to be 'running and ready'(found phase: "Running", readiness: false) (6.170280744s elapsed)
May 31 15:09:58.279: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-uc5qv' status to be 'running and ready'(found phase: "Running", readiness: false) (8.212968774s elapsed)
May 31 15:10:00.322: INFO: Wanted all 1 pods to be running and ready. Result: true. Pods: [nginx]
[It] should support port-forward
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525
STEP: forwarding the container port to a local port
May 31 15:10:00.322: INFO: starting port-forward command and streaming output
May 31 15:10:00.322: INFO: Asynchronously running '/usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh /usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh --server=https://146.148.104.150 --kubeconfig=/usr/local/google/home/ihmccreery/.kube/config port-forward --namespace=e2e-tests-kubectl-uc5qv nginx :80'
May 31 15:10:00.323: INFO: reading from `kubectl port-forward` command's stderr

[hangs]

^C

[...]

• Failure [65.392 seconds]
Kubectl client
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1200
  Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:526
    should support port-forward [It]
    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525

    May 31 15:10:51.904: Failed to read from kubectl port-forward stderr: EOF

    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/portforward.go:97

Repro:

$ git checkout release-1.2
$ make clean && make quick-release
$ go run ./hack/e2e.go --check_version_skew=false -v --test '--test_args=--ginkgo.focus=Kubectl\sclient\sSimple\spod\sshould\ssupport\sport-forward --kubectl-path=<PATH TO 1.3 KUBECTL>'

My guess is just that this test just isn't resilient to empty output. Then there's the separate issue of actually fixing the root problem.

The text was updated successfully, but these errors were encountered:

ikehz · 2016-05-31T22:27:21Z

This looks like a result of #17030. That PR has a release-note label, so this is a (breaking) change we'll notify users about. I just have to figure out how we want to rig the test to be okay.

ikehz · 2016-05-31T23:13:37Z

Hm. Even using stdout instead of stderr, I still see:

Kubectl client Simple pod 
  should support port-forward
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/framework.go:100
STEP: Creating a kubernetes client
May 31 16:10:05.249: INFO: >>> testContext.KubeConfig: /usr/local/google/home/ihmccreery/.kube/config

STEP: Building a namespace api object
May 31 16:10:05.304: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-774gw
May 31 16:10:05.345: INFO: Service account default in ns e2e-tests-kubectl-774gw with secrets found. (40.73484ms)
STEP: Waiting for a default service account to be provisioned in namespace
May 31 16:10:05.345: INFO: Waiting up to 2m0s for service account default to be provisioned in ns e2e-tests-kubectl-774gw
May 31 16:10:05.386: INFO: Service account default in ns e2e-tests-kubectl-774gw with secrets found. (40.867227ms)
[BeforeEach] Kubectl client
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:120
[BeforeEach] Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:190
STEP: creating the pod from /usr/local/google/home/ihmccreery/Documents/kubernetes-alt/test/e2e/testing-manifests/kubectl/pod-with-readiness-probe.yaml
May 31 16:10:05.386: INFO: Running '/usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh --server=https://146.148.104.150 --kubeconfig=/usr/local/google/home/ihmccreery/.kube/config create -f /usr/local/google/home/ihmccreery/Documents/kubernetes-alt/test/e2e/testing-manifests/kubectl/pod-with-readiness-probe.yaml --namespace=e2e-tests-kubec
tl-774gw'
May 31 16:10:05.990: INFO: stderr: ""
May 31 16:10:05.991: INFO: stdout: "pod \"nginx\" created\n"
May 31 16:10:05.991: INFO: Waiting up to 5m0s for 1 pods to be running and ready: [nginx]
May 31 16:10:05.991: INFO: Waiting up to 5m0s for pod nginx status to be running and ready
May 31 16:10:06.033: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-774gw' status to be 'running and ready'(found phase: "Pending", readiness: false) (41.912515ms elapsed)
May 31 16:10:08.075: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-774gw' status to be 'running and ready'(found phase: "Running", readiness: false) (2.084452796s elapsed)
May 31 16:10:10.118: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-774gw' status to be 'running and ready'(found phase: "Running", readiness: false) (4.127248318s elapsed)
May 31 16:10:12.160: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-774gw' status to be 'running and ready'(found phase: "Running", readiness: false) (6.169868068s elapsed)
May 31 16:10:14.203: INFO: Waiting for pod nginx in namespace 'e2e-tests-kubectl-774gw' status to be 'running and ready'(found phase: "Running", readiness: false) (8.212009843s elapsed)
May 31 16:10:16.245: INFO: Wanted all 1 pods to be running and ready. Result: true. Pods: [nginx]
[It] should support port-forward
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525
STEP: forwarding the container port to a local port
May 31 16:10:16.245: INFO: starting port-forward command and streaming output
May 31 16:10:16.245: INFO: Asynchronously running '/usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh /usr/local/google/home/ihmccreery/Documents/kubernetes/cluster/kubectl.sh --server=https://146.148.104.150 --kubeconfig=/usr/local/google/home/ihmccreery/.kube/config port-forward --namespace=e2e-tests-kubectl-774gw nginx :80'
May 31 16:10:16.246: INFO: reading from `kubectl port-forward` command's stdout
STEP: curling local port output
May 31 16:10:16.847: INFO: got: 
May 31 16:10:16.847: FAIL: Failed http.Get of forwarded port (http://localhost:36038): Get http://localhost:36038: read tcp 127.0.0.1:36038: connection reset by peer

[...]

• Failure [19.684 seconds]
Kubectl client
/go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1200
  Simple pod
  /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:526
    should support port-forward [It]
    /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:525

    May 31 16:10:16.847: Failed http.Get of forwarded port (http://localhost:36038): Get http://localhost:36038: read tcp 127.0.0.1:36038: connection reset by peer

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

ikehz · 2016-06-02T21:38:38Z

#22149 (comment) seems to be the problem; removing these calls fixes the problem:

defer stdout.Close()
defer stderr.Close()

@ncdc authored #23445, which I think we should backport to 1.2 and 1.1 if possible.

ncdc · 2016-06-02T21:43:28Z

@ihmccreery yeah that sounds like a correct analysis re closing stdout/stderr. But are 1.2 and 1.1 built with go 1.6?

ikehz · 2016-06-02T21:51:21Z

No, they aren't, but when Kubectl v1.3 is, so when running v1.2 tests with a v1.3 Kubectl, the new SIGPIPE logic applies, IIUC.

ncdc · 2016-06-02T22:13:00Z

I think the PR of mine you referenced only has to do with the e2e tests vs
the go version. I don't think the kubectl version matters, does it? Have
you tried running the 1.2 e2es compiled with go < 1.6 along with a 1.3
kubectl?

On Thursday, June 2, 2016, Isaac Hollander McCreery <
notifications@github.com> wrote:

No, they aren't, but when Kubectl v1.3 is, so when running v1.2 tests with
a v1.3 Kubectl, the new SIGPIPE logic applies, IIUC.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
#26594 (comment),
or mute the thread
https://github.com/notifications/unsubscribe/AAABYtu7DSzosCa6O91aDGl3UVo0zxSsks5qH1CSgaJpZM4IrAqp
.

ncdc · 2016-06-03T00:58:03Z

Nevermind, maybe... I think you're right 😄

ikehz · 2016-06-03T17:50:19Z

My read of #22149 (comment) is that it's the version of Go the client is compiled with, combined with the

defer stdout.Close()
defer stderr.Close()
...
stderr.Read(buf)
...
return cmd

pattern that's the issue:

The code snippet reads that amount and then closes standard error. Then later the subprocess writes a small amount more to standard error. Specifically, at least one write but fewer than 10 writes. If it had gone over 10 writes in Go 1.5 or earlier, it would have been killed even in the earlier releases. Now the cutoff is effectively 1 instead of 10, so the subprocess crosses the line earlier.

ikehz · 2016-06-09T00:28:30Z

This is now affecting:

14:50:31 • [SLOW TEST:24.294 seconds]
14:50:31 Kubectl client
14:50:31 /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1200
14:50:31   Kubectl run job
14:50:31   /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1124
14:50:31     should create a job from an image when restart is OnFailure [Conformance]
14:50:31     /go/src/k8s.io/kubernetes/_output/dockerized/go/src/k8s.io/kubernetes/test/e2e/kubectl.go:1104
14:50:31 ------------------------------
14:50:31 S+ rc=124
16:38:44 + [[ 124 -ne 0 ]]
16:38:44 + [[ -x kubernetes/cluster/log-dump.sh ]]
16:38:44 + [[ 124 -eq 124 ]]
16:38:44 
+ echo 'Build timed out'

E.g. https://console.cloud.google.com/storage/browser/kubernetes-jenkins/logs/kubernetes-e2e-gke-1.2-1.3-kubectl-skew/398

ncdc · 2016-06-09T13:56:41Z

@ihmccreery by "this" do you mean deferred stdout/stderr.Close calls in the job test?

ikehz · 2016-06-09T16:50:04Z

Ah, no I mean #17030, which changed certain output from stderr to stdout. That's what causes the test to hang—it's expecting output from stderr, and just waits forever.

ikehz · 2016-06-11T01:07:39Z

#26643 takes care of the hang, but doesn't address the root problem; we should follow it up with a PR into master that makes the test more resilient to receiving nothing from stdout by adding a timeout somewhere. But that can be post-v1.3.

Automatic merge from submit-queue Add kubectl version guard around kubectl port-forward Fixes #26594 (once this gets backported to v1.2 and v1.3).

ikehz added area/test area/upgrade team/ux labels May 31, 2016

ikehz added this to the v1.3 milestone May 31, 2016

ikehz assigned ikehz and unassigned ikehz May 31, 2016

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

ikehz mentioned this issue Jun 1, 2016

Add kubectl version guard around kubectl port-forward #26643

Closed

ikehz mentioned this issue Jun 2, 2016

Update port forward e2e for go 1.6 #23445

Merged

ikehz self-assigned this Jun 6, 2016

ikehz mentioned this issue Jun 6, 2016

Automated cherry pick of #23445 #26918

Merged

ikehz mentioned this issue Jun 9, 2016

Jenkins doesn't delete container when timing out a run #26647

Closed

ikehz mentioned this issue Jun 13, 2016

Add kubectl version guard around kubectl port-forward #27310

Merged

k8s-github-robot closed this as completed in #27310 Jun 14, 2016

This was referenced Jun 15, 2016

Automated cherry pick of #27310 #27448

Merged

Automated cherry pick of #23445 #27310 #27453

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

v1.2 "Kubectl client Simple pod should support port-forward" hanging when run with v1.3 Kubectl #26594

v1.2 "Kubectl client Simple pod should support port-forward" hanging when run with v1.3 Kubectl #26594

ikehz commented May 31, 2016

ikehz commented May 31, 2016

ikehz commented May 31, 2016

ikehz commented Jun 2, 2016

ncdc commented Jun 2, 2016

ikehz commented Jun 2, 2016

ncdc commented Jun 2, 2016

ncdc commented Jun 3, 2016

ikehz commented Jun 3, 2016

ikehz commented Jun 9, 2016 •

edited

Loading

ncdc commented Jun 9, 2016

ikehz commented Jun 9, 2016

ikehz commented Jun 11, 2016

v1.2 "Kubectl client Simple pod should support port-forward" hanging when run with v1.3 Kubectl #26594

v1.2 "Kubectl client Simple pod should support port-forward" hanging when run with v1.3 Kubectl #26594

Comments

ikehz commented May 31, 2016

ikehz commented May 31, 2016

ikehz commented May 31, 2016

ikehz commented Jun 2, 2016

ncdc commented Jun 2, 2016

ikehz commented Jun 2, 2016

ncdc commented Jun 2, 2016

ncdc commented Jun 3, 2016

ikehz commented Jun 3, 2016

ikehz commented Jun 9, 2016 • edited Loading

ncdc commented Jun 9, 2016

ikehz commented Jun 9, 2016

ikehz commented Jun 11, 2016

ikehz commented Jun 9, 2016 •

edited

Loading