あんまりかっこいいバグというわけでもないが、解決が楽しかったのでここに書いて供養しておこう。
最近はOSの性能テストをよく書いて計測している。Go言語で書いたテストコードがコンパイルされた上で実機上で動いてOSをいろいろ操作させるというものだが、こういうend-to-endなテストの性質上、壊れることもよくある。ある日のテストの失敗レポートもそういうよくあるやつに見えた。
ログを見ると、なかなか失敗しなさそうなところでタイムアウトして失敗している。理由もよくわからない。手元で再現させてみるが、もちろん再現しない。ところがCIでは頻繁に失敗している。なぜだろう？ 考えられるのは、同じ試行で走っている前のテストケースの影響だ。それで思いつく関係しそうなテストケースをいろいろ組み合わせてみるが、それでも再現しない。
もうちょっと良く見てみよう、と失敗したログを見てみる。失敗した場合、psのダンプも保存してくれるので、それも見てみる。すると……実機上のテストコード自体のCPU負荷が300%を越えてる！！ これなのは間違いない。テストコードが狂っていてCPU負荷が高くなりすぎてOSがまともに動作できず、普段なら失敗しないところでもタイムアウトしてしまうというわけだ。
しかし何が原因なのか、どこにCPUを使っているのかは謎のままだった。仕方ないので、同じ試行で走るべき全テストを実行させつつtopでCPU使用率を目で追ってみた。するとテストの早い段階でとあるテストケースが失敗すると、その後のCPU使用率が100%を越えることがわかった。これだろう。CPU利用率は違うが、同じ問題を引き起こすテストケースがほかにいくつかあるのだろう。
問題の分析
再現環境が手に入ったので話はずいぶん簡単になったが、まだ何故これが起きたのかはわかっていない。Go言語にはプロファイラが標準で入っているから、これを使ってみることにする。自分のテストのほうでプロファイラを取るようにし、問題を起こすテストケースと自分のテストケースの2つだけを実行させる。で、これをflame graphで眺めてみたら問題は一目瞭然。cdpというライブラリのなかの、とあるgoroutineが大幅にCPUサイクルを消費している。しかもその消費の大部分は文字列フォーマットとエラーオブジェクトの構築。ようするに、エラーの報告しまくっているということだ。
cdpというのはChrome devtools protocolの略だ。OSやブラウザをテストから操作するためにこのプロトコルを使っていて、cdpというのはこれをGoから使えるようにしているサードパーティのライブラリだったが、どうもここにバグがあるらしい。それで調べてみると、たしかに問題の起きたOSバージョンから、cdpのバージョンを上げる変更が入っている。手元でcdpのバージョンを落としてみると問題が直る。
というわけでcdpのバージョンを戻せば解決するが、それじゃ本質的な解決にはならないので、もうすこしcdpの中身を眺めてみる。すると、このgoroutineは実際にchromeとのメッセージをやりとりするようなものだった。何らかの理由で通信チャネルが閉じたらエラーになるが、エラーといってもいろいろなので「エラーが起きたらエラーオブジェクトを作って報告する。もしそれがcloseに関係するエラーだったらgoroutineを終了する」といったロジックになっていた。どうも、問題の事例では本当は通信チャネルが閉じたのに、closeエラーかどうかの判定が間違っていたためgoroutineが止まらず、ビジーループでエラーオブジェクトを作り続ける無限ループに陥っていたようだ。
実際に起きているエラーがなんなのか見る方法はないだろうか？ テストは実機で走っているので、ログは簡単には仕込めない。テストインフラ側には専用のロガーがあるが、依存先であるサードパーティライブラリはそのロガーのことを知らない……。ただcdpはエラーをGoのchannelに書き出してくれていたので、テストシナリオの側でこのchannelを読んでテストインフラのロガーに流すコードを仕込んでみた。すると、たしかにエラーオブジェクトが無数に流れてくる。根本的には、cdpライブラリがさらに依存しているwebsocketライブラリのcloseエラーになっているが、手前がcdpのcloseエラーになっていないので、判定に失敗しているようだ。
解決
いったん手元では雑なパッチで修正し、問題としてはひとまず解決した。これをupstreamすることにしたのだが、そこでもうすこし問題の詳細を眺めてみた。
さっきも書いたように、いちばん根底のエラーはwebsocketライブラリのエラーだった。一番手前のエラーは全然別のエラーだ。Go言語では、こういうふうにエラーオブジェクトをベースにしてちょっとエラーメッセージを追記するようなwrapがよく行われている。cdpライブラリの場合、Causeという独自のメソッドがあり、wrappingを剥がして元のエラーオブジェクトを取れるようになっている。
ライブラリとしての構造が複雑になってくると、こういうwrappingは多段化しがちだ。実際このケースでもそうで、複数段のwrappingが入っていた。ところが問題の無限ループでは、一番手前のエラーオブジェクトと、一番奥のエラーオブジェクト（websocketライブラリのエラーオブジェクト）しかチェックしていない。実際にはcdpライブラリのcloseエラーは正しく存在していたが、この多段wrappingの中間にしかなかったので、無視される状態になっていた。そこで、このwrappingを一段ずつはがしてチェックするように修正をつくってupstreamした。これがマージされたのでこの問題はおしまい。
ところで、ちょっと勘のいいGoプログラマは気づいたかもしれないが、これはGo 1.13で導入されたerrors.Isと類似性がある( https://blog.golang.org/go1.13-errors )。Go 1.13ではerrors.Isという関数ができて、こういう「ほかのエラーオブジェクトをラップしたエラーオブジェクトとの一致チェック」というパターンを簡単にかけるようになった。errors.Isでは、エラーオブジェクトにUnwrapというメソッドがないかチェックする。あるならそれを使ってwrapを外す。どこかでtargetと一致するエラーがあったらtrueを返す。どこにもなくunwrapできなくなったらfalse。
ただ、cdpライブラリの状況ではこれはそのまま使えるものではない（とくに==でのチェックだと厳しい）。使えるようにするにしてもかなりの再設計が必要になるだろう。でもまあよくあるパターンとして比較的最近、標準でサポートされるような問題ではあるという話だったのは興味深かった。
最後は karino2.