[Fail] [k8s.io] Pods [It] should support remote command execution over websockets [Suite:openshift/conformance/parallel] [Suite:k8s]

[gabemontero]

See https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin_extended_conformance_install/7855/consoleFull#-169259343956c60d7be4b02b88ae8c268b

The failed test highlighted that Feb 22 20:21:07.165: Got message from server that didn't start with channel 1 (STDOUT): [2]

The pod for the test was in fact running.

I saw no errors in the node log for the pod prior to the namespace getting tore down.

[gabemontero]

@openshift/sig-kube-origin

[gabemontero]

@sjenning fyi

[sosiouxme]

subject looks similar to #18721 but not sure failure is the same.

I saw this too in https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/18709/test_pull_request_origin_extended_conformance_install/7879/

[deads2k]

Is this flaking or just straight out failing?

[deads2k]

No successful runs in the last 18 hours. Bumping to p0.

[deads2k]

The commit suggested by https://deck-ci.svc.ci.openshift.org/?job=test_branch_origin_extended_conformance_install doesn't make any sense. It must be a side-effect of something else.

@Kargakis @stevekuznetsov @derekwaynecarr there was a docker something in our ami, right?

[runcom]

This has been broken by the upgrade to docker 1.13 (very very likely). First build with 1.13 broken:

https://ci.openshift.redhat.com/jenkins/job/test_pull_request_origin_extended_conformance_install/7843/consoleFull#51637152658b6e51eb7608a5981914356

Previous build with 1.12 success: https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/18625/test_pull_request_origin_extended_conformance_install/7842/

[gabemontero]

removed all "flake" indicators from this issue

[runcom]

@sjenning @deads2k @gabemontero could you guys assist us with narrowing down the issue to a docker issue? Not sure what in origin triggers that error.

[sdodson]

https://openshift-gce-devel.appspot.com/build/origin-ci-test/pr-logs/pull/openshift_openshift-ansible/7235/test_pull_request_openshift_ansible_extended_conformance_install/5564/#k8sio-pods-should-support-remote-command-execution-over-websockets-suiteopenshiftconformanceparallel-suitek8s

[stevekuznetsov]

Reverted the 1.13 AMI

[deads2k]

It's failing here: https://github.com/openshift/origin/blob/master/vendor/k8s.io/kubernetes/test/e2e/common/pods.go#L526 after an exec call. The websocket appears to be passed through https://github.com/openshift/origin/blob/master/vendor/k8s.io/kubernetes/pkg/kubelet/server/remotecommand/websocket.go#L73

it's not obvious to me why docker levels matter, but perhaps @sjenning knows.

[sjenning]

I'm seeing this in the node log

Feb 23 14:29:07 ip-172-18-1-150.ec2.internal origin-node[26740]: I0223 14:29:07.964266   26740 server.go:800] GET /exec/e2e-tests-pods-wn695/pod-exec-websocket-e22e0362-18a5-11e8-beb9-0ea3dacd3950/main?command=cat&command=%2Fetc%2Fresolv.conf&error=1&output=1: (35.208338ms) 302 [[Go-http-client/1.1] 172.18.1.150:50886]

Seems that we are getting a 302 redirection from the endpoint.

[sjenning]

I see that 302 on both versions of docker in my local cluster so that isn't it.

I have near zero knowledge about websockets, spdy, http/2, etc so this could take me a while to figure out. Anyone that knows more is welcome to figure it out faster. @smarterclayton ?

However, it seems that the test is reading the stream for STDERR with stream id 2 rather than STDOUT with stream 1 id as the test expects. The query params indicate the desire for both streams. I'm not sure how the test ensures that the STDOUT stream is the one that it is reading.

[sjenning]

I do wonder if we just removed this line if it would resolve the situation since the test does not expect to read from STDERR
https://github.com/openshift/origin/blob/master/vendor/k8s.io/kubernetes/test/e2e/common/pods.go#L499

[liggitt]

The 302 is a redirect followed by the API server before returning anything to the client, and has to do with redirecting to what will eventually be a CRI endpoint on the node. For now, it is still served by the kubelet.

[liggitt]

We are requesting both stdout and stderr output from running the command be sent to us, but we are not expecting to actually receive any stderr output from that command, which is why the test fails if it receives a message on the stderr channel. We should not change the test to ignore error output. I do wonder if docker changed to send zero byte writes to the standard error output stream. I could potentially see updating the test to ignore empty stderr channel messages.

[smarterclayton]

Sorry I didn't respond, I think ignoring empty stderr channel messages is totally fine. We use them in other contexts and if we have websockets support ever we will deliver zero byte messages.

[runcom]

We are requesting both stdout and stderr output from running the command be sent to us, but we are not expecting to actually receive any stderr output from that command, which is why the test fails if it receives a message on the stderr channel. We should not change the test to ignore error output. I do wonder if docker changed to send zero byte writes to the standard error output stream. I could potentially see updating the test to ignore empty stderr channel messages.

is there any way to read what's in STDERR actually? @liggitt @sjenning

[liggitt]

is there any way to read what's in STDERR actually? @liggitt @sjenning

the content of the message is logged, and is empty:

Feb 22 20:21:07.165: Got message from server that didn't start with channel 1 (STDOUT): [2]

that means the message contained exactly one byte (2) which indicated the stderr channel, and no other content

[sjenning]

Opened PR kubernetes/kubernetes#60457 upstream