以前 Mac OS X が不安定だと思っていたが、その原因は ESET Cyber Security Pro だった。
コンソール アプリケーションで .crash ファイルを確認すると、
と、こんな感じでクラッシュが多発していた。
ESET プロセスのクラッシュ直後に
などの症状に遭遇している。まるで Mac OS X が不安定な感じだが、ECSP がカーネルに悪影響を及ぼす（カーネル拡張処理中に異常終了する）ので様々な症状が出ていたようだ。
クラッシュ時の診断ファイルを見つつ分析して、動作が不安定となるバグを特定した。このバグは初期バージョンから V6.3 まで含まれていて V6.4 で修正された。数日に一回発生していた ESET プロセスのクラッシュは、半年で数回に激減した。V6.5 になってから一度も遭遇していない。
■多発するクラッシュの技術的な詳細
沢山ある .crash ファイルを眺めていると、バックトレース中の RefObje::Unref() が目に付いた。その先には参照が終わったであろうオブジェクトのデストラクタ[Object::~Object()形式の関数]がある。そこからメモリ解放に失敗するなど、メモリ内容の破壊が原因となっているようだった。
デストラクタの処理中なので、同じオブジェクトが別のスレッドで既に破棄されていた場合が考えられる。これを仮定してバックトレースを見ると、呼び出し元である RefObj::Unref() がスレッド セーフではない可能性に気付いた。
RefObj::Unref() はオブジェクトの参照カウントをデクリメントして０ならデストラクタを呼び出す、短くて簡単なプログラムだと名前から推定できる。ライセンス違反（その旨はサポートにも話をしてある）だが逆アセンブルして調査する事にした。プログラムを見ていくと、やっぱりスレッドセーフになっていなかった。
RefObj::Unref() での参照カウントのデクリメントと結果判定は
こんな風になっていてマルチスレッド プログラミングにおけるバグの典型
になっている。 C++ による記述だろうから、アトミック操作と判定処理で別々のメモリアクセスになっているのだろう。アトミック操作により参照カウントは RefObj::Unref() を呼び出した回数に応じた値で更新されるが、判定時に他のスレッドを同じ値と判断する可能性がある。運が悪いと、二つのスレッドから同じオブジェクトのデストラクタが各々呼び出されてしまう。クラッシュする場合はプログラムが異常終了するが、クラッシュしない場合は、メモリ内容を破壊したまま動作するので何が起きるか分からない。
V6.1 はコンパイル時の最適化オプションが入っておらずシンボルも残っていた。どうやらデバッグ版でビルドしたバイナリをリリースしていたようだ。お陰で RefObj::Unref() という名前の関数にあるバグを特定できた。
■クラッシュログ
サポートからの最初の回答は「正常に動作しています」だった。問い合わせ内容にクラッシュログを引用し、customer_info ログにクラッシュ ログが含まれていたのに「正常動作」と判断している。クラッシュログを見ていないことが分かった。サポートの技術担当の知識不足もあるだろうけど、クラッシュログ確認を指示されていないことも分かる。本来は ESET社からクラッシュログの収集指示が出ていないといけないが、不具合調査におけるクラッシュログの重要性を知らない技術担当でいいのか？と、基本的なことから問い合わせしないといけなかった。
不具合の状況について提出した資料では、動作と症状の詳細解説と修正方法を示しておいた。サポートの技術担当は理解したという返事が早々にあったが、そこからESET社が「内容が正しいようだ」と回答されるまで約三ヶ月かかっている。動作を理解できたのか非常に怪しいが修正された。経緯から ESET Cyber Security のプログラム担当はスキル不足と判断するしかないので、スキルアップをお願いしておいた。
原因調査ではクラッシュログは重要な情報だから、OSでは「○○が予期しない理由で終了しました」でレポートするときの送信内容になっている。
0コメント