Go の HTTP Server でちょっと変わった使い方をして起きた障害の調査と解決

こんにちは、システム開発部で見積もりしたり設計したりコード書いたりテストしたり運用したりしている小笠原です。こちらは ABEJA アドベントカレンダー 2024、21日目の記事です。

さて、エモい記事は他の皆が書いてくれるだろうから自分はバズからは程遠いニッチな記事でも書くか、、、と思っていたら、最高に~~頭のおかしい~~ニッチな記事がすでに公開されていて、ネタを考え直そうかと頭を抱えたのですが、初志貫徹してやっぱりニッチな障害解決の話をお届けしようと思います。

発端
コードリーディング
解決
まとめ
We Are Hiring!

発端

発端は、Go で書いた HTTP Server へのリクエストが、たまにタイムアウトする、という障害でした。
特殊な用途だったのもあり、Web フレームワークは使わずに net/http の機能を直接使って実装していましたが、アクセスログには該当するようなログは出力されていません。
となると、(AWS で Serve していたので) ELB か Kubernetes の Load Balancer のどちらかで止まってしまっている？というのが(AWS さんには申し訳ないと思いつつ)誰でも疑うポイントだと思いますが、色々ログを調査した結果、どうも HTTP Server まではリクエスト届いてそうだぞ、という状況がはっきりしてきました。
次に疑うのは、 HTTP Server にバグがあって、特定の条件で無限ループしたり、外部リソースへの問い合わせが返って来ないのを延々まっているような可能性でしょうか。しかし、処理前後にログを出力するようにしても、やはりタイムアウトするリクエストのログは出力されませんでした。また、タイムアウトするリクエストは完全にランダムに見えます。同じリクエストを複数投げても、正常にレスポンスを返せたり、稀にタイムアウトします。タイムアウトするときは HandlerFunc までリクエストは届いてなさそうです。

コードリーディング

自前のコード

とりあえず自前のコードの net/http を使って HTTP Server を立ち上げている部分を示します。だいぶん簡略化していますが、ご了承ください。

serviceHandler := http.NewServeMux()
// HandlerFunc メソッドを使って handler を登録...

serviceServer := &http.Server{
    Addr:           conf.GetListenAddress(),
    Handler:        serviceHandler,
    ReadTimeout:    30 * time.Second,
    WriteTimeout:   30 * time.Second,
    MaxHeaderBytes: 1 << 20,
}

// (1)
listener, _ := net.Listen("tcp", serviceServer.Addr)
limitedListener := netutil.LimitListener(listener, 1)

if err := serviceServer.Serve(limitedListener); err != nil {
    if err != http.ErrServerClosed {
        // エラー処理...
    }
    // 終了処理...
}

(1) の処理がいかにも怪しいですが、少々事情があって、当時は後続の処理が並行で動くと都合が悪かったため、Listener の数を1に制限しています。
基本的には、処理自体も短時間で終了し、クライアントからのリクエストも直列で行われる前提だったので、致し方なく採用したアーキテクチャで、実際ほぼ問題なく動いていました、今回のことがあるまでは。

それでは以下、Go のコードを読んでいきましょう。
ちなみに、引用する Go のコードは記事執筆時点の最新リリースバージョンである go1.23.4 のもので、 x/net も最新リリースバージョンの v0.32.0 のものです。調査時点とはバージョンは異なりますが、本質は変わっていなかったので、このようにしています。

Server.Serve

ちょっとコード端折ってますが、無限ループの中で Listener.Accept して新しい Conn を取得して、実際のリクエストの処理は goroutine で処理させることで、自身は Accept 待ちに戻っていることがわかります。

func (srv *Server) Serve(l net.Listener) error {

    ...

    ctx := context.WithValue(baseCtx, ServerContextKey, srv)
    for {
        rw, err := l.Accept()

        ...

        connCtx := ctx
        if cc := srv.ConnContext; cc != nil {
            connCtx = cc(connCtx, rw)
            if connCtx == nil {
                panic("ConnContext returned nil")
            }
        }
        tempDelay = 0
        c := srv.newConn(rw)
        c.setState(c.rwc, StateNew, runHooks) // before Serve can return
        go c.serve(connCtx)
    }
}

netutil.LimitListener

同時接続数を絞るための Listener 実装が提供されています。といってもここでは net.Listener Interface を満たす limitListener 構造体を返しているだけで、

func LimitListener(l net.Listener, n int) net.Listener {
    return &limitListener{
        Listener: l,
        sem:      make(chan struct{}, n),
        done:     make(chan struct{}),
    }
}

実際の待受処理は limitListener.Accept やさらにそこから呼び出される limitListener.acquire で行われています。

func (l *limitListener) acquire() bool {
    select {
    case <-l.done:
        return false
    case l.sem <- struct{}{}:
        return true
    }
}

func (l *limitListener) Accept() (net.Conn, error) {
    if !l.acquire() {
        for {
            c, err := l.Listener.Accept()
            if err != nil {
                return nil, err
            }
            c.Close()
        }
    }

    c, err := l.Listener.Accept()
    if err != nil {
        l.release()
        return nil, err
    }
    return &limitListenerConn{Conn: c, release: l.release}, nil
}

LimitListener.sem をバッファ（sem という変数名自体 semaphore の略なんでしょう）として使い、 acquire() 内で sem が空くまでブロックすることで、同時接続数をコントロールしてるんですね。

limitListenerConn は net.Conn Interface を満たす構造体なので、レスポンスを返した後接続を閉じる際の Close 時に limitListener.release を呼び出すことで limitListener.sem から struct{}{} を取り出し、semaphore を管理している、と。

func (l *limitListener) release() { <-l.sem }

func (l *limitListenerConn) Close() error {
    err := l.Conn.Close()
    l.releaseOnce.Do(l.release)
    return err
}

はて、ここまで見てきた限りでは、クライアントから直列に呼び出されている限りでは、問題なさそうに見えます。あるいは、もし並列にリクエストが飛んできたとしても、もう少しわかりやすく、たとえば徐々にレスポンスタイムが伸びていき、最終的にタイムアウトする、といった形で障害として現れそうなものです。

解決

いったん、前提条件やここまででわかったことをまとめてみます。

Go の HTTP Server がたまにタイムアウトする
- タイムアウトするリクエスト以外は、数百 ms 程度でレスポンスが得られている
HTTP Server は Load Balancer の後ろにいる
HTTP Server が受け付ける同時接続数は 1

ここではたと気づきました。
Load Balancer の後ろにいるので、前述のコードでもわかる通り、TLS は設定していません。つまり HTTP/1.1 で通信しています。HTTP/1.1 の場合、レスポンスヘッダー Content-Length を設定すると、Go の HTTP Server は自動で keep-alive してくれます。はい、レスポンスヘッダーに Content-Length 設定していました。

ここまで書けば、勘の良い読者の皆様はもうお気づきかと思いますが、ELB にしても Kubernetes の Load Balancer にしても、オートスケールするんですよね（ Kubernetes は設定次第ですが）。つまり、LB が 1 インスタンスで動いている間は keep-alive していても何の問題も無いのですが、LB がオートスケールした途端（最初から居た方を LB1、新しく起動した方を LB2 とします）、LB1 との接続を keep している間は当然 Connection が close されないので、LB2 経由でやってきたリクエストは Accept されません。LB1 との接続が Close すれば Accept されますが、それより先に Client の方がタイムアウトして接続断、というわけです。
また、 LB2 経由のリクエストは常にタイムアウトするため、LB の戦略的に LB2 の優先度はあっという間に下がり、使用されなくなります。そのうち LB2 は shutdown して、別のインタンスが立ち上がるでしょうが、それもまた LB2 と同じ運命を辿り、、、という流れで、「たまにタイムアウトする」という不可解な状況が発生する説明にもなります。

解決策としては、http.Server.SetkeepAlivesEnabled に false を設定することで、無事問題を解消できました。。。あるいは、レスポンスヘッダに Connection: close を追加することでも、レスポンスを返した後に Connection を close してくれるようです。