gRPCのkeepaliveで気をつけること

概要

gRPCでは１つのHTTP/2コネクション上でstreamを多重化します。
しかしidleなコネクションは、LBなど間に介在するネットワーク機器によって気づいたら切断されているケースがあります。
そうならないよう、定期的にパケット（PINGフレーム）を流して「idleではないよ」とコネクションを維持しようとするのがいわゆるkeepaliveという仕組みです。

gRPCではデフォルトの設定では無効になっている＆地味に設定が細かいので１つ１つ説明します。

gRPCのkeepaliveの役割

大きく２つあります。

１つ目は先に述べたようにidleコネクションを維持するためです。

２つ目は死んだコネクション（TCPハーフオープン）があったら切断し、再接続するためです。

例えばNLBでは350秒以上idleなコネクションが切断される仕組みがあり、これによって普段あんまりトラフィックの無いサービスでいつの間にか切断されており、次回のリクエストでもその死んだコネクションをそのまま使おうとしてエラーになるケースをちらほら見かけます。

１つ目の対応でコネクションを維持するのも解決策の１つですが、切断された古いコネクションを使い続けないよう、再接続するというのも１つです。

環境

• Go v1.15.0
• grpc-go v1.29.1

事前知識

あらかじめ知っておいた方が良い知識を書いていきます。

HTTP/2のシーケンス図

PINGフレームやらGoAwayフレームやらいろんな用語が出てくるので、シーケンスを理解していると良いです。

各パラメータの説明

パラメータの意味を知っておくとスムーズに設定できます。

クライアント

クライアント側はClientParametersというパラメータを設定します。

パラメータ	説明	デフォルト値
Time	クライアントからサーバへPINGフレームを送る間隔	無限。つまり送らない
Timeout	↑の間隔で送ったPINGフレームのackが返るまでのtimeout 期間内に返らなければコネクションをクローズする	20秒
PermitWithoutStream	アクティブなRPCがない（＝ストリームがない）コネクションにPINGフレームを送るかどうか。 アクティブなRPCがなくfalseだとPINGを送らない（TimeやTimeoutの値は無視される）	false

サーバ

サーバ側はEnforcementPolicyとServerParametersの２つの設定があります。

EnforcementPolicy

パラメータ	説明	デフォルト値
MinTime	PING FloodというDoS対策で、前回のPINGからこの期間中にPINGを送ると不正なPINGとみなす。不正なPINGが一定数来たらコネクションをクローズ	5分
PermitWithoutStream	アクティブなRPCがない（＝ストリームがない）コネクションでClientからのPINGフレームを許可するか。 falseな場合不正なPINGとみなす。不正なPINGが一定数来たら来たらコネクションクローズ	false

不正なPINGが一定数来たら

grpc-goの場合２回まで許容されます。gRPCの仕様通りです。

https://github.com/grpc/grpc-go/blob/v1.29.1/internal/transport/http2_server.go#L707-L724

ref: grpc/keepalive.md at master · grpc/grpc · GitHub

３回目の不正なPINGが来たらGoAwayフレームを飛ばしてコネクションがクローズされます。

図で表すと以下です。

ServerParameters

パラメータ	説明	デフォルト値
MaxConnectionIdle	idleコネクションがこの期間を過ぎるとGoAwayフレームを送ってコネクションをクローズする	無限
MaxConnectionAge	idleかどうかに関わらず、この期間を過ぎると強制的にGoAwayフレームを送る。つまり強制切断する期間。	無限
MaxConnectionAgeGrace	↑を過ぎてから追加したい猶予期間。猶予期間を過ぎるとコネクションを強制切断	無限
Time	コネクションがidleの時にサーバからクライアントへPINGフレームを送る間隔	2時間
Timeout	↑の間隔で送ったPINGフレームのackが返るまでのtimeout 期間内に返らなければコネクションをクローズする	20秒

検証

それでは

• Client Side keepaliveの場合
• Server Side keepaliveの場合
• MaxConnectionXxxを使った場合
• 何も設定しない場合

で動作検証してみます。
実行する際はGODEBUG=http2debug=2を環境変数にセットしてログを見やすくします。

Client Side keepalive

通常使う方です。
Cloud PubSubやらGCPのサービスでもgRPCを使っていたりする場合はこちらの設定をよく使うでしょう。

クライアント側の設定

クライアント側からサーバ側にprobeを送る頻度を設定します。
10秒以下の値を設定すると10秒にまるめられます。

// here
var kacp = keepalive.ClientParameters{
        Time:                10 * time.Second,
        Timeout:             5 * time.Second,
        PermitWithoutStream: true,
}

func main() {
        conn, err := grpc.Dial(
                address, grpc.WithInsecure(),
                grpc.WithKeepaliveParams(kacp),  // here
        )
        if err != nil {
                log.Fatal(err)
        }
        defer conn.Close()

        c := pb.NewGreeterClient(conn)

        req := &pb.HelloRequest{
                Name: "alice",
        }
        resp, err := c.SayHello(context.Background(), req)
        if err != nil {
                log.Fatal(err)
        }
        log.Println("Reply: ", resp.Message)
        select {} // Block forever; run with GODEBUG=http2debug=2 to observe ping frames and GOAWAYs due to idleness.
}

サーバ側の設定

gRPCサーバ側も自前で管理している場合はEnforcementPolicyを設定しておく必要があります。

// here
var kaep = keepalive.EnforcementPolicy{
        MinTime:             5 * time.Second,
        PermitWithoutStream: true,
}

func main() {
        lis, err := net.Listen("tcp", port)
        if err != nil {
                log.Fatal(err)
        }

        s := grpc.NewServer(
                grpc.KeepaliveEnforcementPolicy(kaep),  // here
        )
        pb.RegisterGreeterServer(s, &server{})
        err = s.Serve(lis)
        if err != nil {
                log.Fatal(err)
        }
}

結果

Client Log

10秒ごとにPINGフレームを送っており、コネクションが切れていない事が分かります。

2020/08/30 03:25:51 http2: Framer 0xc00019a000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:25:51 Reply:  Hello alice
2020/08/30 03:25:51 http2: Framer 0xc00019a000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:26:01 http2: Framer 0xc00019a000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:01 http2: Framer 0xc00019a000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:11 http2: Framer 0xc00019a000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:11 http2: Framer 0xc00019a000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:21 http2: Framer 0xc00019a000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:21 http2: Framer 0xc00019a000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:31 http2: Framer 0xc00019a000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:31 http2: Framer 0xc00019a000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

Server Log

サーバ側からもGoAwayフレームが飛んでない事がわかります。

2020/08/30 03:25:51 http2: Framer 0xc0001d0000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:25:51 http2: Framer 0xc0001d0000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:26:01 http2: Framer 0xc0001d0000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:01 http2: Framer 0xc0001d0000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:11 http2: Framer 0xc0001d0000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:11 http2: Framer 0xc0001d0000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:21 http2: Framer 0xc0001d0000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:21 http2: Framer 0xc0001d0000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:31 http2: Framer 0xc0001d0000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:26:31 http2: Framer 0xc0001d0000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

MinTimeをいじらない場合

サーバからGoAwayフレームが飛んでコネクションが切れます。
too_many_pingsと怒られてますね。

2020/08/30 03:32:17 http2: Framer 0xc0001ae000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:32:17 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 03:32:27 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:27 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:37 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:37 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:47 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:47 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 03:32:47 http2: Framer 0xc0001ae000: wrote GOAWAY len=22 LastStreamID=1 ErrCode=ENHANCE_YOUR_CALM Debug="too_many_pings"

GODEBUG=http2debug=2以外にも環境変数に

• GRPC_GO_LOG_SEVERITY_LEVEL=info
• GRPC_GO_LOG_VERBOSITY_LEVEL=2

を設定していると

INFO: 2020/08/30 03:32:47 Client received GoAway with http2.ErrCodeEnhanceYourCalm.

というログが出て確認できます。

ネットワークが途切れた場合

ネットワークを切断して擬似的に死んだコネクションが発生したとします。

$ sudo iptables -A INPUT -p tcp -d 127.0.0.1 --dport 8080 -j DROP

するとクライアント側の設定で行ったTimeout後（5秒）に再接続しようとします。

2020/08/30 08:31:55 http2: Framer 0xc00016e000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 08:31:55 http2: Framer 0xc00016e000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 08:32:05 http2: Framer 0xc00016e000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
INFO: 2020/08/30 08:32:10 Subchannel Connectivity change to CONNECTING
INFO: 2020/08/30 08:32:10 Channel Connectivity change to CONNECTING
INFO: 2020/08/30 08:32:10 Subchannel picks a new address "localhost:8080" to connect

※再接続ログはGRPC_GO_LOG_SEVERITY_LEVEL=infoで表示されます。

Server Side keepalive

今度はサーバ側からprobeを送るパターンです。

サーバ側の設定

サーバ側からクライアントにprobeを送る頻度を設定します。

// here
var kasp = keepalive.ServerParameters{
        Time:    6 * time.Second,
        Timeout: 3 * time.Second,
}

func main() {
        lis, err := net.Listen("tcp", port)
        if err != nil {
                log.Fatal(err)
        }

        s := grpc.NewServer(
                grpc.KeepaliveParams(kasp),  // here
        )
        pb.RegisterGreeterServer(s, &server{})
        err = s.Serve(lis)
        if err != nil {
                log.Fatal(err)
        }
}

結果

Client Log

設定した6秒ごとにサーバからPINGフレームが送られてきます。

2020/08/30 12:20:03 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 12:20:09 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:09 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:15 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:15 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:21 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:21 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:27 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:27 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

クライアント側のkeepaliveも設定してあった場合、Timeが短い方が優先されます。

Server Log

2020/08/30 12:20:03 http2: Framer 0xc00022a000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 12:20:09 http2: Framer 0xc00022a000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:09 http2: Framer 0xc00022a000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:15 http2: Framer 0xc00022a000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:15 http2: Framer 0xc00022a000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:21 http2: Framer 0xc00022a000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:21 http2: Framer 0xc00022a000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:27 http2: Framer 0xc00022a000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 12:20:27 http2: Framer 0xc00022a000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"

MaxConnection

MaxConnectionXxxを設定したときの挙動も見てみましょう。

具体的にこれらを使いたいユースケースというのは、

christina04.hatenablog.com

で話したようにコネクションが切れた時に再resolveする仕組みを利用したいときです。
上記ではバランシングのために定期的にコネクションをリセットするようにしてます。

MaxConnectionIdle

先に

idleコネクションがこの期間を過ぎるとGoAwayフレームを送ってコネクションをクローズする

と書きましたが、ここでいうidleというのは有効なRPCがない状態を言います。
なので仮にPINGフレームをクライアント側から投げていても、RPCが無い限りこの期間を過ぎればコネクションが切断されます。

• MaxConnectionIdleは20秒
• 30秒かかるRPCメソッドを用意
• Client側のkeepalive Timeは10秒ごと

で検証してみましょう。

サーバ側の設定

var kaep = keepalive.EnforcementPolicy{
        MinTime:             10 * time.Second,
        PermitWithoutStream: true,
}

var kasp = keepalive.ServerParameters{
        MaxConnectionIdle: 20 * time.Second,  // here
}

type server struct{}

func (s *server) SayHello(ctx context.Context, in *pb.HelloRequest) (*pb.HelloReply, error) {
        time.Sleep(30 * time.Second)  // here
        return &pb.HelloReply{Message: "Hello " + in.Name}, nil
}

func main() {
        lis, err := net.Listen("tcp", port)
        if err != nil {
                log.Fatal(err)
        }

        s := grpc.NewServer(
                grpc.KeepaliveEnforcementPolicy(kaep),
                grpc.KeepaliveParams(kasp),
        )
        pb.RegisterGreeterServer(s, &server{})
        err = s.Serve(lis)
        if err != nil {
                log.Fatal(err)
        }
}

クライアント側の設定

先ほどと同じなので割愛

Server Log

実行してみると以下のようになります。

2020/08/30 15:21:33 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:21:33 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:21:43 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:21:43 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:21:53 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:21:53 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: wrote HEADERS flags=END_HEADERS stream=1 len=14
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: wrote DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: read WINDOW_UPDATE len=4 (conn) incr=18
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:22:03 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:22:13 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:22:13 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:22:23 http2: Framer 0xc0001ae000: wrote GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""

まとめると以下の挙動でした。

• RPCの実行中はMaxConnectionIdleを過ぎてもコネクションは切れない
• RPC実行中、実行後に関わらずクライアント側からPINGフレームが10秒ごとに飛ぶ
• RPC実行後はPINGフレームが飛んできてもMaxConnectionIdleを過ぎたらコネクション切断

MaxConnectionAge

先程はidleかどうかが、焦点になりましたが、こちらのパラメータはidleに限らずこの期間が過ぎればコネクションが切断されます。

• MaxConnectionAgeは20秒
• 30秒かかるRPCメソッドを用意
• Client側のkeepalive Timeは10秒ごと

で検証してみましょう。

クライアント側の設定

先ほどと同じなので割愛

Server Log

実行してみると以下のようになります。

2020/08/30 15:31:07 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:31:07 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:31:17 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:17 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:27 http2: Framer 0xc0001ae000: read PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:27 http2: Framer 0xc0001ae000: wrote PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:28 http2: Framer 0xc0001ae000: wrote GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
2020/08/30 15:31:28 http2: Framer 0xc0001ae000: wrote PING len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
2020/08/30 15:31:28 http2: Framer 0xc0001ae000: read PING flags=ACK len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
2020/08/30 15:31:28 http2: Framer 0xc0001ae000: wrote GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=""

RPC中にも関わらず、GoAwayフレームでコネクションが切断されてます。

Client Log

クライアントではリクエスト中にコネクションが切断されたため、transport is closingが出てエラーになっています。

2020/08/30 15:31:07 http2: Framer 0xc000218000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:31:07 http2: Framer 0xc000218000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/08/30 15:31:17 http2: Framer 0xc000218000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:17 http2: Framer 0xc000218000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:27 http2: Framer 0xc000218000: wrote PING len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:27 http2: Framer 0xc000218000: read PING flags=ACK len=8 ping="\x00\x00\x00\x00\x00\x00\x00\x00"
2020/08/30 15:31:28 http2: Framer 0xc000218000: read GOAWAY len=8 LastStreamID=2147483647 ErrCode=NO_ERROR Debug=""
2020/08/30 15:31:28 http2: Framer 0xc000218000: read PING len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
2020/08/30 15:31:28 http2: Framer 0xc000218000: wrote PING flags=ACK len=8 ping="\x01\x06\x01\b\x00\x03\x03\t"
2020/08/30 15:31:28 http2: Framer 0xc000218000: read GOAWAY len=8 LastStreamID=1 ErrCode=NO_ERROR Debug=""
2020/08/30 15:31:28 http2: Framer 0xc0002b4000: wrote SETTINGS len=0
2020/08/30 15:31:28 http2: Framer 0xc0002b4000: read SETTINGS len=6, settings: MAX_FRAME_SIZE=16384
2020/08/30 15:31:28 http2: Framer 0xc0002b4000: wrote SETTINGS flags=ACK len=0
2020/08/30 15:31:28 http2: Framer 0xc0002b4000: read SETTINGS flags=ACK len=0
2020/08/30 15:31:31 rpc error: code = Unavailable desc = transport is closing
exit status 1

何も設定しない場合

最後にkeepaliveを全く利用しないケースです。

クライアント側の設定

通常のgRPCのクライアントコードです。
15秒ごとにリクエストを送るようにしています。

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

        c := pb.NewGreeterClient(conn)

        for {
                req := &pb.HelloRequest{
                        Name: "alice",
                }
                resp, err := c.SayHello(context.Background(), req)
                if err != nil {
                        log.Print(err)
                } else {
                        log.Println("Reply: ", resp.Message)
                }
                time.Sleep(15 * time.Second)
        }
}

サーバ側の設定

こちらもよくあるコードです。

func main() {
        lis, err := net.Listen("tcp", port)
        if err != nil {
                log.Fatal(err)
        }

        s := grpc.NewServer()
        pb.RegisterGreeterServer(s, &server{})
        err = s.Serve(lis)
        if err != nil {
                log.Fatal(err)
        }
}

結果

今回は分かりやすさのためGRPC_GO_LOG_SEVERITY_LEVEL=infoも付けます。

Client Log

これまでと異なりprobeとしてのPINGフレームは投げません。

2020/09/01 01:25:47 http2: Framer 0xc00012e000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: Framer 0xc00012e000: read HEADERS flags=END_HEADERS stream=1 len=14
2020/09/01 01:25:47 http2: decoded hpack field header field ":status" = "200"
2020/09/01 01:25:47 http2: Framer 0xc00012e000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: decoded hpack field header field "content-type" = "application/grpc"
2020/09/01 01:25:47 http2: Framer 0xc00012e000: read DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/09/01 01:25:47 http2: Framer 0xc00012e000: read HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2020/09/01 01:25:47 http2: decoded hpack field header field "grpc-status" = "0"
2020/09/01 01:25:47 http2: decoded hpack field header field "grpc-message" = ""
2020/09/01 01:25:47 http2: Framer 0xc00012e000: wrote WINDOW_UPDATE len=4 (conn) incr=18
2020/09/01 01:25:47 http2: Framer 0xc00012e000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: Framer 0xc00012e000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 Reply:  Hello alice
2020/09/01 01:26:02 http2: Framer 0xc00012e000: wrote HEADERS flags=END_HEADERS stream=3 len=7
2020/09/01 01:26:02 http2: Framer 0xc00012e000: wrote DATA flags=END_STREAM stream=3 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read WINDOW_UPDATE len=4 (conn) incr=12
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read HEADERS flags=END_HEADERS stream=3 len=2
2020/09/01 01:26:02 http2: decoded hpack field header field ":status" = "200"
2020/09/01 01:26:02 http2: decoded hpack field header field "content-type" = "application/grpc"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read DATA stream=3 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2020/09/01 01:26:02 http2: decoded hpack field header field "grpc-status" = "0"
2020/09/01 01:26:02 http2: decoded hpack field header field "grpc-message" = ""
2020/09/01 01:26:02 Reply:  Hello alice
2020/09/01 01:26:02 http2: Framer 0xc00012e000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: wrote WINDOW_UPDATE len=4 (conn) incr=18
2020/09/01 01:26:02 http2: Framer 0xc00012e000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc00012e000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"

Server Log

2020/09/01 01:25:47 http2: Framer 0xc0001aa000: read DATA flags=END_STREAM stream=1 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote WINDOW_UPDATE len=4 (conn) incr=12
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote HEADERS flags=END_HEADERS stream=1 len=14
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote DATA stream=1 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote HEADERS flags=END_STREAM|END_HEADERS stream=1 len=24
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: read WINDOW_UPDATE len=4 (conn) incr=18
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:25:47 http2: Framer 0xc0001aa000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: read HEADERS flags=END_HEADERS stream=3 len=7
2020/09/01 01:26:02 http2: decoded hpack field header field ":method" = "POST"
2020/09/01 01:26:02 http2: decoded hpack field header field ":scheme" = "http"
2020/09/01 01:26:02 http2: decoded hpack field header field ":path" = "/helloworld.Greeter/SayHello"
2020/09/01 01:26:02 http2: decoded hpack field header field ":authority" = "localhost:8080"
2020/09/01 01:26:02 http2: decoded hpack field header field "content-type" = "application/grpc"
2020/09/01 01:26:02 http2: decoded hpack field header field "user-agent" = "grpc-go/1.29.1"
2020/09/01 01:26:02 http2: decoded hpack field header field "te" = "trailers"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: read DATA flags=END_STREAM stream=3 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote WINDOW_UPDATE len=4 (conn) incr=12
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote HEADERS flags=END_HEADERS stream=3 len=2
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote DATA stream=3 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote HEADERS flags=END_STREAM|END_HEADERS stream=3 len=2
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: read WINDOW_UPDATE len=4 (conn) incr=18
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:26:02 http2: Framer 0xc0001aa000: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"

ネットワークが途切れるとどうなるか

ここで

$ sudo iptables -A INPUT -p tcp -d 127.0.0.1 --dport 8080 -j DROP

をしてリクエストがサーバに届かないようにしてみます。

すると

2020/09/01 01:28:20 http2: Framer 0xc00012e000: wrote HEADERS flags=END_HEADERS stream=7 len=7
2020/09/01 01:28:20 http2: Framer 0xc00012e000: wrote DATA flags=END_STREAM stream=7 len=12 data="\x00\x00\x00\x00\a\n\x05alice"

でリクエストを投げっぱなしにして止まってしまいます。
仮にcontext timeoutを付けていたとしても

2020/09/01 01:31:16 http2: Framer 0xc00012e000: wrote HEADERS flags=END_HEADERS stream=3 len=15
2020/09/01 01:31:16 http2: Framer 0xc00012e000: wrote DATA flags=END_STREAM stream=3 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:31:19 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2020/09/01 01:31:19 http2: Framer 0xc00012e000: wrote RST_STREAM stream=3 len=4 ErrCode=CANCEL
2020/09/01 01:31:34 http2: Framer 0xc00012e000: wrote HEADERS flags=END_HEADERS stream=5 len=15
2020/09/01 01:31:34 http2: Framer 0xc00012e000: wrote DATA flags=END_STREAM stream=5 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:31:37 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2020/09/01 01:31:37 http2: Framer 0xc00012e000: wrote RST_STREAM stream=5 len=4 ErrCode=CANCEL

このようにずっとそのコネクションを使おうとするという挙動になっています。

$ sudo iptables --flush

して戻すと、再びコネクションにstreamを作ってリクエストが完了しました。

2020/09/01 01:37:19 http2: Framer 0xc00015a1c0: wrote HEADERS flags=END_HEADERS stream=11 len=8
2020/09/01 01:37:19 http2: Framer 0xc00015a1c0: wrote DATA flags=END_STREAM stream=11 len=12 data="\x00\x00\x00\x00\a\n\x05alice"
2020/09/01 01:37:22 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2020/09/01 01:37:22 http2: Framer 0xc00015a1c0: wrote RST_STREAM stream=11 len=4 ErrCode=CANCEL
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read WINDOW_UPDATE len=4 (conn) incr=12
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read HEADERS flags=END_HEADERS stream=7 len=2
2020/09/01 01:37:37 http2: decoded hpack field header field ":status" = "200"
2020/09/01 01:37:37 http2: decoded hpack field header field "content-type" = "application/grpc"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read DATA stream=7 len=18 data="\x00\x00\x00\x00\r\n\vHello alice"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read HEADERS flags=END_STREAM|END_HEADERS stream=7 len=2
2020/09/01 01:37:37 http2: decoded hpack field header field "grpc-status" = "0"
2020/09/01 01:37:37 http2: decoded hpack field header field "grpc-message" = ""
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: wrote PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: wrote WINDOW_UPDATE len=4 (conn) incr=18
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: wrote PING len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: read PING flags=ACK len=8 ping="\x02\x04\x10\x10\t\x0e\a\a"
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: wrote HEADERS flags=END_HEADERS stream=13 len=8
2020/09/01 01:37:37 http2: Framer 0xc00015a1c0: wrote DATA flags=END_STREAM stream=13 len=12 data="\x00\x00\x00\x00\a\n\x05alice"

なのでkeepaliveでprobeによるコネクションの死活チェックをしておかないと、腐ったコネクションでずっとエラーが発生する可能性があります。

ずっとネットワーク断してみると

先程は途中で戻しましたが、ずっとコネクション断の状態にしていると

2020/09/01 01:41:52 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2020/09/01 01:41:52 http2: Framer 0xc00015a000: wrote RST_STREAM stream=17 len=4 ErrCode=CANCEL
INFO: 2020/09/01 01:41:58 Subchannel Connectivity change to CONNECTING
INFO: 2020/09/01 01:41:58 Channel Connectivity change to CONNECTING
INFO: 2020/09/01 01:41:58 Subchannel picks a new address "localhost:8080" to connect
2020/09/01 01:42:10 rpc error: code = DeadlineExceeded desc = context deadline exceeded
WARNING: 2020/09/01 01:42:18 grpc: addrConn.createTransport failed to connect to {localhost:8080  <nil> 0 <nil>}. Err: connection error: desc = "transport: Error while dialing dial tcp 127.0.0.1:8080: i/o timeout". Reconnecting...
INFO: 2020/09/01 01:42:18 Subchannel Connectivity change to TRANSIENT_FAILURE
INFO: 2020/09/01 01:42:18 Channel Connectivity change to TRANSIENT_FAILURE

何回かの試行後にこのように再接続フローになりました。
なのでkeepaliveの設定をしていなくても、とりあえずどこかのタイミングで新しいコネクションを作ってくれるようです。
が、それまでは死んだコネクションを使い続けます。

サンプルコード

今回使用したコードはこちら

github.com

まとめ

gRPCのkeepaliveには２つの役割があり

• idleコネクションを維持する
• 死んだコネクションがあったら切断し、再接続する

これらのメリットを享受できるよう、keepaliveの設定をすることをおすすめします。

追記：第二弾も書きました。

christina04.hatenablog.com

ソース

• grpc-go/keepalive.md at master · grpc/grpc-go · GitHub
• grpc-go/examples/features/keepalive at master · grpc/grpc-go · GitHub
• HTTP/2 理解メモ – CAT EARS
• HTTP/2