背景

gRPCを利用していると、デプロイを含む一時的なネットワーク断で以下のようなエラーが発生することがあります。

rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp xxx: connect: connection refused"

rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp: lookup xxx: i/o timeout"

これはgRPCがfail fastの思想になっており、ChannelがTRANSIENT_FAILUREの状態だとRPCを即座に失敗させるようにしているためです。

Channelの詳細は過去の記事を参考にしてください。

christina04.hatenablog.com

しかしローリングアップデートのようにChannelの状態がすぐに復旧する（再接続される）状況下であれば、すぐにエラーとせずに待機して正常系レスポンスを返せた方が良さそうです。

今回はその対応方法を紹介します。

環境

Go v1.20.2
grpc-go v1.53.0

方法

WaitForReadyを使う

gRPCにはWait for Readyという仕様があり、これをtrueにすることでTRANSIENT_FAILUREでもすぐにエラーを返さず、READYになるまでRPCを待ってくれます。

Goだとgrpc.WaitForReadyが用意されています。

context canceledであったり、deadline exceeded(=context timeout)であればエラーとして終了されるので、永続的に残ることはありません。

逆に言うと↑をきちんと対応しておかないと、もしコネクションが復旧しない場合に永続的にRPCがキューに残るので、リソースリークが起きOOMが発生する可能性があります。

実装

CallOptionなので、１つ１つのRPCに設定するか、

resp, err := c.SayHello(ctx, req, grpc.WaitForReady(true))

もしくはWithDefaultCallOptionsで一律設定することで対応できます。

        conn, err := grpc.Dial(address,
                grpc.WithInsecure(),
                grpc.WithDefaultCallOptions(
                        grpc.WaitForReady(true),
                ),
        )

動作確認

サーバとクライアントを１台ずつ用意し、クライアントは１秒毎にリクエストを送ります。

func main() {
        conn, err := grpc.Dial(address,
                grpc.WithInsecure(),
                grpc.WithDefaultCallOptions(
                        grpc.WaitForReady(true),
                ),
        )
        if err != nil {
                log.Fatal(err)
        }
        defer conn.Close()

        c := pb.NewGreeterClient(conn)

        for {
                hello(c)
                time.Sleep(1 * time.Second)
        }
}

その状態でサーバを落としたり起動したりして検証します。

またGRPC_GO_LOG_SEVERITY_LEVELを付けてChannelの状態を確認します。

$ export GRPC_GO_LOG_SEVERITY_LEVEL=info

WaitForReadyなしの場合

2023/04/01 06:22:07 Reply:  Hello alice
2023/04/01 06:22:08 Reply:  Hello alice
# サーバを停止
2023/04/01 06:22:08 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:22:08 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:22:09 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:22:09 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:22:09 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
2023/04/01 06:22:09 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
  "Addr": "localhost:8080",
  "ServerName": "localhost:8080",
  "Attributes": null,
  "BalancerAttributes": null,
  "Type": 0,
  "Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"
2023/04/01 06:22:09 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:22:09 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:22:09 rpc error: code = Unavailable desc = connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"

timeoutに関わらず、即座にUnavailableエラーが返ります。

WaitForReadyありの場合

2023/04/01 06:24:12 Reply:  Hello alice
2023/04/01 06:24:13 Reply:  Hello alice
2023/04/01 06:24:14 Reply:  Hello alice
# サーバを停止
2023/04/01 06:24:14 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:24:14 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:24:15 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:24:15 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:24:15 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
2023/04/01 06:24:15 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
  "Addr": "localhost:8080",
  "ServerName": "localhost:8080",
  "Attributes": null,
  "BalancerAttributes": null,
  "Type": 0,
  "Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"
2023/04/01 06:24:15 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:15 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:16 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:24:16 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:24:16 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:24:16 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:24:16 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
2023/04/01 06:24:16 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
  "Addr": "localhost:8080",
  "ServerName": "localhost:8080",
  "Attributes": null,
  "BalancerAttributes": null,
  "Type": 0,
  "Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"
2023/04/01 06:24:16 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:16 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:18 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:24:18 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:24:18 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:24:18 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:24:18 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
# サーバを起動
2023/04/01 06:24:18 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to READY
2023/04/01 06:24:18 INFO: [core] [Channel #1] Channel Connectivity change to READY
2023/04/01 06:24:18 Reply:  Hello alice
2023/04/01 06:24:19 Reply:  Hello alice

このようにクライアントでエラーは発生せずに待機し、再接続後してChannelがREADYになったら成功するようになります。

WaitForReadyありでtimeoutした場合

今回5秒のtimeoutを入れているので、

2023/04/01 06:24:20 Reply:  Hello alice
2023/04/01 06:24:21 Reply:  Hello alice
2023/04/01 06:24:22 Reply:  Hello alice
# サーバを停止
2023/04/01 06:24:22 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:24:22 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:24:23 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:24:23 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:24:23 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
2023/04/01 06:24:23 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
  "Addr": "localhost:8080",
  "ServerName": "localhost:8080",
  "Attributes": null,
  "BalancerAttributes": null,
  "Type": 0,
  "Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"
2023/04/01 06:24:23 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:23 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:24 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to IDLE
2023/04/01 06:24:24 INFO: [core] [Channel #1] Channel Connectivity change to IDLE
2023/04/01 06:24:24 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to CONNECTING
2023/04/01 06:24:24 INFO: [core] [Channel #1 SubChannel #2] Subchannel picks a new address "localhost:8080" to connect
2023/04/01 06:24:24 INFO: [core] [Channel #1] Channel Connectivity change to CONNECTING
2023/04/01 06:24:24 WARNING: [core] [Channel #1 SubChannel #2] grpc: addrConn.createTransport failed to connect to {
  "Addr": "localhost:8080",
  "ServerName": "localhost:8080",
  "Attributes": null,
  "BalancerAttributes": null,
  "Type": 0,
  "Metadata": null
}. Err: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"
...
2023/04/01 06:24:27 INFO: [core] [Channel #1 SubChannel #2] Subchannel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:27 INFO: [core] [Channel #1] Channel Connectivity change to TRANSIENT_FAILURE
2023/04/01 06:24:28 rpc error: code = DeadlineExceeded desc = latest balancer error: connection error: desc = "transport: Error while dialing: dial tcp [::1]:8080: connect: connection refused"

このようにDeadlineExceededエラーがクライアントに返りました。

その他

サンプルコード

今回のサンプルコードはこちらです。

github.com

なぜfail fastなのか

fail fastの考え方は、ネットワークエラーやタイムアウトなどの問題が発生した場合、その原因をすぐに特定して接続を早期に断つことで、リソースを保護しシステムの可用性を向上させることを目的としています。

特に大規模トラフィックを扱う場合、ネットワークエラーなどで大量のリクエストが滞留すると、１つ１つのリクエストのメモリ消費は少なくてもそれが積み重なってOOMが発生することがあります。

なのでこの考え方自体は実用的と言えます。

リトライは効かないのか

Interceptorでリトライ処理を入れたとして、Channelの状態はTRANSIENT_FAILUREなので即座にエラーとなるリトライがN回続くだけになります。

またEnvoyやIstioのVirtualServiceのような自動リトライは、そもそもそのレイヤまでRPCが飛んで行かない状況なので効果がありません。

まとめ

gRPCで一時的なネットワーク断が起きた際に、transportエラーを回避する方法を紹介しました。

Carpe Diem

備忘録

gRPCで一時的なネットワーク断でのtransportエラーを回避する

背景

環境

方法