transport: authentication handshake failed: tls: first record does not look like a TLS handshake

[dfawley]

This appeared in a flake of Test/ConcurrentServerStopAndGoAway in test/, but I believe there could be a real issue here. We've also seen the same thing in some integration tests we run internally. b/309025702

It seems like a server-side issue as the integration tests failed running Java & C++. And the client in the test below tried to connect multiple times and failed:

        goaway_test.go:474: Running test in tcp-tls-v1-balancer environment...
        tlogger.go:116: INFO server.go:667 [core] [Server #784] Server created  (t=+155.737106ms)
        tlogger.go:116: INFO server.go:864 [core] [Server #784 ListenSocket #785] ListenSocket created  (t=+155.809662ms)
        tlogger.go:116: INFO clientconn.go:310 [core] [Channel #786] Channel created  (t=+155.89873ms)
        tlogger.go:116: INFO clientconn.go:1734 [core] [Channel #786] original dial target is: "passthrough:///localhost:37771"  (t=+155.916273ms)
        tlogger.go:116: INFO clientconn.go:1741 [core] [Channel #786] parsed dial target is: resolver.Target{URL:url.URL{Scheme:"passthrough", Opaque:"", User:(*url.Userinfo)(nil), Host:"", Path:"/localhost:37771", RawPath:"", OmitHost:false, ForceQuery:false, RawQuery:"", Fragment:"", RawFragment:""}}  (t=+155.941972ms)
        tlogger.go:116: INFO clientconn.go:1896 [core] [Channel #786] Channel authority set to "x.test.example.com"  (t=+155.959204ms)
        tlogger.go:116: INFO resolver_wrapper.go:190 [core] [Channel #786] Resolver state updated: {
              "Addresses": [
                {
                  "Addr": "localhost:37771",
                  "ServerName": "",
                  "Attributes": null,
                  "BalancerAttributes": null,
                  "Metadata": null
                }
              ],
              "Endpoints": [
                {
                  "Addresses": [
                    {
                      "Addr": "localhost:37771",
                      "ServerName": "",
                      "Attributes": null,
                      "BalancerAttributes": null,
                      "Metadata": null
                    }
                  ],
                  "Attributes": null
                }
              ],
              "ServiceConfig": null,
              "Attributes": null
            } (resolver returned new addresses)  (t=+156.034706ms)
        tlogger.go:116: INFO balancer_wrapper.go:174 [core] [Channel #786] Channel switches to new LB policy "pick_first"  (t=+156.06864ms)
        tlogger.go:116: INFO clientconn.go:858 [core] [Channel #786 SubChannel #787] Subchannel created  (t=+156.10029ms)
        tlogger.go:116: INFO clientconn.go:537 [core] [Channel #786] Channel Connectivity change to CONNECTING  (t=+156.11632ms)
        tlogger.go:116: INFO clientconn.go:310 [core] [Channel #786] Channel exiting idle mode  (t=+156.134174ms)
        tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to CONNECTING  (t=+156.160303ms)
        tlogger.go:116: INFO clientconn.go:1348 [core] [Channel #786 SubChannel #787] Subchannel picks a new address "localhost:37771" to connect  (t=+156.194618ms)
        tlogger.go:116: WARNING clientconn.go:1410 [core] [Channel #786 SubChannel #787] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37771", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+156.955221ms)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+156.987251ms)
        tlogger.go:116: INFO clientconn.go:537 [core] [Channel #786] Channel Connectivity change to TRANSIENT_FAILURE  (t=+157.008241ms)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+1.158038514s)
        tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to CONNECTING  (t=+1.15810512s)
        tlogger.go:116: INFO clientconn.go:1348 [core] [Channel #786 SubChannel #787] Subchannel picks a new address "localhost:37771" to connect  (t=+1.158143792s)
        tlogger.go:116: WARNING clientconn.go:1410 [core] [Channel #786 SubChannel #787] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37771", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+1.158889457s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+1.158924323s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+2.493856573s)
        tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to CONNECTING  (t=+2.493911246s)
        tlogger.go:116: INFO clientconn.go:1348 [core] [Channel #786 SubChannel #787] Subchannel picks a new address "localhost:37771" to connect  (t=+2.493939259s)
        tlogger.go:116: WARNING clientconn.go:1410 [core] [Channel #786 SubChannel #787] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37771", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+2.494577462s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+2.494643356s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+5.312581891s)
        tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to CONNECTING  (t=+5.312663174s)
        tlogger.go:116: INFO clientconn.go:1348 [core] [Channel #786 SubChannel #787] Subchannel picks a new address "localhost:37771" to connect  (t=+5.31270872s)
        tlogger.go:116: WARNING clientconn.go:1410 [core] [Channel #786 SubChannel #787] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37771", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+5.313682154s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+5.313726117s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+9.577537518s)
        tlogger.go:116: INFO clientconn.go:1233 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to CONNECTING  (t=+9.57759687s)
        tlogger.go:116: INFO clientconn.go:1348 [core] [Channel #786 SubChannel #787] Subchannel picks a new address "localhost:37771" to connect  (t=+9.577632517s)
        tlogger.go:116: WARNING clientconn.go:1410 [core] [Channel #786 SubChannel #787] grpc: addrConn.createTransport failed to connect to {Addr: "localhost:37771", ServerName: "x.test.example.com", }. Err: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+9.578357062s)
        tlogger.go:116: INFO clientconn.go:1235 [core] [Channel #786 SubChannel #787] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: authentication handshake failed: tls: first record does not look like a TLS handshake"  (t=+9.578388972s)