grpc-go icon indicating copy to clipboard operation
grpc-go copied to clipboard

Flaky test: Test/HTTPHeaderFrameErrorHandlingMoreThanTwoHeaders

Open menghanl opened this issue 3 years ago • 3 comments

https://github.com/grpc/grpc-go/runs/4476382916?check_suite_focus=true

2021/12/09 21:24:47 http: TLS handshake error from 127.0.0.1:60600: write tcp 127.0.0.1:41773->127.0.0.1:60600: use of closed network connection
2021/12/09 21:25:56 http: TLS handshake error from 127.0.0.1:49168: write tcp 127.0.0.1:43987->127.0.0.1:49168: use of closed network connection
2021/12/09 21:26:38 http: TLS handshake error from 127.0.0.1:45668: write tcp 127.0.0.1:46697->127.0.0.1:45668: use of closed network connection
2021/12/09 21:27:26 http: TLS handshake error from 127.0.0.1:58884: write tcp 127.0.0.1:35977->127.0.0.1:58884: use of closed network connection
2021/12/09 21:27:39 http: TLS handshake error from 127.0.0.1:45448: write tcp 127.0.0.1:42771->127.0.0.1:45448: use of closed network connection
--- FAIL: Test (85.00s)
    --- FAIL: Test/HTTPHeaderFrameErrorHandlingMoreThanTwoHeaders (0.05s)
        tlogger.go:116: INFO clientconn.go:175 [core] Channel Created  (t=+227.598µs)
        tlogger.go:116: INFO clientconn.go:1623 [core] original dial target is: "127.0.0.1:33353"  (t=+271.998µs)
        tlogger.go:116: INFO clientconn.go:1628 [core] dial target "127.0.0.1:33353" parse failed: parse "127.0.0.1:33353": first path segment in URL cannot contain colon  (t=+296.598µs)
        tlogger.go:116: INFO clientconn.go:1643 [core] fallback to scheme "passthrough"  (t=+315.798µs)
        tlogger.go:116: INFO clientconn.go:1651 [core] parsed dial target is: {Scheme:passthrough Authority: Endpoint:127.0.0.1:33353 URL:{Scheme:passthrough Opaque: User: Host: Path:/127.0.0.1:33353 RawPath: ForceQuery:false RawQuery: Fragment: RawFragment:}}  (t=+343.298µs)
        tlogger.go:116: INFO clientconn.go:262 [core] Channel authority set to "127.0.0.1:33353"  (t=+361.197µs)
        tlogger.go:116: INFO resolver_conn_wrapper.go:100 [core] ccResolverWrapper: sending update to cc: {[{127.0.0.1:33353  <nil> <nil> 0 <nil>}] <nil> <nil>}  (t=+383.597µs)
        tlogger.go:116: INFO resolver_conn_wrapper.go:183 [core] Resolver state updated: {Addresses:[{Addr:127.0.0.1:33353 ServerName: Attributes:<nil> BalancerAttributes:<nil> Type:0 Metadata:<nil>}] ServiceConfig:<nil> Attributes:<nil>} (resolver returned new addresses)  (t=+405.297µs)
        tlogger.go:116: INFO clientconn.go:712 [core] ClientConn switching balancer to "pick_first"  (t=+420.397µs)
        tlogger.go:116: INFO clientconn.go:732 [core] Channel switches to new LB policy "pick_first"  (t=+437.997µs)
        tlogger.go:116: INFO clientconn.go:773 [core] Subchannel Created  (t=+480.896µs)
        tlogger.go:116: INFO clientconn.go:773 [core] Subchannel(id:1224) created  (t=+493.796µs)
        tlogger.go:116: INFO picker_wrapper.go:161 [core] blockingPicker: the picked transport is not ready, loop back to repick  (t=+527.296µs)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to CONNECTING  (t=+549.396µs)
        tlogger.go:116: INFO clientconn.go:1254 [core] Subchannel picks a new address "127.0.0.1:33353" to connect  (t=+571.896µs)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to CONNECTING  (t=+973.793µs)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to READY  (t=+1.124492ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to READY  (t=+1.155391ms)
        tlogger.go:116: INFO clientconn.go:417 [core] Channel Connectivity change to SHUTDOWN  (t=+1.475389ms)
        tlogger.go:116: INFO clientconn.go:1143 [core] Subchannel Connectivity change to SHUTDOWN  (t=+1.496689ms)
        tlogger.go:116: INFO clientconn.go:1501 [core] Subchannel Deleted  (t=+1.510889ms)
        tlogger.go:116: INFO clientconn.go:1501 [core] Subchanel(id:1224) deleted  (t=+1.522489ms)
        tlogger.go:116: INFO clientconn.go:1099 [core] Channel Deleted  (t=+1.535888ms)
        tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 1224 from a parent (id=1223) that doesn't currently exist  (t=+4.384067ms)
        tlogger.go:116: INFO types.go:68 [channelz] attempt to delete child with id 1224 from a parent (id=1223) that doesn't currently exist  (t=+4.422666ms)
        end2end_test.go:7418: Error at server-side while reading frame. Err: read tcp 127.0.0.1:33353->127.0.0.1:47896: read: connection reset by peer
FAIL

menghanl avatar Dec 09 '21 21:12 menghanl

One more: https://github.com/grpc/grpc-go/runs/4538453130?check_suite_focus=true

easwars avatar Dec 15 '21 23:12 easwars

Not flaking of late.

easwars avatar May 16 '22 22:05 easwars

https://github.com/grpc/grpc-go/runs/7638640797?check_suite_focus=true

easwars avatar Aug 02 '22 19:08 easwars

https://github.com/grpc/grpc-go/actions/runs/3276440555/jobs/5392494447

easwars avatar Oct 18 '22 22:10 easwars

Fails 2/10k on google3

dfawley avatar Nov 28 '22 18:11 dfawley

The underlying issue seems to be the same as the one causing Test/HTTPHeaderFrameErrorHandlingNormalTrailer

arvindbr8 avatar Nov 30 '22 18:11 arvindbr8

Sounds good; let's close this one then.

dfawley avatar Nov 30 '22 18:11 dfawley