Process Monitor活用事例 RAD Studioの起動エラーを解消

概要

C++Builder(RAD Studio)10.3.1にアドインをインストールしたらIDEが起動しなくなってしまった。
明日の納期ギリギリで再インストールなんてやってられないヤバい状況でProcess Monitorで原因を特定して解決したって話。

本家サイトにある「トラブルシューティングのヒント」と作者のブログをマネして物語風にしてみました。
画像多くて少し長いかも？

登場人物

Process Monitor

説明不要と思うけど、Windowsマニアが作った恐ろしく凄いツール群「Sysinternals Suite」の一品。
こういうのを作る人をスーパーハッカーと言うのだろう。マジ憧れるわ。
元々は個人レベルで作ってたのをMicrosoftが見つけて「うちに来てやってくれ」って事でほぼ公式ツールになったって経緯もすごい。
詳しくはここで。
https://technet.microsoft.com/ja-jp/sysinternals

フリーカーソル無効化アドイン

Delphiのテキストエディタはバージョン1の頃から何故か頑なに、頑なにフリーカーソル動作を継承している。
普通の開発ツールなら「フリーカーソル動作を無効にする」設定があっても良さそう、というかあって当然なんだけどそんな常識は通用しない世界。なんせキーのカスタマイズすらさせてくれないので。
仕方ないので有能なユーザーが2003年に作成してくれたアドインがこれ。
2003年といえば、Delphi6のフリー版がリリースされてDelphiの歴史上唯一輝いていた時期。
まさか作者さん(本当に感謝)も平成が終わった16年後にもなってまだこのプラグインが活躍してるなんて想像もしなかった事でしょう。

「フリーカーソル無効化アドイン」の正しいインストール方法については、こちらに記事があるのでどうぞ。
RAD Studio Community Editionでフリーカーソル無効化アドインを使う
この記事にある通り、C++Builderではビルドするのに9年前のC++Builder 2010からATLのソースを持ってくる必要があります。
これは面倒だと思っていたら、別のWebで「配布ファイルに含まれるビルド済みDLLがそのまま使える」という情報を見つけたので実行した結果が↓これ

※そもそも自分が使っているのはC++Builder単体ではなくてDelphiも使えるRAD Studio Proなので、Delphi版のソースをビルドしてインストールすれば良かったorz_

現象

RAD Studio 10.3.1に「フリーカーソル無効化アドイン」のビルド済みDLLをインストールすると、1回目・2回目の起動は正しく動作するが、3回目以降はRAD Studioがエラーで起動しない。
「リストのインデックスが範囲を超えています（12）」というお馴染みのエラーメッセージが表示されて起動が中断してしまう。

初動調査

アドインをアンインストール

現象はアドインのインストールに起因する事は確かなので、まずはインストール手順で追加したレジストリキーを削除してアンインストールする
→現象変わらず。マジかよ、この辺から心臓の鼓動が早くなる

レジストリを調査

アドインかIDEが他のレジストリに何か書いたんだろうと推測し、レジストリエディターで関連キー「Embarcadero/BDS/20.0」を眺める
→直下のサブキー数71個!!さらにネストしているサブキーもありとても調べきれない。絶望の淵に立たされる

エラーメッセージに表示されている（12）でレジストリを検索してみても、怪しいデータは見つからなかった。
→これについては最後にオチが

Process Monitorの出番

ちょっとここで、使い方を説明。

起動・設定

Process Monitorを起動して、直後に表示されるフィルタ設定をリセットする。
最初にフィルタ条件を設定しても良いんだけど、イメージ名を入力したりするのは面倒なので、取りあえず全部記録する。

フィルタを設定したら、Process Monitorのメインウインドウで左から3番目の虫眼鏡のボタンで記録を停止(Ctrl+E)し、左から5番目の消しゴムのボタンでログを消去(Ctrl+X)する。
画像は記録停止・ログ消去後の状態

記録開始し現象を再現する

虫眼鏡のボタンで記録開始(Ctrl+E)し、RAD Studioを起動する。
RAD Studioのエラーメッセージが表示されたら、記録停止(Ctrl+E)する。
ここでのポイントは、RAD Studioのエラーのメッセージボックスが表示されたままの状態でProcess Monitorの記録を停止する事。
問題はエラーメッセージ表示の直前に発生している事が多いので、メッセージボックスにOKボタンで応答してしまうと以降のイベントも記録されてしまい調査が面倒になるため。

4秒間で27万件！！のログが記録されている
Process Monitorはとにかく全部取って、見る時にフィルタで絞り込むというポリシーみたい。
最初はビビるけど安心して下さい、フィルタが優秀です。

プロセスでフィルタ

27万件も記録されているが、ここからがProcess Monitorの真骨頂。
左から9番目、ちょうど中央あたりの「プロセスツリーを表示(Ctrl+T)」でプロセスツリーを表示する。

プロセスツリーウインドウは、同じSysinternals SuitesのProcess Explorerに似た表示で、ログに記録されたプロセスツリーが表示されている。途中で終了したプロセスは薄く表示される。

この中からRAD Stuioのプロセスを探す。この場合はbds.exe。
正確なプロセス(実行ファイル名)を知らなくても、アプリのメインアイコンが表示されるから簡単に見つかる。些細な事に見えるけど非常にありがたい機能だと思う。
目的のプロセスをツリーで選択して、ウインドウ下部の「プロセスを含める」又は「サブツリーを含める」をクリック後、右下の「閉じる」ボタンでプロセスツリーを閉じる。
今回はサブプロセス起動は無いのでどちらを選んでも同じだけど、エラーの原因がサブプロセスの実行結果の事もあるのでその場合はサブツリーも含める必要がある。

フィルタ後のログ

RAD Studioのログだけが表示されて、8万件/27万に絞り込まれた。
ここから問題点を探す事になる。

推理と仮定

• エラーメッセージは、起動時のスプラッシュスクリーンにC++BuilderとDelphiが表示された直後という起動の早い段階で表示される
  
  
• このメッセージは、StringListなんかで境界を越えた時と同じ物なのでDelphiのRTLが例外を検出して表示しているはず
• 上記から起動プロセス中に予期せぬ異常が、正常に検出(例外をキャッチして、終了)している事が推測される
  
  → 中断の直前に実行しようとした処理（ファイルアクセス・レジストリ操作）に手掛かりがあるはず
  
  これがAV（Access Violationね、念のため）によるエラーだったりすると、Process Monitorではどうにもならないかもしれない

ログの調査

ログは下(新しい方)から遡って見ていく。順に見ていくと正常系の動作を追う事になり、これはこれで勉強というか研究になるのだけど、今回は早く復旧して明日の納期に備えなければならない。
今回のログの場合、末尾は「Microsoft Trusted Installer」関連のレジストリアクセスが大量に記録されていて4秒間のログの1/4くらいがこれで占められていた。
なかなか見つからないので、とりあえずRAD Studioの設定が保存されているレジストリキー「Embarcadero/BDS/20.0」で末尾から検索してみる。

すると…、いかにも怪しく文字化けしたレジストリキーへのアクセスを発見
しかもこのログの中でのRAD Studioのレジストリキーへの最後のアクセス、さらにサブキー「DisplayName」へのアクセス要求は「NAME NOT FOUND」が返されている。(「結果」列)
さらに、最後の最後のアクセス「Priority」のリード値がDWORDの12で、エラーメッセージの(12)と一致する。

ちなみに、この「結果」列では「BUFFER OVERFLOW」という恐怖の文字列がどうしても気になるけど、これは正常系の動作。
Win32のリード系APIはバッファサイズに0を指定すると「リードに必要なバッファサイズ」が返される事が多く、この場合のログが「BUFFER OVERFLOW」になるみたい。

対策

レジストリエディタで、ログで見つけた該当のキー「Embarcadero\BDS\20.0\Editor\Options\Known Editor Enhancements\商⹕敓呬扡湉敤瑮」を見に行くと、該当キーともう一つ文字化けしたキーがある。
この2個を削除したところ、無事起動した。ブラボー!!
ここまでの所要時間はおよそ30分。まあまあだね。
ちなみにこの記事でここまでかかった時間は、3時間。まだまだだね。

レジストリの値はDWORD:0x0000_000Cで10進では12、エラーメッセージの(12)はこれを表していたという訳。
12で検索してもヒットせず、0x0000000cで検索しても残念な事にヒットしないというオチでした。

考察

根本原因はレジストリの文字化けから推測すると、Unicode未対応のアドインをUnicode版のRAD Studioにインストールした事。
RAD Studioはバージョン2009で全面的にUnicodeに移行しており、Unicode対応後かそれ以前かで大きな壁がある。
「ビルド済みDLLがそのまま使える」情報を見つけた時に、この点は確かに気になったんだけどビンゴでした。
実際、IDE上でこんな事になってたし。右はDelphi版のソースをビルドしてインストール後の画像。

エラーメッセージの（12）という数字は、レジストリエントリ「Embarcadero\BDS\20.0\Editor\Options\Known Editor Enhancements」直下のサブキー11個のインデックス（0～10）に対して+2の値。

• 発生してるのはこんな流れと想像
  1. レジストリへの保存時に、2個ある文字化けした自分のサブキーが既にある事がなぜか認識出来ない
  2. 自分以外の項目が既に11個（0~10）あるので、自分のインデックスは11,12だ
  3. 11,12をレジストリにライトしたら、文字化けした既存項目が上書きされた
     
     文字化けしていない正常な項目9個の値は（0～8）になっているので、本来は9,10がライトされるべき
  4. 次回起動時に「商⹕敓呬扡湉敤瑮」の値は12が読める
  5. リストのインデックス（12）をアクセスしたが、実際に存在するのは（0～10）
  6. RTLが「リストのインデックスが範囲外（12）」エラーを検出した

という事で、完全に説明がつきました。めでたしめでたし。

まとめ

普通なら「初動調査」のアドインをアンインストールしたところで解決出来なければ、IDE再インストールかレジストリ全消しして再設定って事になるところだけど、Process Monitorのおかげで30分で解決できて、無事に翌日の納期も切り抜けられたというお話しでした。

手っ取り早い現状把握となぜか消せないファイルの対策で有名なのはProcess Explorerだけど、本当に困ったときに頼りになるのはProcess Minitorの方。
自分でもExplorerはよく使ってても、Monitorはとにかく大量のログに圧倒されてそっと終了させる事が多かったんだけど、Windows Sysinternals徹底解説 (Amazonリンク)を読んだら、第3部のトラブルシューティングの実例集が分かり易く、そして面白く書かれててProcess Monitorの本当の有用性が理解できたのでこの本お勧めです。

Process Monitorの事例はもう1件あるので、そちらもそのうち書きます。