prevent corrupted spdy stream after hijacking connection #43922

cezarsa · 2017-03-31T18:48:46Z

This PR fixes corner case in spdy stream code where some bytes would never arrive at the server.

Reading directly from a hijacked connection isn't safe because some data may have already been read by the server before Hijack was called. To ensure all data will be received it's safer to read from the returned bufio.Reader. This problem seem to happen more frequently when using Go 1.8.
This is described in https://golang.org/pkg/net/http/#Hijacker:

// The returned bufio.Reader may contain unprocessed buffered
// data from the client.

I came across this while debugging a flaky test that used code from the k8s.io/apimachinery/pkg/util/httpstream/spdy package. After filling the code with debug logs and long hours running the tests in loop in the hope of catching the error I finally caught something weird.

The first word on the first spdy frame read by the server here had the value 0x03000100. See, the first frame to arrive on the server was supposed to be a control frame indicating the creation of a new stream, but all control frames need the high-order bit set to 1, which was not the case here, so the saver mistakenly assumed this was a data frame and the stream would never be created. The correct value for the first word of a SYN_STREAM frame was supposed to be 0x80030001 and this lead me on the path of finding who had consumed the first 1 byte prior to the frame reader being called and finally finding the problem with the Hijack call.

I added a new test to try stressing this condition and ensuring that this bug doesn't happen anymore. However, it's quite ugly as it loops 1000 times creating streams on servers to increase the chances of this bug happening. So, I'm not sure whether it's worth it to keep this test or if I should remove it from the PR. Please let me know what you guys think and I'll be happy to update this.

Fixes #45093 #45089 #45078 #45075 #45072 #45066 #45023

k8s-reviewable · 2017-03-31T18:48:53Z

This change is

k8s-ci-robot · 2017-03-31T18:48:54Z

Hi @cezarsa. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with @k8s-bot ok to test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

ncdc · 2017-03-31T20:28:46Z

@cezarsa thanks for writing this. It's been on my list but I hadn't gotten around to it yet. This was also something that confused me - are we supposed to read from the buffered reader until it's exhausted, and then switch to reading from the connection, or can we do what you did, and just always read from the buffered reader?

cezarsa · 2017-03-31T23:48:38Z

@ncdc I'm glad I could help. It was an interesting one to track down. :)

From what I can see by looking at the hijack implementation it's safe to keep reading from the bufio.Reader, after the buffer has been exhausted it will read from the underlying connection (actually it's backed by a *connReader instance which then reads from the connection). Also, tests are passing some that's some indication that it's doing its job.

I guess there's a slight overhead of reading from the bufio.Reader because it goes through the connReader but in my opinion that's not enough to justify adding logic to read from the bufio.Reader and then switch the Conn directly once its been exhausted.

grodrigues3 · 2017-04-13T18:21:22Z

@k8s-bot ok to test

smarterclayton · 2017-04-13T20:47:06Z

/approve

cezarsa · 2017-04-13T22:13:38Z

I'm not sure about what went wrong in the tests. It looks like the apiserver didn't even start on Jenkins GCE e2e tests. Is this my fault? Should I rebase the code? Any pointers on how to deal with this are welcome. :)

ncdc · 2017-04-17T14:02:09Z

@k8s-bot cvm gce e2e test this
@k8s-bot gce etcd3 e2e test this

ncdc · 2017-04-17T14:06:17Z

I added a new test to try stressing this condition and ensuring that this bug doesn't happen anymore. However, it's quite ugly as it loops 1000 times creating streams on servers to increase the chances of this bug happening. So, I'm not sure whether it's worth it to keep this test or if I should remove it from the PR. Please let me know what you guys think and I'll be happy to update this.

I'm a bit hesitant to include this test. How frequently does it fail without your fix?

cezarsa · 2017-04-19T13:06:39Z

Sorry for the late response. The added test always fails with Go 1.8, however I couldn't trigger a failure with Go 1.7. I'm fine removing it as it was most useful when debugging this.

ncdc · 2017-04-19T13:37:11Z

staging/src/k8s.io/apimachinery/pkg/util/httpstream/spdy/upgrade.go

@@ -32,6 +34,19 @@ const HeaderSpdy31 = "SPDY/3.1"
 type responseUpgrader struct {
 }

+// connWrapper is used to wrap a hijacked connection its bufio.Reader. All


Could you please put an "and" in between "connection" and "its"?

ncdc · 2017-04-19T13:39:09Z

OK, thanks for the info. @liggitt do you think we should keep or remove this new test?

liggitt · 2017-04-19T13:49:24Z

I'd rather have a deterministic non-stress test for the unit test. If that's not possible, I'd probably remove this one.

From what I can see by looking at the hijack implementation it's safe to keep reading from the bufio.Reader

This is slightly concerning... is the behavior of the returned buffer documented to work that way, or are we depending on an implementation detail that can change?

ncdc · 2017-04-19T13:54:44Z

I'd rather have a deterministic non-stress test for the unit test. If that's not possible, I'd probably remove this one.

AFAIK, this is not possible.

This is slightly concerning... is the behavior of the returned buffer documented to work that way, or are we depending on an implementation detail that can change?

Here is what is in godoc:

// The returned bufio.Reader may contain unprocessed buffered
// data from the client.
Hijack() (net.Conn, *bufio.ReadWriter, error)

I wonder if it would be safer to read from the bufio.ReadWriter until it's exhausted, then switch to reading from the net.Conn?

Or we could ask the go team what we should do.

ncdc · 2017-04-19T13:58:13Z

BTW this was guidance from the go team: #38228 (comment)

ncdc · 2017-04-19T14:33:30Z

@dsnet could you please review this PR and let us know if it's acceptable re the use of the buffered reader returned by the Hijack() call, or if we need to do something differently? Thanks!

cezarsa · 2017-04-19T15:02:25Z

I'll remove the test. Regarding reading from the bufio, if we were to peek from the buffer something like this could be made maintain the wrapper idea:

func (w *connWrapper) Read(b []byte) (n int, err error) {
	if w.bufReader != nil {
		w.bufData, err = w.bufReader.Peek(w.bufReader.Buffered())
		if err != nil {
			return
		}
		w.bufReader = nil
	}
	if len(w.bufData) > 0 {
		n = copy(b, w.bufData)
		w.bufData = w.bufData[n:]
		return
	}
	return w.Conn.Read(b)
}

It's a bit more convoluted then reading straight from the bufio but it works.

liggitt · 2017-04-19T15:42:06Z

It's a bit more convoluted then reading straight from the bufio but it works.

can we use https://golang.org/pkg/io/#MultiReader ?

ncdc · 2017-04-19T15:56:37Z

That certainly sounds better

cezarsa · 2017-04-19T16:32:47Z

Okay, but since using a io.MultiReader with the bufio and the net.Conn directly would not work because the bufio would never EOF, we have to create a bytes.Reader with the peeked []byte to use in the MultiReader:

func (w *connWrapper) Read(b []byte) (n int, err error) {
	if w.reader == nil {
		var bufData []byte
		bufData, err = w.bufReader.Peek(w.bufReader.Buffered())
		if err != nil {
			return
		}
		w.reader = io.MultiReader(bytes.NewReader(bufData), w.Conn)
	}
	return w.reader.Read(b)
}

dsnet · 2017-04-19T17:54:48Z

staging/src/k8s.io/apimachinery/pkg/util/httpstream/spdy/upgrade.go

+	bufReader *bufio.Reader
+}
+
+func (w *connWrapper) Read(b []byte) (n int, err error) {


This solution is okay, but has one edge case. When Close is called, it is entirely possible for Read to still return with data instead of EOF. That may or may not be surprising behavior.

To fix this, you could discard the buffer upon Close.

func (w *connWrapper) Close() error { err := w.Conn.Close() w.bufReader.Discard(w.bufReader.Buffered()) return err }

Also be careful that w.bufReader is not safe for concurrent use. I don't know if the usage of connWrapper allows calling Close and Read concurrently.

cezarsa · 2017-04-20T00:52:36Z

Updated with the atomic approach for now.

k8s-ci-robot · 2017-04-20T01:45:52Z

@cezarsa: The following test(s) failed:

Test name	Commit	Details	Rerun command
Jenkins GCI GCE e2e	`cc5a309`	link	`@k8s-bot gci gce e2e test this`
Jenkins non-CRI GCE e2e	`cc5a309`	link	`@k8s-bot non-cri e2e test this`

Full PR test history. Your PR dashboard. Please help us cut down on flakes by linking to an open issue when you hit one in your PR.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository. I understand the commands that are listed here.

luxas · 2017-04-26T17:59:28Z

Is this easier to do now that we have go1.8?
This PR should be prioritized in case it makes our implementation with Go 1.8 less race-prone

ncdc · 2017-04-28T11:35:50Z

We do need to get this in soon, as the upgrade to 1.8 and/or my #44451 have made the spdy-related tests flakey.

ncdc · 2017-04-28T11:37:55Z

@k8s-bot verify test this
@k8s-bot gci gce e2e test this
@k8s-bot non-cri e2e test this

ncdc · 2017-04-28T11:50:11Z

staging/src/k8s.io/apimachinery/pkg/util/httpstream/spdy/upgrade.go

+	if atomic.LoadInt32(&w.closed) == 1 {
+		return 0, io.EOF
+	}
+	return w.bufReader.Read(b)


@dsnet if we make it past the closed check on line 51, and before this line is executed, Close() executes and closes the net.Conn, what will happen when we next execute w.bufReader.Read(b) - will it EOF?

ncdc · 2017-04-28T11:50:50Z

/release-note-none

ncdc · 2017-04-28T11:51:06Z

/assign

ncdc · 2017-04-28T11:51:48Z

/lgtm

k8s-github-robot · 2017-04-28T11:51:54Z

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: cezarsa, ncdc, smarterclayton

Needs approval from an approver in each of these OWNERS Files:

~~staging/src/k8s.io/apimachinery/pkg/OWNERS~~ [smarterclayton]

You can indicate your approval by writing /approve in a comment
You can cancel your approval by writing /approve cancel in a comment

k8s-github-robot · 2017-04-28T14:40:03Z

Automatic merge from submit-queue

k8s-ci-robot added the cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. label Mar 31, 2017

k8s-github-robot assigned smarterclayton Mar 31, 2017

k8s-github-robot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. release-note-label-needed labels Mar 31, 2017

deads2k requested a review from ncdc March 31, 2017 19:36

grodrigues3 added the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Apr 5, 2017

k8s-ci-robot removed the needs-ok-to-test Indicates a PR that requires an org member to verify it is safe to test. label Apr 13, 2017

k8s-github-robot added the approved Indicates a PR has been approved by an approver from all required OWNERS files. label Apr 13, 2017

ncdc mentioned this pull request Apr 17, 2017

Increase journald rate limiter when running test-end-to-end-docker.sh openshift/origin#13669

Merged

ncdc reviewed Apr 19, 2017

View reviewed changes

dsnet approved these changes Apr 19, 2017

View reviewed changes

cezarsa force-pushed the spdy-fix branch from 26c3a1a to cc5a309 Compare April 20, 2017 00:51

ncdc mentioned this pull request Apr 28, 2017

TestStream {tests} #45063

Closed

0xmichalis added the kind/failing-test Categorizes issue or PR as related to a consistently or frequently failing test. label Apr 28, 2017

ncdc reviewed Apr 28, 2017

View reviewed changes

k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. and removed release-note-label-needed labels Apr 28, 2017

k8s-ci-robot assigned ncdc Apr 28, 2017

k8s-ci-robot added the lgtm "Looks good to me", indicates that a PR is ready to be merged. label Apr 28, 2017

k8s-github-robot merged commit 8787b13 into kubernetes:master Apr 28, 2017

ncdc mentioned this pull request Apr 28, 2017

TestServePortForward {streaming} #45104

Closed

luxas mentioned this pull request Apr 28, 2017

Update to Go 1.8; eval 1.8beta1 #38228

Closed

mikedanese mentioned this pull request Apr 28, 2017

rollback 1.8 upgrade of kubekins-test kubernetes/test-infra#2604

Closed

ncdc mentioned this pull request Apr 28, 2017

[k8s.io] Security Context when creating a pod in the host PID namespace should show its pid in the host PID namespace {E2eNode Suite} #45073

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

prevent corrupted spdy stream after hijacking connection #43922

prevent corrupted spdy stream after hijacking connection #43922

cezarsa commented Mar 31, 2017 •

edited by ncdc

Loading

k8s-reviewable commented Mar 31, 2017

k8s-ci-robot commented Mar 31, 2017

ncdc commented Mar 31, 2017

cezarsa commented Mar 31, 2017

grodrigues3 commented Apr 13, 2017

smarterclayton commented Apr 13, 2017

cezarsa commented Apr 13, 2017

ncdc commented Apr 17, 2017

ncdc commented Apr 17, 2017

cezarsa commented Apr 19, 2017

ncdc Apr 19, 2017

ncdc commented Apr 19, 2017

liggitt commented Apr 19, 2017

ncdc commented Apr 19, 2017

ncdc commented Apr 19, 2017

ncdc commented Apr 19, 2017

cezarsa commented Apr 19, 2017

liggitt commented Apr 19, 2017

ncdc commented Apr 19, 2017

cezarsa commented Apr 19, 2017

dsnet Apr 19, 2017 •

edited

Loading

cezarsa commented Apr 20, 2017

k8s-ci-robot commented Apr 20, 2017 •

edited

Loading

luxas commented Apr 26, 2017

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

ncdc Apr 28, 2017

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

k8s-github-robot commented Apr 28, 2017

k8s-github-robot commented Apr 28, 2017

prevent corrupted spdy stream after hijacking connection #43922

prevent corrupted spdy stream after hijacking connection #43922

Conversation

cezarsa commented Mar 31, 2017 • edited by ncdc Loading

k8s-reviewable commented Mar 31, 2017

k8s-ci-robot commented Mar 31, 2017

ncdc commented Mar 31, 2017

cezarsa commented Mar 31, 2017

grodrigues3 commented Apr 13, 2017

smarterclayton commented Apr 13, 2017

cezarsa commented Apr 13, 2017

ncdc commented Apr 17, 2017

ncdc commented Apr 17, 2017

cezarsa commented Apr 19, 2017

ncdc Apr 19, 2017

Choose a reason for hiding this comment

ncdc commented Apr 19, 2017

liggitt commented Apr 19, 2017

ncdc commented Apr 19, 2017

ncdc commented Apr 19, 2017

ncdc commented Apr 19, 2017

cezarsa commented Apr 19, 2017

liggitt commented Apr 19, 2017

ncdc commented Apr 19, 2017

cezarsa commented Apr 19, 2017

dsnet Apr 19, 2017 • edited Loading

Choose a reason for hiding this comment

cezarsa commented Apr 20, 2017

k8s-ci-robot commented Apr 20, 2017 • edited Loading

luxas commented Apr 26, 2017

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

ncdc Apr 28, 2017

Choose a reason for hiding this comment

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

ncdc commented Apr 28, 2017

k8s-github-robot commented Apr 28, 2017

k8s-github-robot commented Apr 28, 2017

cezarsa commented Mar 31, 2017 •

edited by ncdc

Loading

dsnet Apr 19, 2017 •

edited

Loading

k8s-ci-robot commented Apr 20, 2017 •

edited

Loading