Flaky test [1/100K]: RingHash_RequestHashKeyConnecting

[arjan-bal]

Sample run: https://github.com/grpc/grpc-go/actions/runs/23824485278/job/69444264954?pr=9028

Logs

--- FAIL: Test (12.69s)
    --- FAIL: Test/RingHash_RequestHashKeyConnecting (0.03s)
        tlogger.go:133: INFO server.go:721 [core] [Server #1020] Server created  (t=+373.099µs)
        stubserver.go:300: Started test service backend at "127.0.0.1:46755"
        tlogger.go:133: INFO server.go:917 [core] [Server #1020 ListenSocket #1021] ListenSocket created  (t=+735.461µs)
        tlogger.go:133: INFO server.go:721 [core] [Server #1022] Server created  (t=+1.87052ms)
        stubserver.go:300: Started test service backend at "127.0.0.1:37619"
        tlogger.go:133: INFO server.go:917 [core] [Server #1022 ListenSocket #1023] ListenSocket created  (t=+2.058916ms)
        tlogger.go:133: INFO server.go:721 [core] [Server #1024] Server created  (t=+2.280484ms)
        stubserver.go:300: Started test service backend at "127.0.0.1:39433"
        tlogger.go:133: INFO server.go:917 [core] [Server #1024 ListenSocket #1025] ListenSocket created  (t=+2.437447ms)
        tlogger.go:133: INFO server.go:721 [core] [Server #1026] Server created  (t=+2.535765ms)
        stubserver.go:300: Started test service backend at "127.0.0.1:41763"
        tlogger.go:133: INFO server.go:917 [core] [Server #1026 ListenSocket #1027] ListenSocket created  (t=+2.720402ms)
        tlogger.go:133: INFO server.go:721 [core] [Server #1028] Server created  (t=+2.795197ms)
        stubserver.go:300: Started test service backend at "127.0.0.1:40371"
        tlogger.go:133: INFO clientconn.go:620 [core] [Channel #1058] Channel Connectivity change to IDLE  (t=+10.147347ms)
        tlogger.go:133: INFO clientconn.go:421 [core] [Channel #1058] Channel exiting idle mode  (t=+10.241862ms)
        tlogger.go:133: INFO clientconn.go:620 [core] [Channel #1058] Channel Connectivity change to CONNECTING  (t=+10.670986ms)
        tlogger.go:133: INFO clientconn.go:923 [core] [Channel #1058 SubChannel #1061] Subchannel created  (t=+10.758964ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1061] Subchannel Connectivity change to CONNECTING  (t=+10.847516ms)
        tlogger.go:133: INFO clientconn.go:1471 [core] [Channel #1058 SubChannel #1061] Subchannel picks a new address "127.0.0.1:45565" to connect  (t=+10.909252ms)
        tlogger.go:133: INFO blocking_context_dialer.go:62 [testutils] Hold 0xc0006b30b0: Intercepted connection attempt to addr "127.0.0.1:45565"  (t=+10.981852ms)
        tlogger.go:133: INFO blocking_context_dialer.go:118 [testutils] Hold 0xc0006b30b0: Resuming connection attempt to addr "127.0.0.1:45565"  (t=+22.009067ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1061] Subchannel Connectivity change to READY  (t=+22.514345ms)
        tlogger.go:133: INFO clientconn.go:620 [core] [Channel #1058] Channel Connectivity change to READY  (t=+22.840724ms)
        tlogger.go:133: INFO clientconn.go:923 [core] [Channel #1058 SubChannel #1064] Subchannel created  (t=+23.341745ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1064] Subchannel Connectivity change to CONNECTING  (t=+23.649ms)
        tlogger.go:133: INFO clientconn.go:1471 [core] [Channel #1058 SubChannel #1064] Subchannel picks a new address "127.0.0.1:42291" to connect  (t=+23.754852ms)
        tlogger.go:133: INFO blocking_context_dialer.go:62 [testutils] Hold 0xc0006b31a0: Intercepted connection attempt to addr "127.0.0.1:42291"  (t=+23.8487ms)
        tlogger.go:133: INFO blocking_context_dialer.go:118 [testutils] Hold 0xc0006b31a0: Resuming connection attempt to addr "127.0.0.1:42291"  (t=+23.979305ms)
        ringhash_e2e_test.go:2915: Got 2 connection attempts, want at most 1
        tlogger.go:133: INFO clientconn.go:620 [core] [Channel #1058] Channel Connectivity change to SHUTDOWN  (t=+24.097843ms)
        tlogger.go:133: INFO resolver_wrapper.go:112 [core] [Channel #1058] Closing the name resolver  (t=+24.155719ms)
        tlogger.go:133: INFO balancer_wrapper.go:159 [core] [Channel #1058] ccBalancerWrapper: closing  (t=+24.240467ms)
        tlogger.go:133: INFO ringhash.go:310 [xds] [ring-hash-lb 0xc000969860] Shutdown  (t=+24.334917ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1064] Subchannel Connectivity change to READY  (t=+25.409739ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1061] Subchannel Connectivity change to SHUTDOWN  (t=+26.522911ms)
        tlogger.go:133: INFO clientconn.go:1710 [core] [Channel #1058 SubChannel #1061] Subchannel deleted  (t=+26.575544ms)
        tlogger.go:133: INFO clientconn.go:1303 [core] [Channel #1058 SubChannel #1064] Subchannel Connectivity change to SHUTDOWN  (t=+26.659834ms)
        tlogger.go:133: INFO clientconn.go:1710 [core] [Channel #1058 SubChannel #1064] Subchannel deleted  (t=+26.758263ms)
        tlogger.go:133: INFO clientconn.go:1232 [core] [Channel #1058] Channel deleted  (t=+26.97007ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1057 ListenSocket #1060] ListenSocket deleted  (t=+27.103018ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1056 ListenSocket #1059] ListenSocket deleted  (t=+27.185308ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1054 ListenSocket #1055] ListenSocket deleted  (t=+27.261401ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1052 ListenSocket #1053] ListenSocket deleted  (t=+27.33658ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1050 ListenSocket #1051] ListenSocket deleted  (t=+27.417117ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1047 ListenSocket #1049] ListenSocket deleted  (t=+27.477283ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1046 ListenSocket #1048] ListenSocket deleted  (t=+27.558324ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1044 ListenSocket #1045] ListenSocket deleted  (t=+27.644543ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1042 ListenSocket #1043] ListenSocket deleted  (t=+27.726304ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1040 ListenSocket #1041] ListenSocket deleted  (t=+27.804374ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1038 ListenSocket #1039] ListenSocket deleted  (t=+27.897438ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1036 ListenSocket #1037] ListenSocket deleted  (t=+27.984779ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1033 ListenSocket #1035] ListenSocket deleted  (t=+28.068088ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1032 ListenSocket #1034] ListenSocket deleted  (t=+28.159882ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1030 ListenSocket #1031] ListenSocket deleted  (t=+28.243839ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1028 ListenSocket #1029] ListenSocket deleted  (t=+28.328003ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1026 ListenSocket #1027] ListenSocket deleted  (t=+28.435991ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1024 ListenSocket #1025] ListenSocket deleted  (t=+28.580458ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1022 ListenSocket #1023] ListenSocket deleted  (t=+28.672484ms)
        tlogger.go:133: INFO server.go:853 [core] [Server #1020 ListenSocket #1021] ListenSocket deleted  (t=+28.73629ms)

[easwars]

100K run: https://fusion2.corp.google.com/invocations/d0a9488c-2182-4921-b1be-b37e728e5354/targets

[easwars]

Wasn't able to get to the root of the flake, but it does seem like some kind of race between the second RPC being made in a goroutine: https://github.com/grpc/grpc-go/blob/master/balancer/ringhash/ringhash_e2e_test.go#L2887-L2896

and the the main test goroutine ensuring that there is only one connection attempt made here: https://github.com/grpc/grpc-go/blob/master/balancer/ringhash/ringhash_e2e_test.go#L2901-L2913

[easwars]

https://github.com/grpc/grpc-go/actions/runs/24109613067/job/70340993275?pr=9049