Chromium OS で遭遇した厄介なバグの話。しばらく前に、電源管理周りの動き（画面の明るさを変更したり、バッテリの残量を表示したり）がたまにおかしくなる、というバグが報告された。たまに、というところが困りもので、たまにしか起きないから原因を調べるのが難しく、長らく未解決の状態が続いていた。
再現させる手法を確立させるべく同僚の一人が試行錯誤した結果、デバイスのサスペンドを無効にして、一晩くらい放置しておけば、だいたい再現するということがわかった。再現に一晩もかかるのは残念だが、こんな方法でもないよりはましである。再現したデバイスからログを取り出して吟味すると、 D-Bus （プロセス間通信のシステム）に関係したバグらしいことがわかった。
D-Bus 周りは私が結構コードを書いているので、この厄介なバグは私のところに回ってきた。まず調べたいのは、どのプロセスが壊れているか、ということだ。UIを処理しているブラウザ側の問題なのか、それとも power manager （電源周りのデーモン）なのか、どっちかはっきりさせたい。
私の直感は power manager が悪いというものだった。というのも、ちょうどこのバグが報告される少し前に、power manager にバグがあり、512回、明るさ調整キーを押すとそれ以上、明るさが変化しないというバグが修正されたところなのである。
これは power manager 内の D-Bus のメソッドの受付処理に問題があり（リプライを送り忘れていた）、512個のメソッド呼び出しが、処理済みにも関わらず、内部的なキューに溜まってしまい、それ以上の呼び出しを受け付けなくなるという、割としょうもないバグが原因であった。
今回も同じような問題に違いない、と思ってみてみると、 power manager の D-Bus メソッド周りのコードは整頓されていて、確実にリプライを送るように変更されていた。でもどこかに問題がまだ問題があるのかもしれない。
ブラウザなのか power manager なのかはっきりさせないことには話は進まぬ、と難儀していたところ、件の同僚から、彼のデバイスで問題が再現した、という一報をもらった。さっそく見せてもらっていろいろテストしてみたところ、おもしろいことがわかった。
power manager は問題なく動いていたのだが、ブラウザの方はというと、半分壊れていた。半分というところがポイントで、別のプロセスのメソッドを呼ぶことは問題なくできるのだが、メソッドの返り値が戻ってきても受け取れない、という状況になっていた。どうも外へ送るメッセージは処理できるけど、外から入ってくるメッセージは処理できないらしい。どうしてこなったんだろう？
D-Bus のメッセージは D-Busスレッドという独立したスレッドで処理している。もしこのスレッドが固まっているなら、外向きのメッセージも処理できないはずである。よって、スレッドは動いているはず。ということはあり得るのは次の二つのうちどちらか、あるいは複合的な問題か、だ。
1) プロセス間通信用のソケットにデータは届いているが、なぜか読み込まれず放置されている
2) データは読み込まれて内部的なキューに溜まっているが、なぜか処理されずに放置されている
スレッドの状況はどうなっているかはデバッガを使えば、ある程度は観測できるはずなので、デバッガをアタッチして調べてみよう、と思った瞬間、件のデバイスは別のバグでクラッシュして再起動してしまった。ああ、貴重な再現状態が消えてしまった！
こうなったら、ひたすらログを入れて (printf を入れて) 様子をみるしかない、と思ったが、一晩放置させている間、何も進まないのは気が重い。ログの方は最終手段でやるとして、ひとまずコードを読み返してみることにした。ブラウザのメッセージループと libdbus (D-Bus のライブラリ) を統合する部分は結構トリッキーな部分で、いかにもバグはありそうだったが、コードを読んだ限りでは正しそうに見える。
次に試みたのは、バグを再現させるべくストレステストを書くことだ。高負荷の状況では何かおかしなことが起きるのかもしれないと思い、いろいろな状況を試してみた。
1) 非同期メソッド呼び出しと同期メソッド呼び出しを同時に行ってみる
2) 非同期メソッド呼び出しを1000個くらい同時に行ってみる
3) 非同期メソッド呼び出しを1000個くらい同時に行い、全部タイムアウトさせる
ここまでは特に問題は起きなかった。が、次に試したテストでプログラムはついにクラッシュした。
4) 非同期メソッド呼び出しを1000個くらい同時に行い、それぞれ1MBのデータを送りつける
1MBから徐々にデータサイズを減らしていって、100KBくらいにしてもクラッシュは続いた。
が、もっと興味深いのはクラッシュのスタックトレースである。まったく予想外のところでクラッシュしていたのだ（下から読む）
logging::LogMessage::~LogMessage()
<- D-Bus スレッド上にいないのでクラッシュ！ (chrome内)
...
dbus::Bus::AssertOnDBusThread()
<- D-Busスレッド上にいるかチェック (chrome内)
dbus::Bus::OnToggleWatch()
<-- ソケットの状態が変わったので呼ばれた関数 (chrome内)
...
socket_live_messages_changed
<-- あれ？なんでソケットの状態をチェックしているの？ (libdbus内)
...
dbus_message_unref
<-- DBusMessage を解放 (libdbus内)
dbus::Message::~Message()
<- DBusMessage のラッパを解放 (chrome内)
dbus::Response::~Response()
dbus_message_unref() というのは DBusMessage というオブジェクトを解放する（リファレンスカウントをひとつ減らす）関数で、DBusMessage というのはIPCで送受信するデータを格納するためのコンテナである。
コンテナというのはデータを格納するための単純なオブジェクトで、解放したところで副作用などないはず。ましてや libdbus 内の内部的なソケットの状態が変わってしまうなんてあり得るのだろうか？ドキュメントにはそんなことは書かれていないぞ。
何かの間違いかと思い、ソースコードをみると、確かに libdbus 内にこのコードパスは存在した。どうも、キューに入ったデータが合計で 63MB を超えたら、ソケットの読み出しを停止するための安全装置が暗黙的に作動するらしく、ソケットの監視を停止するために、あらかじめ登録してあった dbus::Bus::OnToggleWatch() という関数が呼ばれる。が、DBusMessage を解放したのは D-Bus スレッドではなく、別のスレッドなので、D-Bus スレッド上にいるかをチェックする dbus::Bus::AssertOnDBusThread() のチェックに引っかかってクラッシュ、という顛末であった。
ただのコンテナなんだからどのスレッドで解放しても大丈夫と思っていたら大間違いで、 思わぬ副作用があった。アサーションでクラッシュするのはデバッグビルドだからで、リリース用のビルドではクラッシュせずに先に進んでしまう。本来とは違うスレッドでソケット周りの状態がいじくられてしまうのだから、これ以降のソケットからの読み込みがおかしくなっても不思議ではない。というわけで、件の問題はこのバグで大体説明がつく。
修正は簡単で、オブジェクトの開放を D-Bus スレッドで行うように変更するだけである。問題はこれで本当に件のバグが直ったかを調べる方で、これはまた一晩ほど放置しないといけない。この修正を入れて以来、幾晩か経っているが、幸い、バグは再現していない。どうやら直ったようだ。
単なるコンテナかと思いきや、実はグローバル変数を通じて内部的なソケットに暗黙的に紐づいていて、特定のしきい値を超えると安全装置（我々にとっては自爆装置であったが）が突如作動する、しかもドキュメントには書かれていないのだから、こんなのわかるわけがない、とぶつくさと言っていると、同僚から、バタフライ効果みたいなバグだな、と言われた。まったく風が吹けば桶屋が儲かる、である。しかも、たまにだけ。