Create memhttp package to debug flaky testcases #594

emcfarlane · 2023-09-18T13:28:55Z

Creates two internal packages: memhttp and memhttptest based on https://github.com/akshayjshah/memhttp . We use this for testing connect's services.

Changeshttptest.Server to use an in memory network. This makes testing more robust to ephemeral port issues under load. Two flaky test cases were now easily reproducible and fixed. Both occurred from races between starting the network request in a go routine and checking for a http2 stream and erroring if not. This can error on Send or Receive depending on how fast the request can complete.

On duplexHTTPCall I removed SetError to avoid overwriting the original response error. Now BlockUntilResponseReady returns an error from the response initialization.

See: golang/go#14200

Fixes:

TestServer/http1/*/*/cumsum_cancel_before_send: send can error on write message.
TestBidiRequiresHTTP2: send can io.EOF error on write, or succeed.
TestBidiOverHTTP1: same as above.
TestClientPeer/grpcweb: stream request sends an invalidate payload invoking server error, races with interceptor.

Two places where errors raced:

connect-go/duplex_http_call.go

Line 290 in 525cf76

d.SetError(errorf(
connect-go/handler.go

Line 184 in 525cf76

if isBidi && request.ProtoMajor < 2 {

Changes httptest.Server to use an in memory network. This makes testing more robust to ephemeral port issues under load. Two flaky test cases were now easily reproducible and fixed. Both occured from races between starting the network request in a go routine and checking for a http2 stream and erroring if not. This can error on Send or Receive depending on how fast the request can complete. See: golang/go#14200

emcfarlane · 2023-09-18T13:39:31Z

Running many iterations locally to find more, need to fix another one:

--- FAIL: TestClientPeer (0.00s)
    --- FAIL: TestClientPeer/grpcweb (0.01s)
        client_ext_test.go:111:
            assertion:  assert.Nil
            got:        unknown: io: read/write on closed pipe

jhump

Looking good so far to me. Are you planning to fix that other flake you found in this PR? Or do you want this PR approved now so you can merge it and fix the other issue in a subsequent PR?

connect_ext_test.go

emcfarlane · 2023-09-18T15:21:24Z

@jhump had to step out but hopefully can debug it now. Not sure what is calling close twice.

emcfarlane · 2023-09-18T16:04:57Z

I left it as a TODO. I think it's related to SetError but not sure how it rises. I have other branches to rejig the duplex_http_call which should make this easier to debug. Will fix later.

emcfarlane · 2023-09-18T16:31:17Z

Benchmarking increase in allocs, making the net.Pipe is ~8 and theres some more locking. Maybe better to use local network for bench.

- BenchmarkConnect/unary-8                    5433           1981280 ns/op         5651212 B/op        229 allocs/op
+ BenchmarkConnect/unary-8                    5440           1980366 ns/op         5729820 B/op        237 allocs/op

jhump

Maybe better to use local network for bench.

Yeah, I think so, too. The benchmark seems less useful if it's intentionally different from real world conditions 🤷

internal/memhttp/memhttptest/http.go

.golangci.yml

internal/memhttp/listener.go

internal/memhttp/memhttp.go

compression_test.go

.golangci.yml

internal/memhttp/option.go

Direction has changed a little since original review

internal/memhttp/internal/config.go

emcfarlane · 2023-10-13T17:00:17Z

=== CONT  TestBidiRequiresHTTP2
    connect_ext_test.go:786:
        assertion:      assert.Equal
        got:    unknown
        want:   unimplemented

Test is still flaky 😞, need to relook into this.

Two errors:

unknown: write envelope: EOF
unimplemented: response from http://1.2.3.4/connect.ping.v1.PingService/CumSum is HTTP/1.1: bidi streams require at least HTTP/2

Removes SetError in favour of reporting errors on BlockUntilResponseReady. ensureRequestMade removes sync.Once as the contract of ClientStream state calling Send with CloseRequest is not safe to call concurrently.

emcfarlane · 2023-10-22T20:07:32Z

@jhump behaviour in duplexHTTPCall has changed in the last 2 commits to address the flaky tests. I've removed SetError to avoid subsequent errors overwriting the original cause. Now BlockUntilResponseReady reports the error and Send is closed with io.EOF. ensureMakeRequest is no longer concurrent safe which is consistent with the interface contract for ClientStream that states Send or CloseRequest will race. Please re-review!

duplex_http_call.go

connect_ext_test.go

duplex_http_call.go

protocol_connect.go

jhump · 2023-10-23T15:09:45Z

client_ext_test.go

@@ -106,10 +106,8 @@ func TestClientPeer(t *testing.T) {
 		err = clientStream.Send(&pingv1.SumRequest{})
 		assert.Nil(t, err)
 		// server streaming
-		serverStream, err := client.CountUp(ctx, connect.NewRequest(&pingv1.CountUpRequest{}))
+		serverStream, err := client.CountUp(ctx, connect.NewRequest(&pingv1.CountUpRequest{Number: 1}))


Is this change relevant? Why would the request data make this flaky or not?

It causes the server to error with invalid_argument: number must be positive: got 0

Okay. But was that not true before? Why wasn't this a problem before this PR? (I'm trying to understand why change it now.)

The test is checking in the interceptor that the peer address and peer protocol is set. It's testing each request style by sending an empty but valid request, however server stream is the only one that will cause the server handler to error. This can now report the server error instead of success. I don't think this is intended behaviour of the test.

Not setting Number will cause the following only for grpcweb:

--- FAIL: TestClientPeer (0.00s) --- FAIL: TestClientPeer/grpcweb (0.07s) client_ext_test.go:112: assertion: assert.Nil got: unknown: http2: response body closed

Close to fail with http2: response body closed here

Errors on discard which usually receives an io.EOF

The grpcweb error response is a header only response, need to investigate why this error is returned on a no body.

Now flaky with:

client_ext_test.go:113: assertion: assert.Nil got: unknown: io: read/write on closed pipe

Discard is reading from a closed response which is causing an io.ErrClosedPipe. This is probably due to the new memhttp. Need to investigate.

Now flaky with:

By "now", do you mean after the last commit you pushed, which removed calls to response.Body.Close()?

Also, in that latest commit, who is the caller that is now responsible for calling Close? Is this done when StreamClientConn.CloseResponse() is called? Is there a chance some code path is failing to call that? (In particular, I'm suspicious why this would only happen for gRPC-Web and not others.)

Discard is reading from a closed response which is causing an io.ErrClosedPipe.

It seems like discard should be resilient against io.ErrClosedPipe and replace it with io.EOF when observed, no?

It's due to the change in closing the pipe writer on Reader instead of Writer. net.Pipe will close both halves but the error is given on the opposite end. So closing the Reader made the Writer return nice io.EOF errors but the Reader to receive io.ErrClosedPipe. HTTP2 libraries set the request error to the response here

I'll need to write more testing around closing, and create an issue for testing with different latencies.

HTTP2 sets the error on the response then here

Discard should never see io.ErrClosedPipe, however I've added context error checks to avoid issues with cancelation errors bubbling up to CloseResponse() errors. These are tested in TestServer tests.

Working and passing with -count=100 locally, can't see any more flaky test issues. Could you please re-review.

duplex_http_call.go

.golangci.yml

emcfarlane · 2023-10-25T20:12:56Z

duplex_http_call.go

-	if _, err := discard(d.response.Body); err != nil {
+	if _, err := discard(d.response.Body); err != nil &&
+		!errors.Is(err, context.Canceled) &&
+		!errors.Is(err, context.DeadlineExceeded) {


I've added these error checks to make CloseResponse behaviour more consistent. Otherwise Close does race with context cancel on errors causing either nil or a context error. Maybe we can revisit the discard behaviour in another PR.

connect_ext_test.go

jhump · 2023-10-25T20:34:45Z

duplex_http_call.go

@@ -257,15 +263,15 @@ func (d *duplexHTTPCall) makeRequest() {
 			err = NewError(CodeUnavailable, err)
 		}
 		d.responseErr = err
-		d.requestBodyReader.CloseWithError(io.EOF)
+		d.requestBodyWriter.Close()


Why is this changed? Since it was using CloseWithError and not simply Close, this would not be the source of io.ErrPipeClosed issues. In fact, I believe this will cause attempts to send on the broken stream to now return io.ErrPipeClosed instead of io.EOF.

In order to control the error received by the write half (senders), you must close the read half (which is what it was doing before), and vice versa.

Close is just calling CloseWithError(nil) which then gets set to io.EOF: https://cs.opensource.google/go/go/+/refs/tags/go1.21.3:src/io/pipe.go;l=100
It's always the opposite side of the pipe that gets the error with the current side getting: io.ErrClosedPipe.

SetError called close on read:

connect-go/duplex_http_call.go

Line 236 in d9b61e9

_ = d.requestBodyReader.Close()

Was my mistake switching to Writer, it's now fixed in the latest PR.

the current side getting: io.ErrClosedPipe
SetError called close on read:

Exactly. By closing the writer here, we will induce io.ErrClosedPipe in calls to send (which is what used the writer). The old behavior, closing the reader, is better since it results in EOF errors instead.

Was my mistake switching to Writer, it's now fixed in the latest PR.

I don't follow this. I'm looking at refreshed diff and it's still closing the writer.

Sorry, I confused myself and switched the ordering. My previous comments don't align.

Closing the write side makes Write on the pipe error with io.ErrClosedPipe. Connect checks for this when sending:

connect-go/duplex_http_call.go

Line 106 in d9b61e9

if err != nil && errors.Is(err, io.ErrClosedPipe) {

However, on the read side we need to return io.EOF to avoid HTTP2 setting the io.ErrClosedPipe as the error for the response body: #594 (comment)

CloseWrite behaviour was different to SetError:

connect-go/duplex_http_call.go

Line 133 in d9b61e9

return d.requestBodyWriter.Close()

connect-go/duplex_http_call.go

Line 236 in d9b61e9

_ = d.requestBodyReader.Close()

Got it. Thank you for explaining!

emcfarlane requested a review from akshayjshah September 18, 2023 13:28

Fix lint

1f1df5d

jhump reviewed Sep 18, 2023

View reviewed changes

connect_ext_test.go Outdated Show resolved Hide resolved

Add TODO for flaky test

225aa0d

emcfarlane requested a review from jhump September 18, 2023 16:32

emcfarlane self-assigned this Sep 18, 2023

jhump previously approved these changes Sep 18, 2023

View reviewed changes

emcfarlane and others added 3 commits September 18, 2023 23:28

Use local networking for benchmarks

27410bd

Merge branch 'main' into ed/memtest

facfa53

Create memhttp and memhttp test packages

877b4df

emcfarlane changed the title ~~Debug flaky testcases with in memory network~~ Create memhttp package to debug flaky testcases Oct 10, 2023

emcfarlane added 2 commits October 10, 2023 11:53

Fix race on RegisterShutdown

932533f

Fix transport desc

c057a62

jhump reviewed Oct 10, 2023

View reviewed changes

internal/memhttp/option.go Outdated Show resolved Hide resolved

internal/memhttp/option.go Outdated Show resolved Hide resolved

emcfarlane added 2 commits October 11, 2023 13:09

Fix feedback

f6a2bd7

Fix description

40594b7

emcfarlane requested a review from jhump October 11, 2023 12:15

Add Cleanup method test servers

b9fccc6

jhump approved these changes Oct 13, 2023

View reviewed changes

bufdev reviewed Oct 13, 2023

View reviewed changes

internal/memhttp/internal/config.go Outdated Show resolved Hide resolved

Revert moving options

dd98dd4

Ensure response errors are reported consistently

716794b

Removes SetError in favour of reporting errors on BlockUntilResponseReady. ensureRequestMade removes sync.Once as the contract of ClientStream state calling Send with CloseRequest is not safe to call concurrently.

Document BlockUntilResponseReady behaviour

ccd39d4

emcfarlane requested a review from jhump October 22, 2023 19:58

emcfarlane commented Oct 23, 2023

View reviewed changes

duplex_http_call.go Outdated Show resolved Hide resolved

emcfarlane commented Oct 23, 2023

View reviewed changes

duplex_http_call.go Outdated Show resolved Hide resolved

jhump reviewed Oct 23, 2023

View reviewed changes

emcfarlane added 3 commits October 23, 2023 11:18

Ensure CloseWrite is called

91afa1e

Feedback remove changes to duplexHTTPCall

ea743b3

Add comment to clarify behaviour

628915a

emcfarlane requested a review from jhump October 23, 2023 16:50

emcfarlane mentioned this pull request Oct 23, 2023

Special case unary HTTP calls #611

Closed

6 tasks

akshayjshah reviewed Oct 23, 2023

View reviewed changes

.golangci.yml Show resolved Hide resolved

emcfarlane added 5 commits October 23, 2023 14:47

Restrict log errors to New|Logger|Lshortfile

23dc2da

Document response close error handling

2ee0def

Fix and document Close behaviour for pipe

00d7f6a

Move responseBodyReady to group what it protects

758f889

Add CloseResponse checks in TestServer

fa4a554

emcfarlane commented Oct 25, 2023

View reviewed changes

jhump reviewed Oct 25, 2023

View reviewed changes

jhump approved these changes Oct 25, 2023

View reviewed changes

emcfarlane requested a review from akshayjshah October 27, 2023 18:13

emcfarlane mentioned this pull request Oct 31, 2023

Specialize the unary RPC flow internally #609

Closed

akshayjshah approved these changes Nov 1, 2023

View reviewed changes

Merge branch 'main' into ed/memtest

7b062d1

akshayjshah merged commit 41e8e3b into main Nov 1, 2023
7 checks passed

akshayjshah deleted the ed/memtest branch November 1, 2023 19:01

emcfarlane mentioned this pull request Nov 3, 2023

Test with variable network conditions #625

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Create memhttp package to debug flaky testcases #594

Create memhttp package to debug flaky testcases #594

emcfarlane commented Sep 18, 2023 •

edited

Loading

emcfarlane commented Sep 18, 2023

jhump left a comment

emcfarlane commented Sep 18, 2023

emcfarlane commented Sep 18, 2023

emcfarlane commented Sep 18, 2023

jhump left a comment

emcfarlane commented Oct 13, 2023 •

edited

Loading

emcfarlane commented Oct 22, 2023 •

edited

Loading

jhump Oct 23, 2023

emcfarlane Oct 23, 2023

jhump Oct 23, 2023

emcfarlane Oct 23, 2023

emcfarlane Oct 25, 2023

emcfarlane Oct 25, 2023

jhump Oct 25, 2023

emcfarlane Oct 25, 2023

emcfarlane Oct 25, 2023

emcfarlane Oct 25, 2023 •

edited

Loading

emcfarlane Oct 25, 2023

jhump Oct 25, 2023

emcfarlane Oct 25, 2023

emcfarlane Oct 25, 2023

jhump Oct 25, 2023 •

edited

Loading

emcfarlane Oct 25, 2023

emcfarlane Oct 25, 2023

jhump Oct 25, 2023

Create memhttp package to debug flaky testcases #594

Create memhttp package to debug flaky testcases #594

Conversation

emcfarlane commented Sep 18, 2023 • edited Loading

emcfarlane commented Sep 18, 2023

jhump left a comment

Choose a reason for hiding this comment

emcfarlane commented Sep 18, 2023

emcfarlane commented Sep 18, 2023

emcfarlane commented Sep 18, 2023

jhump left a comment

Choose a reason for hiding this comment

emcfarlane commented Oct 13, 2023 • edited Loading

emcfarlane commented Oct 22, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

emcfarlane Oct 25, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

jhump Oct 25, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

emcfarlane commented Sep 18, 2023 •

edited

Loading

emcfarlane commented Oct 13, 2023 •

edited

Loading

emcfarlane commented Oct 22, 2023 •

edited

Loading

emcfarlane Oct 25, 2023 •

edited

Loading

jhump Oct 25, 2023 •

edited

Loading