"DC" envoy codes since 1.8.3 upgrade

[Stono]

Bug description
Hi,
Not sure where to go with this so figured I'd share the observation in case anyone had any ideas.

We recently upgraded from 1.7 to 1.8.3. On 1.7 we'd periodically see 0DC's (expected, as the client, some of which have a low tolerance to slow reponses, killed the request before a response was returned, thus the DC and 0 response code due to the request not completing).

Note: We also see this on our testing 1.9 cluster

On 1.8, we're seeing DCs with status codes, as well as without:

You can see how pronounced it is here:

And you can see it's across most response codes:

There is no correlation against source or destination workload, it's cluster wide.

Note that these metrics are reporter=source, so from the source service.

[ ] Docs
[ ] Installation
[x] Networking
[ ] Performance and Scalability
[ ] Extensions and Telemetry
[ ] Security
[ ] Test and Release
[ ] User Experience
[ ] Developer Infrastructure
[ ] Upgrade

Expected behavior

Steps to reproduce the bug

Version (include the output of istioctl version --remote and kubectl version --short and helm version --short if you used Helm)

How was Istio installed?

Environment where the bug was observed (cloud vendor, OS, etc)

Additionally, please consider running istioctl bug-report and attach the generated cluster-state tarball to this issue.
Refer cluster state archive for more details.

[Stono]

By some miracle I did manage to catch one in envoy logs.

2021-02-28T10:36:20.533517Z debug envoy pool  [C3984378] using existing connection
2021-02-28T10:36:20.533522Z debug envoy pool  [C3984378] creating stream
2021-02-28T10:36:20.533534Z debug envoy router  [C3897434][S14880343837474254794] pool ready
2021-02-28T10:36:20.575085Z debug envoy filter  original_dst: New connection accepted
2021-02-28T10:36:20.575173Z debug envoy conn_handler  [C3985182] new connection
2021-02-28T10:36:20.575238Z debug envoy http  [C3985182] new stream
2021-02-28T10:36:20.575312Z debug envoy http  [C3985182][S9369404714274295047] request headers complete (end_stream=true):
':authority', 'app.search-one-read'
':path', '/api/v1/advert/201607135816874'
':method', 'GET'
'accept', 'application/json'
'x-request-id', '628981035bc3c795-AMS'
'x-b3-parentspanid', '7fdb0b055f759768'
'x-b3-traceid', '05875718085acea7'
'x-b3-spanid', '15f5e3c12011df59'
'x-b3-sampled', '1'
'client', 'dealer-websites'
'x-b3-flags', '0'
'x-client-identifier', 'dealer-websites'
'connection', 'Keep-Alive'
'user-agent', 'Apache-HttpClient/4.5.5 (Java/1.8.0_275)'
'accept-encoding', 'gzip,deflate'

2021-02-28T10:36:20.575335Z debug envoy http  [C3985182][S9369404714274295047] request end stream
2021-02-28T10:36:20.575433Z debug envoy filter  override with 3 ALPNs
2021-02-28T10:36:20.575460Z debug envoy router  [C3985182][S9369404714274295047] cluster 'outbound|80||app.search-one-read.svc.cluster.local' match for URL '/api/v1/advert/201607135816874'
2021-02-28T10:36:20.575506Z debug envoy router  [C3985182][S9369404714274295047] router decoding headers:
':authority', 'app.search-one-read'
':path', '/api/v1/advert/201607135816874'
':method', 'GET'
':scheme', 'https'
'accept', 'application/json'
'x-request-id', '628981035bc3c795-AMS'
'client', 'dealer-websites'
'x-b3-flags', '0'
'x-client-identifier', 'dealer-websites'
'user-agent', 'Apache-HttpClient/4.5.5 (Java/1.8.0_275)'
'accept-encoding', 'gzip,deflate'
'x-forwarded-proto', 'http'
'x-envoy-decorator-operation', 'app.search-one-read.svc.cluster.local:80/*'
'x-envoy-peer-metadata', '...'
'x-envoy-peer-metadata-id', 'sidecar~10.194.52.186~dealer-websites-server-757cf77bc5-682nk.dealer-websites-server~dealer-websites-server.svc.cluster.local'
'x-envoy-expected-rq-timeout-ms', '25000'
'x-envoy-attempt-count', '1'
'x-b3-traceid', '05875718085acea7'
'x-b3-spanid', '3c43cc204ee16ece'
'x-b3-parentspanid', '15f5e3c12011df59'
'x-b3-sampled', '1'
2021-02-28T10:36:20.575520Z debug envoy pool  [C3981158] using existing connection
2021-02-28T10:36:20.575525Z debug envoy pool  [C3981158] creating stream
2021-02-28T10:36:20.575531Z debug envoy router  [C3985182][S9369404714274295047] pool ready
2021-02-28T10:36:20.580330Z debug envoy router  [C3985182][S9369404714274295047] upstream headers complete: end_stream=false
2021-02-28T10:36:20.580426Z debug envoy http  [C3985182][S9369404714274295047] encoding headers via codec (end_stream=false):
':status', '404'
'originating-request-identifier', '8E0E6EC774914B7BACFEC1A41AB2FC8C'
'request-identifier', '8E0E6EC774914B7BACFEC1A41AB2FC8C'
'server', 'envoy'
'vary', 'accept-encoding'
'content-encoding', 'gzip'
'content-type', 'application/json'
'date', 'Sun, 28 Feb 2021 10:36:19 GMT'
'x-envoy-upstream-service-time', '4'

2021-02-28T10:36:20.580610Z debug envoy connection  [C3985182] remote early close
2021-02-28T10:36:20.580623Z debug envoy connection  [C3985182] closing socket: 0
2021-02-28T10:36:20.580681Z debug envoy http  [C3985182][S9369404714274295047] stream reset
2021-02-28T10:36:20.580787Z debug envoy wasm  wasm log: [extensions/stats/plugin.cc:615]::report() metricKey cache hit , stat=36
2021-02-28T10:36:20.580800Z debug envoy wasm  wasm log: [extensions/stats/plugin.cc:615]::report() metricKey cache hit , stat=6
2021-02-28T10:36:20.580802Z debug envoy wasm  wasm log: [extensions/stats/plugin.cc:615]::report() metricKey cache hit , stat=10
2021-02-28T10:36:20.580805Z debug envoy wasm  wasm log: [extensions/stats/plugin.cc:615]::report() metricKey cache hit , stat=14
2021-02-28T10:36:20.580812Z debug envoy router  [C3985182][S9369404714274295047] resetting pool request
2021-02-28T10:36:20.580817Z debug envoy client  [C3981158] request reset
2021-02-28T10:36:20.580823Z debug envoy connection  [C3981158] closing data_to_write=0 type=1
2021-02-28T10:36:20.580825Z debug envoy connection  [C3981158] closing socket: 1
2021-02-28T10:36:20.580850Z debug envoy connection  [C3981158] SSL shutdown: rc=0
2021-02-28T10:36:20.580853Z debug envoy connection  [C3981158]
2021-02-28T10:36:20.580873Z debug envoy client  [C3981158] disconnect. resetting 0 pending requests
2021-02-28T10:36:20.580881Z debug envoy pool  [C3981158] client disconnected, failure reason:
2021-02-28T10:36:20.580897Z debug envoy conn_handler  [C3985182] adding to cleanup list
2021-02-28T10:36:20.580902Z debug envoy pool  [C3981158] destroying stream: 0 remaining
2021-02-28T10:36:20.583551Z debug envoy client  [C3983536] response complete

Guessing the problem line is: 2021-02-28T10:36:20.580881Z debug envoy pool [C3981158] client disconnected, failure reason:

The client (dealer-websites-server) in this instance, got the 404 back, and handled it accordingly, so there's some change in envoy behaviour here 1.7 -> 1.8.

I'm not wholly sold that it's actually a problem per-se, as the client appears to still be receiving the response correctly. But we monitor for DC codes which is what made this stand out.

It would be nice to understand what's causing it at least and ruling out any underlying problem.

[Stono]

OK so my gut here was that the impact is connection churn. As I mentioned before the source service is getting the response but then we get the client disconnect.

I decided to turn on http2upgrades just to see what differences that makes, if any. I took two candidate services which have more traffic than others just so we have some consistency in source and destination workloads.

As expected the connection rate (bottom graph) dropped right off as the persistent h2 connections were used), but interestingly the 0DCs reduced (didn't stop, but reduced).

I've no idea what this is actually telling me, it's just more data.

[Stono]

This graph is also interesting, we had been experiencing more p95 latency recently and had been struggling to get to the bottom of it. As I enabled http2 on the above service yesterday, that seems to have almost entirely solved the issues we were seeing in latency.

Last 48 hours:

Which makes me wonder if the increased latency we've been seeing is partly due to reconnections due to an excess of DC's (this issue)?

[Stono]

OK I believe this to be a 1.8+ regression, I've tested a workload with a 1.7 sidecar this morning and get barely any DCs in comparison.

I have proxy logs from both a 1.7 and 1.9 sidecar that I can share privately if required, the 1.9 shows:

The pattern appears to be every 10 seconds, feels like an aggressive socket timeout perhaps?

❯ cat 1.9.log | grep -i disconn
{"level":"debug","time":"2021-03-01T07:15:49.635786Z","scope":"client","msg":"[C196035] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:15:49.635806Z","scope":"pool","msg":"[C196035] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:15:59.636194Z","scope":"client","msg":"[C196048] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:15:59.636203Z","scope":"pool","msg":"[C196048] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:16:19.621107Z","scope":"client","msg":"[C196054] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:16:19.621118Z","scope":"pool","msg":"[C196054] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:16:29.634028Z","scope":"client","msg":"[C196042] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:16:29.634040Z","scope":"pool","msg":"[C196042] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:16:39.630850Z","scope":"client","msg":"[C196029] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:16:39.630860Z","scope":"pool","msg":"[C196029] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:16:49.632537Z","scope":"client","msg":"[C196077] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:16:49.632541Z","scope":"pool","msg":"[C196077] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:16:59.642396Z","scope":"client","msg":"[C196083] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:16:59.642403Z","scope":"pool","msg":"[C196083] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:17:09.628760Z","scope":"client","msg":"[C196065] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:17:09.628773Z","scope":"pool","msg":"[C196065] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:17:19.640277Z","scope":"client","msg":"[C196095] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:17:19.640282Z","scope":"pool","msg":"[C196095] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:17:29.626087Z","scope":"client","msg":"[C196101] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:17:29.626099Z","scope":"pool","msg":"[C196101] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:17:59.673122Z","scope":"client","msg":"[C196113] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:17:59.673133Z","scope":"pool","msg":"[C196113] client disconnected, failure reason: "}
{"level":"debug","time":"2021-03-01T07:18:09.625307Z","scope":"client","msg":"[C196107] disconnect. resetting 0 pending requests"}
{"level":"debug","time":"2021-03-01T07:18:09.625316Z","scope":"pool","msg":"[C196107] client disconnected, failure reason: "}

The 1.7 shows some, but hardly any in comparison:

❯ cat 1.7.log | grep -i discon
2021-03-01T07:20:04.035052Z     debug   envoy client    [C21] disconnect. resetting 0 pending requests
2021-03-01T07:20:04.035057Z     debug   envoy pool      [C21] client disconnected, failure reason:
2021-03-01T07:21:54.036225Z     debug   envoy client    [C37] disconnect. resetting 0 pending requests
2021-03-01T07:21:54.036237Z     debug   envoy pool      [C37] client disconnected, failure reason:

I'll continue to dig...

cc @howardjohn

[Stono]

FWIW something else I've noticed is that you get client disconnected, failure reason: at the source service when you:

• update the DestinationRule of the remote service.
• scale the remote service up or down

So I assume these are long lived connections being closed by the remote. It'd be good to have something in the failure reason to help you differentiate good from bad?

[Stono]

We can certainly see the RST's in wireshark, I'm not the best at deciphering pcaps so if anyone wants to look please ping me on slack.

I was wondering if it's due to socket timeouts on the local app server causing RST of sidecar -> app. It doesn't appear to be the case as the apps all have 6 minute idle socket timeouts.

My gut here is we're seeing client disconnected between A and B now being reported with a DC? whereas before we only saw them for B.

local app ---A--> local istio proxy --B--> remote istio proxy

[ramaraochavali]

@lambdai FYI. Any idea if some thing is changed in Envoy with 1.8?

[Stono]

OK so I'm almost certain here that what i'm seeing is clients that are not using connection pooling, eg using a single http client per request. Every app that i've checked so far is not reusing connections across requests.

The behaviour of these apps haven't changed, however what has changed since 1.8 is we're now seeing a DC in envoy on perfectly OK status code (2xx etc).

[lambdai]

The behaviour of these apps haven't changed, however what has changed since 1.8 is we're now seeing a DC in envoy on perfectly OK status code (2xx etc).

New 200 DC combination is interesting.
I guess access log delayed thus DC(downstream closed) is appended in the extreme cases where a http response is prepared before client received it

#31136 (comment) shows some application send reset to local istio proxy(port 15001), that is probably the cause of DC

[lambdai]

Http2 stop the proportionate from downstream close to upstream because per request failure is not likely to promote to connection failure

[lambdai]

Suspicious changes:

• http: fixed a bug in access logs where early stream termination could be incorrectly tagged as a downstream disconnect, and disconnects after partial response were not flagged.

• http: added HCM level configuration of error handling on invalid messaging which substantially changes Envoy’s behavior when encountering invalid HTTP/1.1 defaulting to closing the connection instead of allowing reuse. This can temporarily be reverted by setting envoy.reloadable_features.hcm_stream_error_on_invalid_message to false, or permanently reverted by setting the HTTP/1 configuration override_stream_error_on_invalid_http_message to true to restore prior HTTP/1.1 behavior (i.e. connection isn’t terminated) and to retain prior HTTP/2 behavior (i.e. connection is terminated).

• http: added HCM level configuration of error handling on invalid messaging which substantially changes Envoy’s behavior when encountering invalid HTTP/1.1 defaulting to closing the connection instead of allowing reuse. This can temporarily be reverted by setting envoy.reloadable_features.hcm_stream_error_on_invalid_message to false, or permanently reverted by setting the HCM option to true to restore prior HTTP/1.1 beavior and setting the new HTTP/2 configuration override_stream_error_on_invalid_http_message to false to retain prior HTTP/2 behavior.

[lambdai]

Likely this one: envoyproxy/envoy#12711

My interpretation is that any client connection close is will append a DC error detail.
Envoy don't guarantee the response will be transmitted to the client, only best efforts

[Stono]

The behaviour of these apps haven't changed, however what has changed since 1.8 is we're now seeing a DC in envoy on perfectly OK status code (2xx etc).

New 200 DC combination is interesting.
I guess access log delayed thus DC(downstream closed) is appended in the extreme cases where a http response is prepared before client received it

#31136 (comment) shows some application send reset to local istio proxy(port 15001), that is probably the cause of DC

Fwiw we see this on quite a lot of responses. Will get you a % figure shortly.