TcpProxy: downstream connection gets terminated in the middle of TLS handshake when upstream is down #2800
Description
Description:
Downstream connection gets terminated in the middle of TLS handshake (usually while waiting for NewSessionTicket message, but that might be just because of timing) when TCP proxying to an upstream that's down.
Repro steps:
$ bssl client -connect 127.0.0.1:10000 -debug
Connecting to 127.0.0.1:10000
Handshake started.
Handshake progress: TLS client enter_early_data
Handshake progress: TLS client read_server_hello
Handshake progress: TLS client read_server_certificate
Handshake progress: TLS client read_certificate_status
Handshake progress: TLS client verify_server_certificate
Handshake progress: TLS client read_server_key_exchange
Handshake progress: TLS client read_certificate_request
Handshake progress: TLS client read_server_hello_done
Handshake progress: TLS client send_client_certificate
Handshake progress: TLS client send_client_key_exchange
Handshake progress: TLS client send_client_certificate_verify
Handshake progress: TLS client send_client_finished
Handshake progress: TLS client finish_flight
Handshake progress: TLS client read_session_ticket
Error while connecting: 5
Config:
admin:
access_log_path: /tmp/admin_access.log
address:
socket_address: { address: 0.0.0.0, port_value: 10001 }
static_resources:
listeners:
- address:
socket_address: { address: 0.0.0.0, port_value: 10000 }
filter_chains:
- tls_context:
common_tls_context:
tls_certificates:
- certificate_chain: { inline_string: "-----BEGIN CERTIFICATE-----\nMIIDGjCCAoOgAwIBAgIJALE/9j8tvBGNMA0GCSqGSIb3DQEBCwUAMIGDMQswCQYD\nVQQGEwJVUzETMBEGA1UECAwKQ2FsaWZvcm5pYTEWMBQGA1UEBwwNU2FuIEZyYW5j\naXNjbzENMAsGA1UECgwETHlmdDEZMBcGA1UECwwQTHlmdCBFbmdpbmVlcmluZzEd\nMBsGA1UEAwwUVGVzdCBJbnRlcm1lZGlhdGUgQ0EwHhcNMTgwMTE1MjI0MDI3WhcN\nMjAwMTE1MjI0MDI3WjB6MQswCQYDVQQGEwJVUzETMBEGA1UECAwKQ2FsaWZvcm5p\nYTEWMBQGA1UEBwwNU2FuIEZyYW5jaXNjbzENMAsGA1UECgwETHlmdDEZMBcGA1UE\nCwwQTHlmdCBFbmdpbmVlcmluZzEUMBIGA1UEAwwLVGVzdCBTZXJ2ZXIwgZ8wDQYJ\nKoZIhvcNAQEBBQADgY0AMIGJAoGBALGG70n/nfIB64LH6jraqxpJ3EUO+gL/KkHG\n4+/hQMMZpehPdcHa7vj1efBgaaddtjRZ3GLSSF968O19EbMwjQl1Azwn3Ql8SddQ\nhyW30/Q/jgY54MnDBGgb5xhb7tdfjGvZ+lKapu9FypTcrre/wXSwBSsmm2me0CCN\nAZKddyMzAgMBAAGjgZ0wgZowDAYDVR0TAQH/BAIwADALBgNVHQ8EBAMCBeAwHQYD\nVR0lBBYwFAYIKwYBBQUHAwIGCCsGAQUFBwMBMB4GA1UdEQQXMBWCE3NlcnZlcjEu\nZXhhbXBsZS5jb20wHQYDVR0OBBYEFBZcRXhGXlFghYQ9/R6yF7XTHzkxMB8GA1Ud\nIwQYMBaAFIuDOLnI5iZPpH230VFAuWeNYuWdMA0GCSqGSIb3DQEBCwUAA4GBAFZg\n6ZznS3KuEus6ZJsLJH7J0BMKmpdj5hM0M++TBnP8LVy73ETc95Y2sxvB/B2c7f2v\nwjz4nGd5O3kkiVlMrQ44GPUKrO3/Ltix+MT3ixuF7Z7vLFKwkIG2d0RXJVVb1MOM\nw1bmtABHf8sVAFF6RZtjshWSaZYvIhiG1FedV4Vw\n-----END CERTIFICATE-----\n-----BEGIN CERTIFICATE-----\nMIIC3jCCAkegAwIBAgIJAJvUixVO/5pTMA0GCSqGSIb3DQEBCwUAMHYxCzAJBgNV\nBAYTAlVTMRMwEQYDVQQIEwpDYWxpZm9ybmlhMRYwFAYDVQQHEw1TYW4gRnJhbmNp\nc2NvMQ0wCwYDVQQKEwRMeWZ0MRkwFwYDVQQLExBMeWZ0IEVuZ2luZWVyaW5nMRAw\nDgYDVQQDEwdUZXN0IENBMB4XDTE4MDExNTIyNDAyN1oXDTI4MDExMzIyNDAyN1ow\ngYMxCzAJBgNVBAYTAlVTMRMwEQYDVQQIDApDYWxpZm9ybmlhMRYwFAYDVQQHDA1T\nYW4gRnJhbmNpc2NvMQ0wCwYDVQQKDARMeWZ0MRkwFwYDVQQLDBBMeWZ0IEVuZ2lu\nZWVyaW5nMR0wGwYDVQQDDBRUZXN0IEludGVybWVkaWF0ZSBDQTCBnzANBgkqhkiG\n9w0BAQEFAAOBjQAwgYkCgYEAxd1kOhV+/2n+rJWKvrtkyyqkWgBXXhH15G9cusaR\nzJtwxsvtPRYZ9nTc+A6GDFgZ0TS1sq/WJXfs3guMpFObXU+tSlezxHVRpWPTXKff\nhblqtZMPKW5q5LmOHxKi8GUxwDnEeAiZmzstGCYkRKn+GmLYe26vFGBw4MvM89Vm\necMCAwEAAaNmMGQwEgYDVR0TAQH/BAgwBgEB/wIBADAOBgNVHQ8BAf8EBAMCAQYw\nHQYDVR0OBBYEFIuDOLnI5iZPpH230VFAuWeNYuWdMB8GA1UdIwQYMBaAFDt4pFFP\nFoSTHEgoegytK5ZByn15MA0GCSqGSIb3DQEBCwUAA4GBAGO77sBFzn63pM2Oy4XS\n+FEcFj/lB4vBh4r8jtzdf5EMaKUeXY9i57MTryPTJZRFXW6BuQ/B3hiOW2fwkCdL\neHd0MwGv95cn1PCWZh1IidVrtrDeu0oLxhRk5mcflaaLBuGADUD3Y1ms2sl90Ean\n6C+0EHH2O6Emesx9IhPZRx4H\n-----END CERTIFICATE-----" }
private_key: { inline_string: "-----BEGIN RSA PRIVATE KEY-----\nMIICXgIBAAKBgQCxhu9J/53yAeuCx+o62qsaSdxFDvoC/ypBxuPv4UDDGaXoT3XB\n2u749XnwYGmnXbY0Wdxi0khfevDtfRGzMI0JdQM8J90JfEnXUIclt9P0P44GOeDJ\nwwRoG+cYW+7XX4xr2fpSmqbvRcqU3K63v8F0sAUrJptpntAgjQGSnXcjMwIDAQAB\nAoGAJk4kQcZLEVYCuDRkwRA/zStUwP3rSkw+lPTSaAcljzNwjgDfOtX/rG5jQk+7\nXGanEwK0wAn5nciMReIvuIdoVt7zEtFygZ7D3yKh+Ywu0AYC8TaiszAaL0efMnAW\nMtpgyrAoMB4bFON3oyNVZM161+cdrU0PrEDqh+GHl8abpokCQQDfn2jE3WmS/a36\n2Dt/e3yjNE/4xDshAcHkNmF+jpcB66bls5ZU5Yv07RUVExQ30fw3v+ADMxmNYg2f\nqpAF2getAkEAyzr9GwgdKeruErwlLhMOG327zTcZlHZXU5Q378/S3bKi3c/voGCb\nexKjxRBZTzSw5hfrOzbCEpMLcwZaoBiyXwJBAJAH2XAq98vQDpXpXfEPNUjc8cFV\niowI2LxHdmYQKxz2jemW0PXfX1Siuxh20GffnOa/c+Y7rHKOvB2hut+5/YUCQQCF\nnBx2vxjdTBSEwKj455IoxLrJKeZpUnwK+LDluo35Ls4gYeo6WAkgGpsMnbj5d7yt\nKSB/Z3qj14R5dL3z7wilAkEAp78JPrvWP5zc3YOmmr9s8IQ3almspwnlh1mdcgoX\n4rHe3U4jRZwE6fw8W9G4QsFRlez1Re6g8T7yoFXiZETGqQ==\n-----END RSA PRIVATE KEY-----" }
filters:
- name: envoy.tcp_proxy
config:
stat_prefix: tcp_proxy
cluster: cluster_down
clusters:
- name: cluster_down
connect_timeout: 0.25s
type: STATIC
lb_policy: ROUND_ROBIN
hosts: [{ socket_address: { address: 127.0.0.1, port_value: 65001 }}]
Logs:
[debug][main] source/server/connection_handler_impl.cc:195] [C1] new connection
[debug][filter] source/common/filter/tcp_proxy.cc:171] [C1] new tcp proxy session
[trace][connection] source/common/network/connection_impl.cc:229] [C1] readDisable: enabled=true disable=true
[debug][filter] source/common/filter/tcp_proxy.cc:310] [C1] Creating connection to cluster cluster_down
[debug][connection] source/common/network/connection_impl.cc:568] [C2] connecting to 127.0.0.1:65001
[debug][connection] source/common/network/connection_impl.cc:577] [C2] connection in progress
[trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=1)
[trace][connection] source/common/network/connection_impl.cc:386] [C1] socket event: 2
[trace][connection] source/common/network/connection_impl.cc:454] [C1] write ready
[debug][connection] source/common/ssl/ssl_socket.cc:110] [C1] handshake error: 2
[trace][connection] source/common/network/connection_impl.cc:386] [C2] socket event: 3
[trace][connection] source/common/network/connection_impl.cc:454] [C2] write ready
[debug][connection] source/common/network/connection_impl.cc:473] [C2] delayed connection error: 111
[debug][connection] source/common/network/connection_impl.cc:134] [C2] closing socket: 0
[trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=1)
[debug][filter] source/common/filter/tcp_proxy.cc:310] [C1] Creating connection to cluster cluster_down
[debug][connection] source/common/network/connection_impl.cc:99] [C1] closing data_to_write=0 type=1
[debug][connection] source/common/network/connection_impl.cc:134] [C1] closing socket: 1
[debug][main] source/server/connection_handler_impl.cc:54] [C1] adding to cleanup list
[trace][main] source/common/event/dispatcher_impl.cc:126] item added to deferred deletion list (size=2)
[trace][main] source/common/event/dispatcher_impl.cc:52] clearing deferred deletion list (size=2)
[debug][main] source/server/server.cc:130] flushing stats