Go 1.11 のバグと DNS の障害の合わせ技でハマった件
Go で書いたプログラムで、HTTP(S) による通信を行うとなぜか10秒間プログラム (goroutine) がストールして、その後正常に通信が行えるという謎な現象に悩まされ、無事解決できたのでここにメモしておきます。
といっても、解決のためにやったことといえば、Go のバージョンを 1.11.1（バグが修正されたバージョン）に上げただけなのですが😅
「同様の問題にハマっている人が多いみたいなので知見を共有すればよいのでは」という同僚の id:moznion のすすめもあって書いてみることにしました。
TL;DR
問題の内容と、解決に至るまでの経緯を時系列順に書き下してみます。
まず問題に気づいたのは、私が関わっているある Web サイトのログインなどの処理がやけにもっさりしているという報告を受け、それを私も確認したタイミングです。 エラーになるわけではないのですが、特定の API を呼ぶタイミングで、毎回 10 秒くらい待たされてしまうようになっていました。
ブラウザでデベロッパーツールを開いてみると、問題の API が毎回 10 秒ちょうどくらいでレスポンスを返してきていることに気づきました。正常時は数十 msec でレスポンスが返ってきますので、これは明らかにおかしいと思いました。しかも、「10秒かかるときもあれば15秒くらいなときもあれば8秒くらいなときもある」というような、バックエンドに負荷がかかったりしていることに起因しているような感じではなくて、常に 10.xxx 秒のレスポンスタイムでした。
その不調になっている API のサーバーは私が Go で構築して AWS 上で運用していたものでしたので、新しいインスタンスを立ち上げてそちらに最新版をデプロイし切り替えた時点でユーザー様から見える問題はすぐに回復しました。（ログインなど API を呼ぶ部分で 10 秒もかからなくなりました）
しかし原因究明をしないと不安だったので、不調だった方の API サーバーはサービスから切り離しましたがそのままアクセスはできる状態で残しておきました。
当初は、サービスの負荷が原因かと思ったのですが、サービスから切り離して負荷がほぼゼロの状況でも API 呼び出しに 10 秒かかるという問題は解決しませんでした。 この時点で、負荷が原因という説は否定されました。
API サーバーのログを確認すると、Redis (Elasticache) に接続しに行く部分の前後でタイムスタンプに 10 秒のラグがあるようでした。
そこで Elasticache もしくは AWS 上のネットワークの不調などを疑ったのですが、API サーバー上のシェルから curl コマンドなどで Redis に接続しにいってもまったく問題なく一瞬で繋がりますし、redis-cli でのコマンドのレスポンスにも全く問題がありませんでした。
Elasticache のイベントログ等を見ても、何日間もまったく問題なく動いているようでした。
Redis クラスターの DNS 名の解決も、dig コマンドなどで一瞬で解決できます。
ということで、どこで時間がかかっているのか、まったくわからなくなってしまいました。
こうなると、怪しいのは Go のプログラム自体です。
Redis のクライアントとしては redigo を使っていますが、こちらの redis.Dial() 関数の呼び出しで 10 秒かかっていることまではわかったのですが Issue などを探しても同様の問題は報告されていないようでした。
Dial() の内容としては基本的には名前解決をしてソケットを開いているだけだと思ったので、名前解決の部分がおかしいのかと思い、困り果てて golang dns slow みたいなやけっぱちな検索ワードで検索してみたところ奇跡的に引っかかったのがこちらの Go 本体の Issue でした：
この Issue 自体は 2017 年 9 月にレポートされたもので、 Go 1.8 とか 1.9 の問題だったので、Go 1.11 を使っていた私には関係ないか、、、と思いつつもスレッドを読んでいったところ、今年の8月29日に「Go 1.11 で DNS の名前解決が 10 秒かかる」という、私とまったく同じ症状を訴えている人がいました。
https://github.com/golang/go/issues/21906#issuecomment-416809879
dig など他のツールでは一瞬で名前解決できる、という点も私の症状と同じでした。
で、その Issue は
https://github.com/golang/go/issues/27525
に引き継がれ、以下のコミットで修正されたようでした。
https://github.com/golang/go/commit/94f48ddb96c4dfc919ae024f64df19d764f5fb5b
結論としては、Linux 上で /etc/resolv.conf に書かれた nameserver のうち壊れたものが一つでもあると 10 秒かかるようになってしまっている、ということのようでした。
問題が起こった環境を見てみると、 /etc/resolv.conf に書かれた nameserver が 3 つあり、そのうちの一つで障害が起きており、応答が返ってこない状態になってしまっていました。
また、問題発生時に新しくデプロイし直して復旧した方のバージョンは確実に 1.11.1 でビルドしたもので、同じ nameserver を参照しているにもかかわらず 10 秒の遅延は発生しておりませんでしたので、あとは問題が起こっている方のバイナリが 1.11 でビルドされたものであることが確認できれば、ほぼ確実にこのバグにより引き起こされた問題ということができると思いました。
ということで、問題が起きた方のバイナリをコンパイルした Go のバージョンを調べてみることにしました。
コンパイル済みのバイナリから、そのバイナリをコンパイルした Go のバージョンを調べるには、以下の Dave Cheney 氏の記事が参考になります。
How to find out which Go version built your binary | Dave Cheney
すなわち、gdb で実行中のプロセスにアタッチもしくは新規プロセスを起動して、runtime.buildVersion という定数の値を表示してみれば良いわけです。
障害が起こったほうでは
(gdb) p 'runtime.buildVersion'
$1 = {str = 0xa33954 "go1.11gophergrave;gsime;gsiml;gtcir;gtdot;hangupharrw;hcirc;headerhealthheartsheighthelliphiddenhoarr;iacuteicirc;iexcl;ignoreigraveiiint;iiota;ijlig;imacr;image;imath;imped;infin;iogon;ip+netiprod;iq"..., len = 6}
と表示されましたので、 len = 6 ということで先頭から6文字分を読みます。するとgo1.11 ですね。
新しくデプロイした方は
(gdb) p 'runtime.buildVersion'
$1 = {str = 0xa38fb9 "go1.11.1gtquest;gtrless;harrcir;hijackedhostnamehreflanghttp/1.1iam/infoidentityif-matchif-rangeinfinityintprod;invalid isindot;languagelarrbfs;larrsim;lbrksld;lbrkslu;ldrdhar;lesdoto;lessdot;lessgtr;"..., len = 8}
ということで go1.11.1 です。
どうやらビンゴのようです。
ということで、Go 1.11.1 でビルドしてデプロイした現在のバージョンはこのまま問題なく稼働できそうということがわかり一安心です。
ただ、Elasticache へのアクセスは明示的にタイムアウトを設定して、異常時にももうちょっと早めにキャッシュを利用しない処理にフォールバックできたほうがよいように思いましたのでその点は修正する必要がありそうです。
まとめ
たしかコードコンプリートあたりに「プログラマはすぐ『コンパイラのバグじゃないか？』と疑いがちだけど、99％以上の場合は自分のコードのバグだ」みたいなことが書いてあったと思いますし私もしょっちゅう処理系を疑ってはブーメランが飛んできて自分のコードが良くないことを発見するのですが、今回はほんとに処理系のバグでした。
あと、DNS の障害が引き金になって起こるというレアなケースだったので調査に苦労しましたが原因を見つけることができたときはとても痛快でした。
これだからプログラマーはやめられませんね。
