hashicorp / hashicorp/consul

Intermittent "upstream connect error or disconnect/reset before headers. reset reason: remote reset" Errors in Envoy gRPC requests

Open
#10,258 0 comments 0 reactions 0 assignees View on GitHub
theme/connect theme/consul-nomad theme/envoy/xds theme/reliability type/bug
Dominant language
Go
Stars
30.1k
Forks
4.6k
Avg merge
2d 6h
Merged PRs (30d)
43

Description

#### Overview of the Issue

We run a Consul Connect-enabled mesh with Consul 1.9.3 and Envoy 1.16.2 in a Nomad 1.0.4 setup, and are seeing small numbers of failures for gRPC requests between systems. This has effectively made Consul Connect unusable for us at production-level as a service mesh for reliability reasons.

These will manifest themselves in error logs as the following (names/IPs are redacted/changed for privacy reasons; can provide more information via email if needed):

```
Failed to call ListWidgets - gRPC call `widgets/ListWidgets` failed with `upstream connect error or disconnect/reset before headers. reset reason: remote reset`(Status code: 14)
```

(We have also seen `connection termination` reset reasons as well, though at much lower volumes.)

#### http1 via Envoy Bridge Filter -> grpc

We were able to get some significant logs for a call that was a http1 (cURL from PHP) -> Ruby gRPC service below. (This error, however, manifests on typical grpc->grpc calls too.)

Taking a deeper look at statistics for the Envoy container that made the egress call to `widgets-rpc`, we can see this:

```
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::cx_active::2
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::cx_connect_fail::0
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::cx_total::8
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::rq_active::0
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::rq_error::12
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::rq_success::0
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::rq_timeout::0
widgets-grpc.default.stg-us.internal.f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul::1.2.3.4:20669::rq_total::12
```

Other containers registered under this service behave normally.

Looking at the specific Envoy for the `widgets-grpc` service:

```
local_app::127.0.0.1:9011::cx_active::6
local_app::127.0.0.1:9011::cx_connect_fail::0
local_app::127.0.0.1:9011::cx_total::35
local_app::127.0.0.1:9011::rq_active::0
local_app::127.0.0.1:9011::rq_error::34
local_app::127.0.0.1:9011::rq_success::11977
local_app::127.0.0.1:9011::rq_timeout::0
local_app::127.0.0.1:9011::rq_total::12011
```

#### Debug Logs

We turned on debug for Envoy, and were able to capture a failure in-flight (note this specific call is a service using Envoy's http1.1 bridge filter to convert http1 to grpc).

This path is: `app1` (php/curl) -> `app1 connect proxy` via Envoy bridge filter -> `widgets-grpc` Envoy Sidecar -> `widgets-grpc`.

```
[2021-05-18 21:21:07.513][33][debug][conn_handler] [source/server/connection_handler_impl.cc:476] [C42198] new connection
[2021-05-18 21:21:07.514][33][debug][http2] [source/common/http/http2/codec_impl_legacy.cc:1140] [C42198] updating connection-level initial window size to 268435456
[2021-05-18 21:21:07.514][33][debug][http] [source/common/http/conn_manager_impl.cc:225] [C42198] new stream
[2021-05-18 21:21:07.514][33][debug][http] [source/common/http/conn_manager_impl.cc:837] [C42198][S848891993966539889] request headers complete (end_stream=false):
':authority', '127.0.0.1:14006'
':path', '/widgets/ListWidgets'
':method', 'POST'
':scheme', 'https'
'accept', '*/*'
'accept-encoding', 'identity'
'authorization', 'Basic REDACTED'
'deadline', '1624372867.512'
'content-type', 'application/grpc'
'user-agent', 'grphp/1.0.0'
'x-newrelic-id', 'REDACTED'
'x-newrelic-transaction', 'REDACTED'
'content-length', '37'
'x-forwarded-proto', 'http'
'x-request-id', 'f2c3bac5-c57a-4d23-be92-aa99c6399689'
[2021-05-18 21:21:07.514][33][debug][rbac] [source/extensions/filters/http/rbac/rbac_filter.cc:68] checking request: requestedServerName: , sourceIP: 1.1.1.1:58656, directRemoteIP: 1.2.3.4:58656, remoteIP: 1.2.3.4:58656,localAddress: 1.2.3.4:23747, ssl: uriSanPeerCertificate: spiffe://f73c09a4-ccb5-28bc-dc9e-1b5beff4b219.consul/ns/default/dc/stg-us/svc/app1, dnsSanPeerCertificate: , subjectPeerCertificate: CN=app1.svc.default.f73c09a4.consul, headers: ':authority', '127.0.0.1:14006'
':path', '/widgets/ListWidgets'
':method', 'POST'
':scheme', 'https'
'accept', '*/*'
'accept-encoding', 'identity'
'authorization', 'Basic REDACTED'
'deadline', '1624372867.512'
'content-type', 'application/grpc'
'user-agent', 'grphp/1.0.0'
'x-newrelic-id', 'REDACTED'
'x-newrelic-transaction', 'REDACTED'
'content-length', '37'
'x-forwarded-proto', 'http'
'x-request-id', 'f2c3bac5-c57a-4d23-be92-aa99c6399689'
, dynamicMetadata:
[2021-05-18 21:21:07.514][33][debug][rbac] [source/extensions/filters/http/rbac/rbac_filter.cc:113] enforced allowed, matched policy none
[2021-05-18 21:21:07.514][33][debug][router] [source/common/router/router.cc:429] [C42198][S848891993966539889] cluster 'local_app' match for URL '/widgets/ListWidgets'
[2021-05-18 21:21:07.514][33][debug][router] [source/common/router/router.cc:586] [C42198][S848891993966539889] router decoding headers:
':authority', '127.0.0.1:14006'
':path', '/widgets/ListWidgets'
':method', 'POST'
':scheme', 'http'
'accept', '*/*'
'accept-encoding', 'identity'
'authorization', 'Basic REDACTED'
'deadline', '1624372867.512'
'content-type', 'application/grpc'
'user-agent', 'grphp/1.0.0'
'x-newrelic-id', 'REDACTED'
'x-newrelic-transaction', 'REDACTED'
'content-length', '37'
'x-forwarded-proto', 'http'
'x-request-id', 'f2c3bac5-c57a-4d23-be92-aa99c6399689'
[2021-05-18 21:21:07.514][33][debug][pool] [source/common/conn_pool/conn_pool_base.cc:174] [C41710] using existing connection
[2021-05-18 21:21:07.514][33][debug][pool] [source/common/conn_pool/conn_pool_base.cc:126] [C41710] creating stream
[2021-05-18 21:21:07.514][33][debug][router] [source/common/router/upstream_request.cc:357] [C42198][S848891993966539889] pool ready
[2021-05-18 21:21:07.514][33][debug][http] [source/common/http/filter_manager.cc:721] [C42198][S848891993966539889] request end stream
[2021-05-18 21:21:07.515][33][debug][http2] [source/common/http/http2/codec_impl.cc:964] [C41710] stream closed: 2
[2021-05-18 21:21:07.515][33][debug][client] [source/common/http/codec_client.cc:119] [C41710] request reset
[2021-05-18 21:21:07.515][33][debug][pool] [source/common/conn_pool/conn_pool_base.cc:151] [C41710] destroying stream: 0 remaining
[2021-05-18 21:21:07.515][33][debug][router] [source/common/router/router.cc:1031] [C42198][S848891993966539889] upstream reset: reset reason: remote reset, transport failure reason:
[2021-05-18 21:21:07.515][33][debug][http] [source/common/http/filter_manager.cc:805] [C42198][S848891993966539889] Sending local reply with details upstream_reset_before_response_started{remote reset}
[2021-05-18 21:21:07.515][33][debug][http] [source/common/http/conn_manager_impl.cc:1435] [C42198][S848891993966539889] encoding headers via codec (end_stream=true):
':status', '200'
'content-type', 'application/grpc'
'grpc-status', '14'
'grpc-message', 'upstream connect error or disconnect/reset before headers. reset reason: remote reset'
'date', 'Tue, 18 May 2021 21:21:07 GMT'
'server', 'envoy'
[2021-05-18 21:21:07.515][33][debug][http2] [source/common/http/http2/codec_impl_legacy.cc:933] [C42198] stream closed: 0
[2021-05-18 21:21:10.433][34][debug][conn_handler] [source/server/connection_handler_impl.cc:476] [C42199] new connection
[2021-05-18 21:21:10.434][34][debug][connection] [source/extensions/transport_sockets/tls/ssl_socket.cc:215] [C42199]
[2021-05-18 21:21:10.434][34][debug][connection] [source/common/network/connection_impl.cc:203] [C42199] closing socket: 0
[2021-05-18 21:21:10.434][34][debug][conn_handler] [source/server/connection_handler_impl.cc:152] [C42199] adding to cleanup list
```

Note that a vast majority of these requests _succeed_; however, we're seeing low numbers of these requests just hard fail with the `stream closed: 2` error. We ruled out thread pool exhaustions on the gRPC server side.

#### grpc->grpc

We have also seen this with normal grpc->grpc calls as well:

```
14:upstream connect error or disconnect/reset before headers. reset reason: connection termination. debug_error_string:{"created":"@1621440548.908510397","description":"Error received from peer ipv4:127.0.0.1:8100","file":"src/core/lib/surface/call.cc","file_line":1067,"grpc_message":"upstream connect error or disconnect/reset before headers. reset reason: connection termination","grpc_status":14}
```

Similarily, this manifests itself in statistics like so:

```
cluster.inv-rpc.default.int-us.internal.7e225fe1-9399-9945-8548-77c97d033ff2.consul.upstream_cx_connect_fail: 57
```

#### Reproduction Steps

We cannot consistently reproduce this error; however, sending traffic through Consul Connect-controlled Envoy sidecars will periodically (in no discernable pattern) produce these errors for a percentage of requests.

### Consul info for both Client and Server

Client info

```
agent:
check_monitors = 1
check_ttls = 39
checks = 145
services = 107
build:
version = 1.9.3
consul:
acl = disabled
known_servers = 3
server = false
runtime:
arch = amd64
cpu_count = 12
goroutines = 7278
max_procs = 12
os = linux
version = go1.15.6
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 102
failed = 0
health_score = 0
intent_queue = 0
left = 3
member_time = 119087
members = 221
query_queue = 0
query_time = 1
```

Server info

```
agent:
check_monitors = 1
check_ttls = 0
checks = 5
services = 4
build:
version = 1.9.3
consul:
acl = disabled
bootstrap = false
known_datacenters = 2
leader = false
leader_addr = REDACTED:8300
server = true
raft:
applied_index = 401710728
commit_index = 401710728
fsm_pending = 0
last_contact = 59.817814ms
last_log_index = 401710728
last_log_term = 73570
last_snapshot_index = 401694782
last_snapshot_term = 73570
latest_configuration = [{Suffrage:Voter ID:9b5e5016-a89e-a420-e7db-f51e7883ddd0 Address:REDACTED:8300} {Suffrage:Voter ID:147003f5-f498-a4ff-c6cd-2767b98fc8ca Address:REDACTED:8300} {Suffrage:Voter ID:72da8b90-45c2-3078-03db-d4c9999db483 Address:REDACTED:8300}]
latest_configuration_index = 0
num_peers = 2
protocol_version = 3
protocol_version_max = 3
protocol_version_min = 0
snapshot_version_max = 1
snapshot_version_min = 0
state = Follower
term = 73570
runtime:
arch = amd64
cpu_count = 2
goroutines = 4830
max_procs = 2
os = linux
version = go1.15.6
serf_lan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 96
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 57185
members = 223
query_queue = 0
query_time = 4
serf_wan:
coordinate_resets = 0
encrypted = false
event_queue = 0
event_time = 1
failed = 0
health_score = 0
intent_queue = 0
left = 0
member_time = 321
members = 6
query_queue = 0
query_time = 4
```

### Operating system and Environment details

Debian Buster:

```
# cat /etc/debian_version
10.8
```

Docker:

```
# docker -v
Docker version 20.10.5, build 55c4c88
```

Nomad:

```
# nomad -v
Nomad v1.0.4 (9294f35f9aa8dbb4acb6e85fa88e3e2534a3e41a)
```

Envoy:

```
# envoy --version
envoy version: e98e41a8e168af7acae8079fc0cd68155f699aa3/1.16.2/Clean/RELEASE/BoringSSL
```

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.