ネットワークコネクションの切断と Go の HTTP/2 クライアントのタイムアウト - Cybozu Inside Out

こんにちは、クラウド基盤本部の向井です。

幸いにも cybozu.com を運用しているデータセンター内のネットワークは（担当チームの尽力により）安定していますが、ネットワークコネクションは常に切断されるリスクがあることを念頭においておく必要があります。その原因が一時的なネットワークの不調だったり、関係するコンポーネントのメンテナンスに伴う瞬断であったりした場合、アプリケーションは適切にリトライするなどして処理を継続したいところです。一方で、このような場合には OS によるプロトコルの実装やライブラリによって隠蔽された動作により、一見不思議に見える挙動に悩まされることも少なくありません。本記事では、一例として私が所属するチームで開発している Go を使って開発されたコンポーネントで経験したネットワークコネクションの切断に伴うトラブルと、その解決に利用した Go の HTTP/2 クライアントのタイムアウトの設定について紹介します。なお、以下で Go の HTTP クライアントと書いた場合 net/http や golang.org/x/net/http2 のクライアント実装を指すこととします。

この記事は、CYBOZU SUMMER BLOG FES '24 クラウド基盤本部 Stage DAY 5 の記事です。

現象

私の所属するチームで開発・運用している Go のコードに、ある Kubernetes クラスタから別の Kubernetes クラスタへ HTTP のリクエストを送るものがあります。この環境では、ネットワークスタックの制限により、特殊なメンテナンスが行われた際にクラスタ間通信の TCP コネクションが切断される場合があります¹。このメンテナンスのタイミングで http.Client.Do() がリクエストの処理中だった場合、16 分ほど待ってからリクエストが成功するように見える場合がありました。一方で即座にエラーとなっているように見えるリクエストもありました。http.Client.Do() が即座にエラーを返した場合は明示的なリトライの仕組みがあるので問題はありませんでしたが、16 分ほど待ってしまう場合には処理の遅延が問題となりました。

この現象から、私は二つの疑問を抱きました。

なぜ長時間経ってから成功することがあるのか？
なぜ 16 分なのか？

これらについて順に考えてみましょう。

疑問1：なぜ長時間経ってから成功することがあるのか？

まずはおよそ 16 分という時間は棚に上げて、なぜそんなに時間が経ってからリクエストが成功することがあるのか考えます。

Go の HTTP クライアントは、サーバーにリクエストが到達しなかったと思われる場合などに一定の条件下でリクエストをリトライしています。例えば HTTP/1.1 を使う場合、その条件のひとつが keep-alive されていたコネクションを再利用したというものです。問題となった系ではコネクションが一定数 keep-alive されており、そのようなコネクションが利用された場合に 16 分後にリトライされることでレスポンスが得られたのではないかと考えられます。

上記はコードリーディングによっても確認できますが ²、ここでは簡単な実験によって確かめてみましょう³。以下のような Go のテストコードを考えます。

func newTestServer(t *testing.T, closeIfMod2Equal int) *httptest.Server {
        counter := 0
        handler := http.HandlerFunc(func(rw http.ResponseWriter, req *http.Request) {
                counter++
                if counter%2 == closeIfMod2Equal {
                        log.Printf("count=%d, Disconnect.", counter)
                        hj := rw.(http.Hijacker)
                        conn, _, _ := hj.Hijack()
                        conn.Close()
                        return
                }
                log.Printf("count=%d, OK.", counter)
                rw.WriteHeader(http.StatusOK)
        })
        return httptest.NewServer(handler)
}

func sendTwoRequests(t *testing.T, url string, withConnectionClose bool) {
        client := http.DefaultClient
        for i := 0; i < 2; i++ {
                req, _ := http.NewRequest(http.MethodGet, url, nil)
                if withConnectionClose {
                        req.Header.Add("connection", "close")
                }
                resp, err := client.Do(req)
                if err != nil {
                        t.Fatal(err)
                }
                if resp.StatusCode != http.StatusOK {
                        t.FailNow()
                }
        }
}

func doRetryTest(t *testing.T, closeIfMod2Equal int, withConnectionClose bool) {
        ts := newTestServer(t, closeIfMod2Equal)
        defer ts.Close()
        sendTwoRequests(t, ts.URL, withConnectionClose)
}

func TestServerCloseOnFirstRequest(t *testing.T) {
        doRetryTest(t, 1, false)
}

func TestServerCloseOnSecondRequestWithClientClose(t *testing.T) {
        doRetryTest(t, 0, true)
}

func TestServerCloseOnSecondRequestWithClientKeepAlive(t *testing.T) {
        doRetryTest(t, 0, false)
}

このコードには 3 個のテストが含まれます。いずれのテストでもクライアントは2回 http.DefaultClient の Do() メソッドを使って GET リクエストを送ります。この際、withConnectionClose が true であれば毎回新しいコネクションを確立し、そうでなければ keep-alive されたコネクションを再利用しています。また、サーバーは 200 OK を返すか、レスポンスを返さずコネクションを close することを交互にくり返します。closeIfMod2Equal によりどちらを先に行うかが決まり、0 の場合は先に 200 OK を返し、1 の場合は先に close します。

まず TestServerCloseOnFirstRequest() を考えます。この場合、サーバーは 1 リクエスト目にコネクションを close しています。コネクションを再利用しておらず Go の HTTP クライアントのリトライの条件には当てはまらないため、リトライされずにエラーとなります。

=== RUN   TestServerCloseOnFirstRequest
2024/08/07 00:45:44 count=1, Disconnect.
    main_test.go:36: Get "http://127.0.0.1:38221": EOF
--- FAIL: TestServerCloseOnFirstRequest (0.00s)

次に TestServerCloseOnSecondRequestWithClientClose() の場合、サーバーは2リクエスト目にコネクションを close します。1 リクエスト目では 200 OK を受け取りますが、クライアントはこのコネクションを keep-alive していないので、2 リクエスト目に TestServerCloseOnFirstRequest() の場合と同様にエラーとなります。

=== RUN   TestServerCloseOnSecondRequestWithClientClose
2024/08/07 00:45:44 count=1, OK.
2024/08/07 00:45:44 count=2, Disconnect.
    main_test.go:36: Get "http://127.0.0.1:38701": EOF
--- FAIL: TestServerCloseOnSecondRequestWithClientClose (0.00s)

最後に TestServerCloseOnSecondRequestWithClientKeepAlive() を考えます。この場合もサーバーは 2 リクエスト目にコネクションを close しますが、これは keep-alive されたコネクションです。その他の Go の HTTP クライアントのリトライ条件も満たされ、client.Do() 内でリクエストのリトライが行われます。3 リクエスト目は 200 OK を返すので、2 回目の client.Do() も成功したように見えています。

=== RUN   TestServerCloseOnSecondRequestWithClientKeepAlive
2024/08/07 00:45:44 count=1, OK.
2024/08/07 00:45:44 count=2, Disconnect.
2024/08/07 00:45:44 count=3, OK.
--- PASS: TestServerCloseOnSecondRequestWithClientKeepAlive (0.00s)

疑問2：なぜ 16 分なのか？

次は 16 分という時間について考えます。これは Go とは直接関係なく、TCP のレイヤーでパケットの再送が起きていたのではないかと考えています。Linux では /proc/sys/net/ipv4/tcp_retries2 で設定された回数だけ再送が行われ、デフォルトの 15 回の場合は理論上 924.6 秒、現実的にはそれ以上の時間でタイムアウトするようです⁴。観測しているおよそ 16 分という時間は、このタイムアウトまでの時間だったと考えてよさそうです。つまり、Client.Do() の中でサーバーにデータを送ろうとする net.Conn.Write() のような操作が TCP の再送のタイムアウトまで待ってからエラーを返し、疑問 1 で紹介したリトライの条件を満たしていたため HTTP リクエストがリトライされることで 16 分ほども経ってからリクエストが成功したように見えていたのではないかと考えています。

対策

何が起こっていたのかの理解が進んだので、コネクションが切断されてしまったことに気づくための仕組みを実装することを考えます。コネクションの切断がリクエストの送信時に起きても、レスポンスの受信時に起きても対応したいと考えると、ネットワークコネクション経由の読み込みや書き込みにタイムアウトを設定できるとよさそうです。

問題となっていた系では HTTP/1.1 と HTTP/2 でのリクエストが混在していました。まず HTTP/1.1 の場合ですが、「Go net/http タイムアウト」の完全ガイドという記事が参考になります。この記事と net/http のドキュメントを読み、問題となった系をタイムアウトの設定だけで簡単に解決することは難しそうだと判断しました。一つの理由として、サービスの性質上レスポンスの body の長さが大きくなりうるということがありました。レスポンスの body の読み込みにタイムアウトを仕掛けるには http.Client.Timeout を利用することになりますが、要件を満たすような値を設定しようとすると 16 分以上に設定する必要がありました。http.Client.Timeout に TCP の再送タイムアウトよりも長い時間を指定しても、今回のような問題を防ぐことはできないと考えられます。

ではどのようなタイムアウトがあれば嬉しいか考えてみます。レスポンスを受け取る時間全体にタイムアウトを設定することは難しくても、レスポンスの一部を読み込むたびに Deadline が更新されるのであればよさそうです。このような設定は HTTP/1.1 のクライアント実装では提供されておらず、労力をかけて独自の実装を書くか、他の方法で解決する必要があります。しかし HTTP/2 のクライアント実装には便利な設定があります。以下では、HTTP/2 の場合について考えます。

HTTP/2 ではフレームと呼ばれる単位で通信が行われます。RFC9113 では 10 種類のフレームが定義されており、そのうちの一つに PING というフレームがあります。PING フレームはコネクションがまだ機能しているかどうかの判定に利用できます。Go の HTTP/2 のクライアントはデフォルト設定では PING フレームによる疎通確認を行いませんが、Transport.ReadIdleTimeout を設定すると設定された時間を過ぎてもフレームが受信されなかった場合に PING フレームによる疎通確認が行われるようになります。PING フレームの送信後、コネクションが壊れたと判断するまでにレスポンスを待つ時間は Transport.PingTimeout で設定でき、デフォルトでは15秒です。

リクエストを送信しているときにコネクションが切れた場合はどうでしょうか。これには Transport.WriteByteTimeout という設定が使えます。コネクションにデータを書き込んだとき、Transport.WriteByteTimeout 以内に書き込めなければコネクションが壊れたと判断されます。

そこで以下のように ReadIdleTimeout と WriteByteTimeout を設定した Transport を利用するクライアントを利用することで、冒頭で説明したような特殊なメンテナンスが行われたような場合でも、HTTP/2 を利用していれば十分に短い時間でエラーが発生するようになりました。

func defaultHTTPTransport() (*http.Transport, error) {
    tp, ok := http.DefaultTransport.(*http.Transport)
    if !ok {
        return nil, errors.New("failed to cast http.DefaultTransport to *http.Transport")
    }
    tp = tp.Clone()

    tp2, err := http2.ConfigureTransports(tp)
    if err != nil {
        return nil, fmt.Errorf("failed to configure http2 transport: %w", err)
    }
    tp2.ReadIdleTimeout = 10 * time.Second
    tp2.WriteByteTimeout = 10 * time.Second

    return tp, nil
}