Request fails when sent on an existing connection on the connection pool

[jrajahalme]

Cilium main using quay.io/cilium/cilium-envoy:v1.27.2-f19708f3d0188fe39b7e024b4525b75a9eeee61f

Sometimes request fails when "using existing fully connected connection".

In a specific example, an upstream connection was created and then the request was denied by CNP and nothing was sent on the connection. Then, when the connection was reused 43 seconds later for a request that was accepted, it timed out:

2023-12-05T17:09:12.497700658Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] connecting" subsys=envoy-client threadID=290
2023-12-05T17:09:12.497809231Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] socket event: 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497812487Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498622410Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] raising connection event 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498628973Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] connected" subsys=envoy-client threadID=290
2023-12-05T17:09:55.783386414Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] using existing fully connected connection" subsys=envoy-pool threadID=290
2023-12-05T17:09:55.783388679Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] creating stream" subsys=envoy-pool threadID=290
2023-12-05T17:09:55.783424525Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] writing 222 bytes, end_stream false" subsys=envoy-connection threadID=290
2023-12-05T17:09:55.783428022Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] encode complete" subsys=envoy-client threadID=290
2023-12-05T17:09:55.783443311Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] socket event: 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:55.783446486Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:55.783449202Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] write returns: 222" subsys=envoy-connection threadID=290
2023-12-05T17:10:05.784450945Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] request reset" subsys=envoy-client threadID=290
2023-12-05T17:10:05.784461874Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] closing socket: 1" subsys=envoy-connection threadID=290
2023-12-05T17:10:05.784464850Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] raising connection event 1" subsys=envoy-connection threadID=290
2023-12-05T17:10:05.784467095Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] disconnect. resetting 0 pending requests" subsys=envoy-client threadID=290
2023-12-05T17:10:05.786287775Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] client disconnected, failure reason: " subsys=envoy-pool threadID=290
2023-12-05T17:10:05.786539263Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] destroying stream: 0 remaining" subsys=envoy-pool threadID=290

Possible remedies may include to:

• only keep connections in the pool if they were successfully used for a request at least once?

In the above case the original connection created for the denied request was connection 67. which was torn down after the denied request. It is unclear why the connection 68 was created right after:

2023-12-05T17:09:12.491565522Z level=debug msg="[cilium.network: in upstream callback" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.491569881Z level=debug msg="[cilium.ipcache: Looking up key: af40192, prefixlen: 32" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.491573377Z level=debug msg="[cilium.ipcache: 10.244.1.146 has ID 10513" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.491584558Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] router decoding headers:" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491631217Z level=debug msg="':authority', '10.244.1.146:8080'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491636276Z level=debug msg="':path', '/private'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491638951Z level=debug msg="':method', 'GET'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491642197Z level=debug msg="':scheme', 'http'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491644782Z level=debug msg="'user-agent', 'curl/8.4.0'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491647077Z level=debug msg="'accept', '*/*'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491649281Z level=debug msg="'x-forwarded-proto', 'http'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491651455Z level=debug msg="'x-envoy-internal', 'true'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491653879Z level=debug msg="'x-request-id', '937e2c24-0c9d-43a1-8086-52cee0efde18'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491656233Z level=debug msg="'x-envoy-expected-rq-timeout-ms', '3600000'" subsys=envoy-router threadID=290
2023-12-05T17:09:12.491658908Z level=debug msg="[queueing stream due to no available connections (ready=0 busy=0 connecting=0)" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.491693553Z level=debug msg="[trying to create new connection" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.491706968Z level=debug msg="[ConnPoolImplBase 0x178d3fd9fa40, ready_clients_.size(): 0, busy_clients_.size(): 0, connecting_clients_.size(): 0, connecting_stream_capacity_: 0, num_active_streams_: 0, pending_streams_.size(): 1 per upstream preconnect ratio: 1" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.491710555Z level=debug msg="[creating a new connection (connecting=0)" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.491721866Z level=debug msg="[Set socket (70) option SO_MARK to dc670b00 (magic mark: b00, id: 56423, cluster: 0), src: 10.244.2.139:52450" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.491973634Z level=debug msg="[[C67] current connecting state: true" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.491989194Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] connecting" subsys=envoy-client threadID=290
2023-12-05T17:09:12.491992589Z level=debug msg="[[C67] connecting to 10.244.1.146:8080" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.491995205Z level=debug msg="[[C67] connection in progress" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.491997919Z level=debug msg="[not creating a new connection, shouldCreateNewConnection returned false." subsys=envoy-pool threadID=290
2023-12-05T17:09:12.492001766Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] decode headers called: filter=envoy.filters.http.upstream_codec status=4" subsys=envoy-http threadID=290
2023-12-05T17:09:12.492004692Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] decode headers called: filter=envoy.filters.http.router status=1" subsys=envoy-http threadID=290
2023-12-05T17:09:12.492008499Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] parsed 87 bytes" subsys=envoy-http threadID=290
2023-12-05T17:09:12.492949747Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] socket event: 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.492966399Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.492970566Z level=debug msg="[[C67] connected" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.492973612Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] raising connection event 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.492977980Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] connected" subsys=envoy-client threadID=290
2023-12-05T17:09:12.492980675Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] attaching to next stream" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.492983610Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] creating stream" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.492986356Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] pool ready" subsys=envoy-router threadID=290
2023-12-05T17:09:12.492989221Z level=debug msg="[cilium.ipcache: Looking up key: af40192, prefixlen: 32" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.493721885Z level=debug msg="[cilium.ipcache: 10.244.1.146 has ID 10513" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.493986468Z level=debug msg="[Cilium L7 PortNetworkPolicyRules(): returning false" subsys=envoy-config threadID=290
2023-12-05T17:09:12.493991116Z level=debug msg="[cilium.l7policy: egress (56423->10513) policy lookup for endpoint 10.244.2.139 for port 8080: DENY" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.493993851Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] Sending local reply with details " subsys=envoy-http threadID=290
2023-12-05T17:09:12.493996998Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] encode headers called: filter=cilium.l7policy status=0" subsys=envoy-http threadID=290
2023-12-05T17:09:12.494008609Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] encoding headers via codec (end_stream=false):" subsys=envoy-http threadID=290
2023-12-05T17:09:12.494011665Z level=debug msg="':status', '403'" subsys=envoy-http threadID=290
2023-12-05T17:09:12.494123664Z level=debug msg="'content-length', '15'" subsys=envoy-http threadID=290
2023-12-05T17:09:12.494283161Z level=debug msg="Proxy stats not found when updating" PolicyID.L4="egress:TCP:8080:0" ciliumEndpointName=cilium-test/client2-88575dbb7-qg7c8 containerID=a28fb0bf3f containerInterface= datapathPolicyRevision=108 desiredPolicyRevision=108 endpointID=386 identity=56423 ipv4=10.244.2.139 ipv6="fd00:10:244:2::ca9e" k8sPodName=cilium-test/client2-88575dbb7-qg7c8 subsys=endpoint
2023-12-05T17:09:12.494372487Z level=debug msg="Proxy stats not found when updating" PolicyID.L4="egress:TCP:8080:0" ciliumEndpointName=cilium-test/client2-88575dbb7-qg7c8 containerID=a28fb0bf3f containerInterface= datapathPolicyRevision=108 desiredPolicyRevision=108 endpointID=386 identity=56423 ipv4=10.244.2.139 ipv6="fd00:10:244:2::ca9e" k8sPodName=cilium-test/client2-88575dbb7-qg7c8 subsys=endpoint
2023-12-05T17:09:12.495366117Z level=debug msg="'content-type', 'text/plain'" subsys=envoy-http threadID=290
2023-12-05T17:09:12.495376166Z level=debug msg="'date', 'Tue, 05 Dec 2023 17:09:12 GMT'" subsys=envoy-http threadID=290
2023-12-05T17:09:12.495433963Z level=debug msg="'server', 'envoy'" subsys=envoy-http threadID=290
2023-12-05T17:09:12.495439474Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] writing 124 bytes, end_stream false" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.495443260Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] encode data called: filter=cilium.l7policy status=0" subsys=envoy-http threadID=290
2023-12-05T17:09:12.495446877Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] encoding data via codec (size=15 end_stream=true)" subsys=envoy-http threadID=290
2023-12-05T17:09:12.495449632Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] writing 15 bytes, end_stream false" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.495452788Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] Codec completed encoding stream." subsys=envoy-http threadID=290
2023-12-05T17:09:12.495455634Z level=debug msg="[item added to deferred deletion list (size=1)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.495458619Z level=debug msg="[[Tags: \"ConnectionId\":\"66\",\"StreamId\":\"17062581073634910404\"] resetting pool request" subsys=envoy-router threadID=290
2023-12-05T17:09:12.495500206Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] request reset" subsys=envoy-client threadID=290
2023-12-05T17:09:12.495503863Z level=debug msg="[item added to deferred deletion list (size=2)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.495571579Z level=debug msg="[[C67] closing data_to_write=0 type=1" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497657408Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] closing socket: 1" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497667897Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] raising connection event 1" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497671574Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] disconnect. resetting 0 pending requests" subsys=envoy-client threadID=290
2023-12-05T17:09:12.497674620Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] client disconnected, failure reason: " subsys=envoy-pool threadID=290
2023-12-05T17:09:12.497677385Z level=debug msg="[item added to deferred deletion list (size=3)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497680441Z level=debug msg="[item added to deferred deletion list (size=4)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497691301Z level=debug msg="[creating a new connection (connecting=0)" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.497694767Z level=debug msg="[Set socket (70) option SO_MARK to dc670b00 (magic mark: b00, id: 56423, cluster: 0), src: 10.244.2.139:52450" subsys=envoy-filter threadID=290
2023-12-05T17:09:12.497697803Z level=debug msg="[[C68] current connecting state: true" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497700658Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] connecting" subsys=envoy-client threadID=290
2023-12-05T17:09:12.497703604Z level=debug msg="[[C68] connecting to 10.244.1.146:8080" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497706870Z level=debug msg="[[C68] connection in progress" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497709474Z level=debug msg="[not creating a new connection, shouldCreateNewConnection returned false." subsys=envoy-pool threadID=290
2023-12-05T17:09:12.497712029Z level=debug msg="[item added to deferred deletion list (size=5)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497715065Z level=debug msg="[item added to deferred deletion list (size=6)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497718472Z level=debug msg="[item added to deferred deletion list (size=7)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497721668Z level=debug msg="[enableTimer called on 0x178d3f2c80e0 for 3600000ms, min is 3600000ms" subsys=envoy-misc threadID=290
2023-12-05T17:09:12.497785656Z level=debug msg="[[C67] close during connected callback" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497794262Z level=debug msg="[clearing deferred deletion list (size=7)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.497797409Z level=debug msg="[[Tags: \"ConnectionId\":\"67\"] destroying stream: 0 remaining" subsys=envoy-pool threadID=290
2023-12-05T17:09:12.497800384Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] socket event: 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497803229Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497806165Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] write returns: 139" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497809231Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] socket event: 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497812487Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.497815592Z level=debug msg="[[C68] connected" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498622410Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] raising connection event 2" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498628973Z level=debug msg="[[Tags: \"ConnectionId\":\"68\"] connected" subsys=envoy-client threadID=290
2023-12-05T17:09:12.498632799Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] socket event: 3" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498635595Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] write ready" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498638711Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] read ready. dispatch_buffered_data=0" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498641285Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] read returns: 0" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498643830Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] remote close" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498646705Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] closing socket: 0" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498649591Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] raising connection event 0" subsys=envoy-connection threadID=290
2023-12-05T17:09:12.498661714Z level=debug msg="[[C66] connection on event 0" subsys=envoy-conn_handler threadID=290
2023-12-05T17:09:12.498670460Z level=debug msg="[[Tags: \"ConnectionId\":\"66\"] adding to cleanup list" subsys=envoy-conn_handler threadID=290
2023-12-05T17:09:12.498993125Z level=debug msg="[item added to deferred deletion list (size=1)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.499003795Z level=debug msg="[item added to deferred deletion list (size=2)" subsys=envoy-main threadID=290
2023-12-05T17:09:12.499007392Z level=debug msg="[clearing deferred deletion list (size=2)" subsys=envoy-main threadID=290