Uploaded image for project: 'Maistra'
  1. Maistra
  2. MAISTRA-1287

503 responses due to sidecar closing connection

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Obsolete
    • Icon: Major Major
    • maistra-1.1.8
    • maistra-1.0.8, maistra-1.0.9
    • envoy
    • None

      Using very simple service mesh setup, running highly concurrent load I can see a fraction of requests returning status 503 for no apparent reason. While the number of failed requests is < 1% I found that the need to reopen connections substantially affects overall throughput.

      I have created similar setup using the proxyv2-rhel8:1.0.8 image but running the envoy manually with a custom configuration (note: I've tested with 1.0.9 with the same result). It seems that this issue is triggered by the presence of TLS inspector listener in Envoy configuration on the sidecar side; as my setup did not have to do routing based on SNI I could omit it and the errors went away.

      It seems that in fraction of cases the sidecar determines that the gateway - sidecar connection has been closed and therefore closes the socket on its side, rather than returning the response from application. When the gateway finds out the connection has been closed it returns 503 response. Please see logs below to support this observation:

      Gateway log:

      [2020-03-18 16:55:46.769][49][debug][client] [external/envoy/source/common/http/codec_client.cc:26] [C1113] connecting
[2020-03-18 16:55:46.769][49][debug][connection] [external/envoy/source/common/network/connection_impl.cc:681] [C1113] connecting to 172.30.131.123:9443
[2020-03-18 16:55:46.769][49][debug][connection] [external/envoy/source/common/network/connection_impl.cc:690] [C1113] connection in progress
[2020-03-18 16:55:46.769][49][debug][pool] [external/envoy/source/common/http/conn_pool_base.cc:20] queueing request due to no available connections
[2020-03-18 16:55:46.769][49][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:850] [C8][S5395068215166477669] decode headers called: filter=0x55629c8738b0 status=1
[2020-03-18 16:55:46.769][49][trace][http2] [external/envoy/source/common/http/http2/codec_impl.cc:381] [C8] dispatched 116 bytes
[2020-03-18 16:55:46.769][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C1113] socket event: 2
[2020-03-18 16:55:46.769][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.769][49][debug][connection] [external/envoy/source/common/network/connection_impl.cc:529] [C1113] connected
[2020-03-18 16:55:46.769][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C1113] handshake error: 2
[2020-03-18 16:55:46.773][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C1113] socket event: 3
[2020-03-18 16:55:46.773][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.774][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C1113] handshake error: 2
[2020-03-18 16:55:46.774][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C1113] read ready
[2020-03-18 16:55:46.774][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C1113] handshake error: 2
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C1113] socket event: 3
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.775][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:132] [C1113] handshake complete
[2020-03-18 16:55:46.775][49][debug][client] [external/envoy/source/common/http/codec_client.cc:64] [C1113] connected
[2020-03-18 16:55:46.775][49][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:276] [C1113] attaching to next request
[2020-03-18 16:55:46.775][49][debug][router] [external/envoy/source/common/router/router.cc:1170] [C8][S5395068215166477669] pool ready
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:386] [C1113] writing 324 bytes, end_stream false
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:210] [C1113] ssl write returns: 324
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C1113] read ready
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:90] [C1113] ssl read returns: -1
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C1113] socket event: 2
[2020-03-18 16:55:46.775][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.780][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C1113] socket event: 3
[2020-03-18 16:55:46.780][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C1113] write ready
[2020-03-18 16:55:46.780][49][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C1113] read ready
[2020-03-18 16:55:46.780][49][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:90] [C1113] ssl read returns: 0
[2020-03-18 16:55:46.781][49][debug][connection] [external/envoy/source/common/network/connection_impl.cc:514] [C1113] remote close
[2020-03-18 16:55:46.781][49][debug][connection] [external/envoy/source/common/network/connection_impl.cc:192] [C1113] closing socket: 0
[2020-03-18 16:55:46.781][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:247] [C1113] SSL shutdown: rc=1
[2020-03-18 16:55:46.782][49][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C1113]
[2020-03-18 16:55:46.782][49][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:371] [C1113] parsing 0 bytes
[2020-03-18 16:55:46.782][49][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:392] [C1113] parsed 0 bytes
[2020-03-18 16:55:46.782][49][debug][client] [external/envoy/source/common/http/codec_client.cc:82] [C1113] disconnect. resetting 1 pending requests
[2020-03-18 16:55:46.782][49][debug][client] [external/envoy/source/common/http/codec_client.cc:105] [C1113] request reset
[2020-03-18 16:55:46.782][49][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=1)
[2020-03-18 16:55:46.782][49][debug][router] [external/envoy/source/common/router/router.cc:644] [C8][S5395068215166477669] upstream reset: reset reason connection termination

      Sidecar log (the request is handled on C2698 but I don't know what connection the tls inspector logs belong to): 

      [2020-03-18 16:55:46.770][25][debug][main] [external/envoy/source/server/connection_handler_impl.cc:257] [C2698] new connection
[2020-03-18 16:55:46.770][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=1)
[2020-03-18 16:55:46.770][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:53] clearing deferred deletion list (size=1)
[2020-03-18 16:55:46.770][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C2698] socket event: 3
[2020-03-18 16:55:46.770][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C2698] write ready
[2020-03-18 16:55:46.773][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C2698] handshake error: 2
[2020-03-18 16:55:46.773][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C2698] read ready
[2020-03-18 16:55:46.773][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C2698] handshake error: 2
[2020-03-18 16:55:46.774][25][debug][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:85] tls inspector: new connection accepted
[2020-03-18 16:55:46.774][25][debug][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:85] tls inspector: new connection accepted
[2020-03-18 16:55:46.774][25][trace][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:154] tls inspector: recv: 211
[2020-03-18 16:55:46.774][25][trace][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:175] tls inspector: done: true
[2020-03-18 16:55:46.774][25][debug][main] [external/envoy/source/server/connection_handler_impl.cc:257] [C2701] new connection
[2020-03-18 16:55:46.774][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=1)
[2020-03-18 16:55:46.774][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:53] clearing deferred deletion list (size=1)
[2020-03-18 16:55:46.774][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C2698] socket event: 3
[2020-03-18 16:55:46.774][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C2698] write ready
[2020-03-18 16:55:46.775][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:132] [C2698] handshake complete
[2020-03-18 16:55:46.775][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C2698] read ready
[2020-03-18 16:55:46.775][25][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:90] [C2698] ssl read returns: -1
[2020-03-18 16:55:46.775][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C2701] socket event: 3
[2020-03-18 16:55:46.775][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C2701] write ready
[2020-03-18 16:55:46.777][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C2701] handshake error: 2
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C2701] read ready
[2020-03-18 16:55:46.777][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:143] [C2701] handshake error: 2
[2020-03-18 16:55:46.777][25][trace][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:154] tls inspector: recv: 211
[2020-03-18 16:55:46.777][25][trace][filter] [external/envoy/source/extensions/filters/listener/tls_inspector/tls_inspector.cc:175] tls inspector: done: true
[2020-03-18 16:55:46.777][25][debug][main] [external/envoy/source/server/connection_handler_impl.cc:257] [C2705] new connection
[2020-03-18 16:55:46.777][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=1)
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:452] [C2698] socket event: 3
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:520] [C2698] write ready
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:490] [C2698] read ready
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:90] [C2698] ssl read returns: 324
[2020-03-18 16:55:46.777][25][trace][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:90] [C2698] ssl read returns: -1
[2020-03-18 16:55:46.777][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C2698] TLS error: 337092985:SSL routines:tls_post_process_client_hello:cert cb error 537350270:BIO routines:mem_write:write to read only BIO
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:371] [C2698] parsing 324 bytes
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:516] [C2698] message begin
[2020-03-18 16:55:46.777][25][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:247] [C2698] new stream
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=host value=app.mesh.apps.cloud.scalelab:443
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-variant value=stable
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=user-agent value=#2502@agent-0117-f03-h26
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-forwarded-for value=172.16.0.13
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-forwarded-proto value=https
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-envoy-internal value=true
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-request-id value=95a30a66-564c-400b-926b-de29221144ae
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=x-envoy-expected-rq-timeout-ms value=15000
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:456] [C2698] headers complete
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:333] [C2698] completed header: key=content-length value=0
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:503] [C2698] message complete
[2020-03-18 16:55:46.777][25][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:611] [C2698][S18274153557130304839] request headers complete (end_stream=true):
[2020-03-18 16:55:46.777][25][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1079] [C2698][S18274153557130304839] request end stream
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:850] [C2698][S18274153557130304839] decode headers called: filter=0x5654dacf93b0 status=0
[2020-03-18 16:55:46.777][25][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:850] [C2698][S18274153557130304839] decode headers called: filter=0x5654dabcde50 status=0
[2020-03-18 16:55:46.777][25][debug][router] [external/envoy/source/common/router/router.cc:320] [C2698][S18274153557130304839] cluster 'local' match for URL '/mersennePrime?p=203'
[2020-03-18 16:55:46.778][25][debug][router] [external/envoy/source/common/router/router.cc:381] [C2698][S18274153557130304839] router decoding headers:
[2020-03-18 16:55:46.778][25][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:101] [C758] using existing connection
[2020-03-18 16:55:46.778][25][debug][router] [external/envoy/source/common/router/router.cc:1170] [C2698][S18274153557130304839] pool ready
[2020-03-18 16:55:46.778][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:386] [C758] writing 324 bytes, end_stream false
[2020-03-18 16:55:46.778][25][trace][http] [external/envoy/source/common/http/conn_manager_impl.cc:850] [C2698][S18274153557130304839] decode headers called: filter=0x5654d5f02050 status=1
[2020-03-18 16:55:46.778][25][trace][http] [external/envoy/source/common/http/http1/codec_impl.cc:392] [C2698] parsed 324 bytes
[2020-03-18 16:55:46.778][25][trace][connection] [external/envoy/source/common/network/connection_impl.cc:292] [C2698] readDisable: enabled=true disable=true
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/common/network/connection_impl.cc:514] [C2698] remote close
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/common/network/connection_impl.cc:192] [C2698] closing socket: 0
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:247] [C2698] SSL shutdown: rc=0
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/extensions/transport_sockets/tls/ssl_socket.cc:176] [C2698] TLS error: 337092985:SSL routines:tls_post_process_client_hello:cert cb error 537350270:BIO routines:mem_write:write to read only BIO
[2020-03-18 16:55:46.778][25][debug][http] [external/envoy/source/common/http/conn_manager_impl.cc:1562] [C2698][S18274153557130304839] stream reset
[2020-03-18 16:55:46.778][25][debug][router] [external/envoy/source/common/router/router.cc:1116] [C2698][S18274153557130304839] resetting pool request
[2020-03-18 16:55:46.778][25][debug][client] [external/envoy/source/common/http/codec_client.cc:105] [C758] request reset
[2020-03-18 16:55:46.778][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=2)
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/common/network/connection_impl.cc:103] [C758] closing data_to_write=324 type=1
[2020-03-18 16:55:46.778][25][trace][connection] [external/envoy/source/common/network/raw_buffer_socket.cc:66] [C758] write returns: 324
[2020-03-18 16:55:46.778][25][debug][connection] [external/envoy/source/common/network/connection_impl.cc:192] [C758] closing socket: 1
[2020-03-18 16:55:46.778][25][debug][client] [external/envoy/source/common/http/codec_client.cc:82] [C758] disconnect. resetting 0 pending requests
[2020-03-18 16:55:46.778][25][debug][pool] [external/envoy/source/common/http/http1/conn_pool.cc:133] [C758] client disconnected, failure reason:
[2020-03-18 16:55:46.778][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=3)
[2020-03-18 16:55:46.778][25][trace][main] [external/envoy/source/common/event/dispatcher_impl.cc:133] item added to deferred deletion list (size=4)
[2020-03-18 16:55:46.778][25][debug][main] [external/envoy/source/server/connection_handler_impl.cc:68] [C2698] adding to cleanup list

              Unassigned Unassigned
              rvansa1@redhat.com Radim Vansa (Inactive)
              Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

                Created:
                Updated:
                Resolved: