背景
マイクロサービス環境でIstio(Envoy sidecar)を使っていると、いくつかのエラーに遭遇します。
それぞれどういった状況で発生しているエラーなのかを区別できないと、適切な対応にならないため各種エラーをまとめます。
環境
- Envoy 1.22.0
- Go 1.21
構成
次のようにclient appやserver appにsidecarが挟まるようにします。
エラー
dial tcp 172.20.0.4:8001: connect: connection refused
connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused
が発生するパターンです。
周辺ログも含めると次のようになります。
timeout-client-1 | 2023/08/29 04:34:53 INFO: [core] Creating new client transport to "{\n \"Addr\": \"sidecar-client:8001\",\n \"ServerName\": \"sidecar-client:8001\",\n \"Attributes\": null,\n \"BalancerAttributes\": null,\n \"Type\": 0,\n \"Metadata\": null\n}": connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"
timeout-client-1 | 2023/08/29 04:34:53 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
timeout-client-1 | "Addr": "sidecar-client:8001",
timeout-client-1 | "ServerName": "sidecar-client:8001",
timeout-client-1 | "Attributes": null,
timeout-client-1 | "BalancerAttributes": null,
timeout-client-1 | "Type": 0,
timeout-client-1 | "Metadata": null
timeout-client-1 | }. Err: connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"
timeout-client-1 | 2023/08/29 04:34:53 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE, last error: connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"
timeout-client-1 | 2023/08/29 04:34:53 INFO: [core] pickfirstBalancer: UpdateSubConnState: 0xc000010018, {TRANSIENT_FAILURE connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"}
timeout-client-1 | 2023/08/29 04:34:53 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
timeout-client-1 | 2023/08/29 04:34:53 rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"
timeout-sidecar-client-1 | [2023-08-29 04:34:53.369][1][warning][main] [source/server/server.cc:761] there is no configured limit to the number of allowed active connections. Set a limit via the runtime key overload.global_downstream_max_connections
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE, last error: connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] pickfirstBalancer: UpdateSubConnState: 0xc000010018, {IDLE connection error: desc = "transport: Error while dialing: dial tcp 172.20.0.4:8001: connect: connection refused"}
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "sidecar-client:8001" to connect
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] pickfirstBalancer: UpdateSubConnState: 0xc000010018, {CONNECTING <nil>}
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] pickfirstBalancer: UpdateSubConnState: 0xc000010018, {READY <nil>}
timeout-client-1 | 2023/08/29 04:34:54 INFO: [core] [Channel #1] Channel Connectivity change to READY
原因
このエラーは、接続先のホストが存在しネットワーク上で到達可能であるが、指定されたポートでの接続を受け入れていない場合に発生します。
より具体的に言うと、コンテナ自体は立ち上がっている一方、サーバのプロセスではまだListenできていないような場合に発生します。今回だとclient Appが先に起動し、client-sidecarの方が起動が遅い時に再現できます。
再現方法
- clinet app → client-sidecarの順に起動させる
- client-sidecarのlistenerのportを変更する
- client appの宛先ポートを変更する
といったことをすると再現可能です。
対応方法
以下のような対応があります。
- client-sidecar → clientの順に起動するように調整する
- gRPCであればWaitForReadyを使うことで回避できる
例えば前者であれば、client appの方に
depends_on: sidecar-client: condition: service_started
のような処理を入れることでエラーが出なくなります。
dial tcp lookup timeout
似たようなケースで
rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp: lookup my-service: i/o timeout"
というエラーが発生するケースです。
原因
DNSルックアップがタイムアウトした場合に発生します。例えば
- DNSサーバーがダウンしている
- ネットワーク遅延
といったことが原因で起きます。
再現方法
ローカル環境ではうまく再現できませんでした。
対応方法
以下のような対応があります。
- dial timeoutを増やす
- gRPCであればWaitForReadyを使う
upstream request timeout
次のようなエラーが発生するパターンです。
timeout-client-1 | 2023/08/29 04:32:00 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/29 04:32:01 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/29 04:32:02 rpc error: code = Unavailable desc = upstream request timeout timeout-server-1 | 2023/08/29 04:32:02 name:"alice" age:10 man:true timeout-client-1 | 2023/08/29 04:32:03 rpc error: code = Unavailable desc = upstream request timeout timeout-server-1 | 2023/08/29 04:32:03 name:"alice" age:10 man:true timeout-client-1 | 2023/08/29 04:32:04 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/29 04:32:05 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/29 04:32:06 rpc error: code = Unavailable desc = upstream request timeout
原因
Envoyのlistener route.timeoutが、レスポンスにかかる時間よりも短いと発生します。
sidecar to sidecar
sidecar to server app
再現方法
１つはserver-sidecarでパケットをDropさせる方法です。
docker execしてiptablesをインストール
$ docker-compose exec sidecar-server /bin/bash # apt-get update # apt-get install iptables # iptables -A INPUT -p tcp --dport 9001 -j DROP
もう１つはsidecarのroute.timeoutを短くする方法です。Envoy, Istioそれぞれでやり方を紹介すると以下です。
Envoy
Envoyはlistenerのroute.timeoutで設定できます。
listeners: - name: server address: socket_address: { address: 0.0.0.0, port_value: 8001 } filter_chains: - filters: - name: envoy.filters.network.http_connection_manager typed_config: "@type": type.googleapis.com/envoy.extensions.filters.network.http_connection_manager.v3.HttpConnectionManager stat_prefix: egress_http codec_type: AUTO access_log: - name: envoy.access_loggers.file typed_config: "@type": type.googleapis.com/envoy.extensions.access_loggers.file.v3.FileAccessLog path: /dev/stdout route_config: name: local_route virtual_hosts: - name: local_service domains: ["*"] routes: - match: { prefix: "/" } route: cluster: sidecar-server timeout: 1s # ここ
デフォルトは15sです。
This timeout defaults to 15 seconds, however, it is not compatible with streaming responses (responses that never end), and will need to be disabled. Stream idle timeouts should be used in the case of streaming APIs as described elsewhere on this page.
How do I configure timeouts? — envoy 1.30.0-dev-0811e1 documentation
Istio
IstioはVirtualServiceで設定できます。
apiVersion: networking.istio.io/v1alpha3 kind: VirtualService metadata: name: reviews spec: hosts: - reviews http: - route: - destination: host: reviews subset: v2 timeout: 0.5s # ここ
対応方法
基本的には以下の対応になります。
- route.timeoutより短くなるようにレイテンシを改善する
- route.timeoutを延ばす
後者は先程の再現方法の逆で時間を延ばすことになります。
upstream connect error or disconnect/reset before headers. reset reason: connection failure
次のようなエラーが発生するパターンです。
timeout-client-1 | 2023/08/30 00:21:07 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:21:08 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:21:09 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure
原因
sidecar-server
sidecar-serverが落ちるとupstream request timeoutの後で発生します。
timeout-sidecar-server-1 exited with code 0 timeout-sidecar-server-1 exited with code 0 timeout-client-1 | 2023/08/30 00:19:48 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/30 00:19:50 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/30 00:19:52 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:19:54 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/30 00:19:56 rpc error: code = Unavailable desc = upstream request timeout timeout-client-1 | 2023/08/30 00:19:58 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:20:00 rpc error: code = Unavailable desc = upstream request timeout
connection failureの頻度は cluster.connect_timeout でした。
- name: sidecar-server http2_protocol_options: {} connect_timeout: 3s type: STRICT_DNS lb_policy: ROUND_ROBIN load_assignment: cluster_name: sidecar-server endpoints: - lb_endpoints: - endpoint: address: socket_address: address: sidecar-server port_value: 9001
server app
server appが落ちてる場合はrequest timeoutも発生せずこのエラーが発生しました。
timeout-client-1 | 2023/08/30 00:21:07 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:21:08 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure timeout-client-1 | 2023/08/30 00:21:09 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure
再現方法
- server appを落とす
- sidecar-serverを落とす
とすると再現できます。
対応方法
- client-sidecar → server-sidecarの間であれば（server-sidecarが落ちている場合）route.timeoutを延ばす
- server appが落ちている場合はhealth checkでリクエストがルーティングされないようにする
upstream connect error or disconnect/reset before headers. reset reason: connection failure, transport failure reason: delayed connect error: 111
次のようなエラーが発生するパターンです。
timeout-client-1 | 2023/08/30 00:16:15 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure, transport failure reason: delayed connect error: 111 timeout-client-1 | 2023/08/30 00:16:16 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure, transport failure reason: delayed connect error: 111 timeout-client-1 | 2023/08/30 00:16:18 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure, transport failure reason: delayed connect error: 111 timeout-client-1 | 2023/08/30 00:16:19 rpc error: code = Unavailable desc = upstream connect error or disconnect/reset before headers. reset reason: connection failure, transport failure reason: delayed connect error: 111
原因
111は通常connection refusedを意味します。
実際には ECONNREFUSED として知られるエラーです。
指定されたIPアドレスとポートの組み合わせでListenしているプロセスがない場合に発生します。
宛先のシステムにリスニングしているサービスが存在しない場合、宛先システムはSYNパケットの応答としてRSTパケットを即座に送信します。このRSTパケットの受信が ECONNREFUSED エラーの原因となります。
一方、宛先のシステムがSYNパケットを受信したが、何らかの理由で応答しない場合（例: パケットがドロップされた場合）、クライアントはタイムアウトまで待機します。
sidecarがまだlistenしていないケース
server appがまだlistenしていないケース
再現方法
- server-sidecarのlisten port番号を変える
- server appのlisten port番号を変える
- serverに起動処理を加える（listen前にtime.Sleepを入れる）
といったことで再現が可能です。
対応方法
起動時と終了時両方起きうるので、
終了時
- graceful shutdownでサーバ停止後にリクエストが流れないようにする
起動時
- health checkでリクエストがルーティングされる前に起動完了させる
となります。
その他
サンプルコード
今回のサンプルコードはこちらです。
レスポンスフラグ
レスポンスフラグは短縮形になっているので、こちらを見るとどういうエラーなのかを判別できます。
Access logging — envoy 1.30.0-dev-0811e1 documentation
HTTP and TCP
| Long name | Short name | Description |
|---|---|---|
| NoHealthyUpstream | UH | No healthy upstream hosts in upstream cluster in addition to 503 response code. |
| UpstreamConnectionFailure | UF | Upstream connection failure in addition to 503 response code. |
| UpstreamOverflow | UO | Upstream overflow (circuit breaking) in addition to 503 response code. |
| NoRouteFound | NR | No route configured for a given request in addition to 404 response code or no matching filter chain for a downstream connection. |
| UpstreamRetryLimitExceeded | URX | The request was rejected because the upstream retry limit (HTTP) or maximum connect attempts (TCP) was reached. |
| NoClusterFound | NC | Upstream cluster not found. |
| DurationTimeout | DT | When a request or connection exceeded max_connection_duration or max_downstream_connection_duration. |
HTTP only
| Long name | Short name | Description |
|---|---|---|
| DownstreamConnectionTermination | DC | Downstream connection termination. |
| FailedLocalHealthCheck | LH | Local service failed health check request in addition to 503 response code. |
| UpstreamRequestTimeout | UT | Upstream request timeout in addition to 504 response code. |
| LocalReset | LR | Connection local reset in addition to 503 response code. |
| UpstreamRemoteReset | UR | Upstream remote reset in addition to 503 response code. |
| UpstreamConnectionTermination | UC | Upstream connection termination in addition to 503 response code. |
| DelayInjected | DI | The request processing was delayed for a period specified via fault injection. |
| FaultInjected | FI | The request was aborted with a response code specified via fault injection. |
| RateLimited | RL | The request was ratelimited locally by the HTTP rate limit filter in addition to 429 response code. |
| UnauthorizedExternalService | UAEX | The request was denied by the external authorization service. |
| RateLimitServiceError | RLSE | The request was rejected because there was an error in rate limit service. |
| InvalidEnvoyRequestHeaders | IH | The request was rejected because it set an invalid value for a strictly-checked header in addition to 400 response code. |
| StreamIdleTimeout | SI | Stream idle timeout in addition to 408 or 504 response code. |
| DownstreamProtocolError | DPE | The downstream request had an HTTP protocol error. |
| UpstreamProtocolError | UPE | The upstream response had an HTTP protocol error. |
| UpstreamMaxStreamDurationReached | UMSDR | The upstream request reached max stream duration. |
| ResponseFromCacheFilter | RFCF | The response was served from an Envoy cache filter. |
| NoFilterConfigFound | NFCF | The request is terminated because filter configuration was not received within the permitted warming deadline. |
| OverloadManagerTerminated | OM | Overload Manager terminated the request. |
| DnsResolutionFailed | DF | The request was terminated due to DNS resolution failure. |
| DropOverload | DO | The request was terminated in addition to 503 response code due to drop_overloads. |
まとめ
IstioやEnvoyで発生するネットワーク系エラーの原因、再現方法、対応方法をまとめました。
