背景

以前gRPCのkeepaliveについて説明しました。

christina04.hatenablog.com

keepaliveの目的は

idleコネクションを維持するため
死んだコネクション（TCPハーフオープン）があったら切断し、再接続するため

と書きましたが、どちらの検証もアクティブなRPCがなくなってからのkeepaliveの例であり、リクエストが続く中での挙動は検証できてなかったので今回はそれを行います。

環境

grpc-go v1.38.1
Ubuntu 18.04 (Linux Kernel 4.15.0-147-generic)

PINGフレームはいつ送信される？

Client-side keepaliveのパラメータであるTimeで送信間隔は設定できますが、いつ条件を満たして発火する(タイマーが開始する)かについては説明していませんでした。

Proposalでは

if a new stream is created and there has been greater than 'keepalive time' since the last read byte, then a keepalive PING should be sent (ideally before the HEADERS frame).
...
keepalive time is ideally measured from the time of the last byte read.

ref: https://github.com/grpc/proposal/blob/master/A8-client-side-keepalive.md

とあるように、

アクティブなstream（未完了のリクエスト）がある場合

byte read時（新規stream作成, PING reply, etc...）にタイマーが開始（リセット）され、その後KEEPALIVE_TIMEが経過したらPINGフレームを送信。

アクティブなstream（未完了のリクエスト）がない場合

次の新規stream作成時、前回のbyte readからKEEPALIVE_TIME以上経っていた場合、stream作成直後にPINGフレームを送る。KEEPALIVE_TIME未満の場合は↑と同じ。
（言い換えるとアクティブなstreamがないコネクションではずっとPINGは送信されない）

※ただしPermitWithoutStream: trueのようにアクティブなstreamがなくても送信する設定の場合、KEEPALIVE_TIME毎にPINGを送る

となっています。

ただこれは実装によりけりなようで、

However, simplistic implementations may choose to measure from the time of the last keepalive PING ack (a.k.a., polling).

ref: https://github.com/grpc/proposal/blob/master/A8-client-side-keepalive.md

最後のkeepalive PING ack（ポーリング）の時刻がタイマーの開始時刻となるケースもあるようです。

grpc-goではローカルで検証したところ前者のProposalの挙動（フローチャート）だったので、リクエストが頻繁に飛んでいる（新規streamがどんどん作成）コネクションでは常にタイマーがリセットされるためkeepaliveの設定をしていてもPINGフレームは飛びません。

そうなると死んだコネクションにどんどん新規streamを作ってしまうケースに対してコネクションを切断する、というkeepaliveの効果を期待することはできなさそうに見えます。

動作検証

死んだコネクションでRPCを実行し続けるケースを再現するため、以下の設定で検証を行います。

リクエストを継続的に流す
途中でネットワークを（擬似的に）切断する

ネットワークの擬似的な切断はiptableで行います。

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

keepaliveを設定しない場合

context timeoutなし

以下のログが出ました。

INFO: 2021/07/08 13:29:07 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:29:07 Subchannel picks a new address "localhost:8080" to connect
INFO: 2021/07/08 13:29:07 Subchannel Connectivity change to READY
INFO: 2021/07/08 13:29:07 Channel Connectivity change to READY
2021/07/08 13:29:12 Reply:  Hello alice
2021/07/08 13:29:15 Reply:  Hello alice
2021/07/08 13:29:18 Reply:  Hello alice
2021/07/08 13:29:21 Reply:  Hello alice
# 以降レスポンスなし

ChannelzのSocketは以下

$ grpcdebug localhost:8000 channelz socket 5
Socket ID:                       5
Address:                         127.0.0.1:36634->127.0.0.1:8080
Streams Started:                 9
Streams Succeeded:               4
Streams Failed:                  0
Messages Sent:                   9
Messages Received:               4
Keep Alives Sent:                0
Last Local Stream Created:       1 second ago
Last Remote Stream Created:      a long while ago
Last Message Sent Created:       1 second ago
Last Message Received Created:   11 seconds ago
Local Flow Control Window:       65535
Remote Flow Control Window:      65487

つまり結果としては以下です。

ChannelzのSocketでのkeepalive countは0
コネクション死んでも使い続ける（ずっとリクエストがブロックされる）

keepaliveを使っていませんし、予想通りの結果です。

context timeoutあり

gRPCを実行する際にctx, cancel := context.WithTimeout(ctx, 3*time.Second)を入れておきます。

以下のログが出ました。

INFO: 2021/07/08 13:32:57 Subchannel Connectivity change to CONNECTING
INFO: 2021/07/08 13:32:57 blockingPicker: the picked transport is not ready, loop back to repick
INFO: 2021/07/08 13:32:57 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:32:57 Subchannel picks a new address "localhost:8080" to connect
INFO: 2021/07/08 13:32:57 Subchannel Connectivity change to READY
INFO: 2021/07/08 13:32:57 Channel Connectivity change to READY
2021/07/08 13:33:02 Reply:  Hello alice
2021/07/08 13:33:05 Reply:  Hello alice
2021/07/08 13:33:08 Reply:  Hello alice
2021/07/08 13:33:11 Reply:  Hello alice
2021/07/08 13:33:14 Reply:  Hello alice
2021/07/08 13:33:19 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2021/07/08 13:33:22 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2021/07/08 13:33:25 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2021/07/08 13:33:28 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2021/07/08 13:33:31 rpc error: code = DeadlineExceeded desc = context deadline exceeded

DeadlineExceededでリクエストがコケてます。

ChannelzのSocketは以下

$ grpcdebug localhost:8000 channelz socket 5
Socket ID:                       5
Address:                         127.0.0.1:36648->127.0.0.1:8080
Streams Started:                 12
Streams Succeeded:               5
Streams Failed:                  5
Messages Sent:                   12
Messages Received:               5
Keep Alives Sent:                0
Last Local Stream Created:       2 seconds ago
Last Remote Stream Created:      a long while ago
Last Message Sent Created:       2 seconds ago
Last Message Received Created:   18 seconds ago
Local Flow Control Window:       65535
Remote Flow Control Window:      65463

同じく結果としては

ChannelzのSocketでのkeepalive countは0
コネクション死んでも使い続ける（ずっとリクエストがtimeoutでコケる）

timeoutエラーが発生しても同じコネクションを使い続けようとしていました。

keepaliveを設定した場合

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

というパラメータをつけます。常にアクティブなRPCがあるのでPermitWithoutStreamはfalseのままです。

context timeoutなし

以下のログが出ました。

INFO: 2021/07/08 13:37:39 Subchannel Created
INFO: 2021/07/08 13:37:39 Subchannel(id:2) created
INFO: 2021/07/08 13:37:39 Subchannel Connectivity change to CONNECTING
INFO: 2021/07/08 13:37:39 Subchannel picks a new address "localhost:8080" to connect
INFO: 2021/07/08 13:37:39 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:37:39 blockingPicker: the picked transport is not ready, loop back to repick
INFO: 2021/07/08 13:37:39 Subchannel Connectivity change to READY
INFO: 2021/07/08 13:37:39 Channel Connectivity change to READY
2021/07/08 13:37:44 Reply:  Hello alice
2021/07/08 13:37:47 Reply:  Hello alice
2021/07/08 13:37:50 Reply:  Hello alice
2021/07/08 13:37:53 Reply:  Hello alice
INFO: 2021/07/08 13:38:00 Subchannel Connectivity change to CONNECTING
INFO: 2021/07/08 13:38:00 blockingPicker: the picked transport is not ready, loop back to repick
INFO: 2021/07/08 13:38:00 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:38:00 Subchannel picks a new address "localhost:8080" to connect
2021/07/08 13:38:00 rpc error: code = Unavailable desc = transport is closing
2021/07/08 13:38:00 rpc error: code = Unavailable desc = transport is closing

Subchannelの状態がCONNECTINGになり再接続を試行するようになってます。

ChannelzのSocketは以下ですが、

$ grpcdebug localhost:8000 channelz socket 5
Socket ID:                       5
Address:                         127.0.0.1:36676->127.0.0.1:8080
Streams Started:                 7
Streams Succeeded:               4
Streams Failed:                  0
Messages Sent:                   7
Messages Received:               4
Keep Alives Sent:                0
Last Local Stream Created:       1 second ago
Last Remote Stream Created:      a long while ago
Last Message Sent Created:       1 second ago
Last Message Received Created:   6 seconds ago
Local Flow Control Window:       65535
Remote Flow Control Window:      65511

keepaliveのPINGフレームは飛ばしていないことが分かります。

また再接続を試行したタイミングでTCPコネクションがクローズされており同じIDでは表示できなくなりました。

$ grpcdebug localhost:8000 channelz socket 5
2021/07/08 13:38:04 failed to fetch socket (id=5): rpc error: code = NotFound desc = requested socket 5 not found

つまり結果としては以下です。

ChannelzのSocketでのkeepalive countは0
コネクション死んだら再接続フローに

keepaliveのPINGフレームは飛んでいないにも関わらず、死んだTCPコネクションをクローズして新しいTCPコネクションを作ろうとしました。

context timeoutあり

以下のログが出ました。

INFO: 2021/07/08 13:45:03 Subchannel Created
INFO: 2021/07/08 13:45:03 Subchannel(id:2) created
INFO: 2021/07/08 13:45:03 Subchannel Connectivity change to CONNECTING
INFO: 2021/07/08 13:45:03 blockingPicker: the picked transport is not ready, loop back to repick
INFO: 2021/07/08 13:45:03 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:45:03 Subchannel picks a new address "localhost:8080" to connect
INFO: 2021/07/08 13:45:03 Subchannel Connectivity change to READY
INFO: 2021/07/08 13:45:03 Channel Connectivity change to READY
2021/07/08 13:45:08 Reply:  Hello alice
2021/07/08 13:45:11 Reply:  Hello alice
2021/07/08 13:45:14 Reply:  Hello alice
2021/07/08 13:45:17 Reply:  Hello alice
2021/07/08 13:45:22 rpc error: code = DeadlineExceeded desc = context deadline exceeded
2021/07/08 13:45:25 rpc error: code = DeadlineExceeded desc = context deadline exceeded
INFO: 2021/07/08 13:45:27 Subchannel Connectivity change to CONNECTING
INFO: 2021/07/08 13:45:27 blockingPicker: the picked transport is not ready, loop back to repick
2021/07/08 13:45:27 rpc error: code = Unavailable desc = transport is closing
INFO: 2021/07/08 13:45:27 Channel Connectivity change to CONNECTING
INFO: 2021/07/08 13:45:27 Subchannel picks a new address "localhost:8080" to connect
2021/07/08 13:45:27 rpc error: code = Unavailable desc = transport is closing

こちらも再接続を試行しています。

ChannelzのSocketは以下でした。

$ grpcdebug localhost:8000 channelz socket 5
Socket ID:                       5
Address:                         127.0.0.1:36696->127.0.0.1:8080
Streams Started:                 8
Streams Succeeded:               4
Streams Failed:                  2
Messages Sent:                   8
Messages Received:               4
Keep Alives Sent:                0
Last Local Stream Created:       2 seconds ago
Last Remote Stream Created:      a long while ago
Last Message Sent Created:       2 seconds ago
Last Message Received Created:   9 seconds ago
Local Flow Control Window:       65535
Remote Flow Control Window:      65499

つまり結果としては以下です。

ChannelzのSocketでのkeepalive countは0
コネクション死んだら再接続フローに

こちらもkeepaliveのPINGフレームは飛んでいないにも関わらず、死んだTCPコネクションをクローズして新しいTCPコネクションを作ろうとしました。

結果一覧

それぞれの結果をまとめると以下です。

	context timeoutなし	context timeoutあり
keepalive設定なし	keepalive countは0。コネクション死んでも使い続ける。	keepalive countは0。コネクション死んでも使い続ける。
keepalive設定あり	keepalive countは0。コネクション死んだら再接続フローに。	keepalive countは0。コネクション死んだら再接続フローに。

どれもkeepalive countは0で、リクエストを継続して流す以上これは先に述べたタイマーの仕様通りです。
しかしコネクションが再作成されるのは予想と異なる挙動ですね。

なぜkeepaliveが動いていないのに再接続を試行したのか

これは別のProposalで定義されてました。

proposal/A18-tcp-user-timeout.md at master · grpc/proposal · GitHub

TCP_USER_TIMEOUTというソケットオプションの設定についてで、

値が 0 より大きい場合、その値は、どのくらいの時間、送信されたデータが ACK を受信しないままの状態が続くと、 TCP がその接続を強制的にクローズし、アプリケーションに ETIMEDOUT を返す

ref: Man page of TCP

この設定によりTCPコネクションがクローズされ、新しいコネクションを作ろうとしたのです。

このProposalが生まれた背景は

For cases where the network goes down, and the socket cannot accept more data for writing, an RPC could be blocked for a very long time.

ref: https://github.com/grpc/proposal/blob/master/A18-tcp-user-timeout.md

と、まさしく死んだコネクションにずっとRPCが飛び、RPCがブロックorタイムアウトしてしまう問題について解決するためです。

grpc-goでの実装

コードでは以下で実装されています。

kp := opts.KeepaliveParams
// Validate keepalive parameters.
if kp.Time == 0 {
    kp.Time = defaultClientKeepaliveTime
}
if kp.Timeout == 0 {
    kp.Timeout = defaultClientKeepaliveTimeout
}
keepaliveEnabled := false
if kp.Time != infinity {
    if err = syscall.SetTCPUserTimeout(conn, kp.Timeout); err != nil {
        return nil, connectionErrorf(false, err, "transport: failed to set TCP_USER_TIMEOUT: %v", err)
    }
    keepaliveEnabled = true
}

ClientParametersのTimeoutがTCP_USER_TIMEOUTにセットされています。

まとめ

gRPCはHTTP/2で多重化されるため、１つのTCPコネクションが死ぬと大量のリクエスト（ストリーム）がコケるようになります。

なのでgRPCを使う際は必ずkeepaliveを設定し、死んだコネクションは早めにクローズして再接続されるようにしましょう。

Carpe Diem

備忘録

gRPCのkeepaliveで気をつけることその２

背景

環境

PINGフレームはいつ送信される？

アクティブなstream（未完了のリクエスト）がある場合

アクティブなstream（未完了のリクエスト）がない場合

動作検証

keepaliveを設定しない場合

context timeoutなし

context timeoutあり

keepaliveを設定した場合

context timeoutなし

context timeoutあり

結果一覧

なぜkeepaliveが動いていないのに再接続を試行したのか

grpc-goでの実装

まとめ