一時レジストリ プロファイルの問題

マイクロソフト カスタマー サポート サービス (CSS) は Sysinternals ツールの最大の得意先の 1 つです。CSS からは、このツールを使用して解決された興味深い問題について時々メールをいただきます。今回お伝えする問題は、多くのユーザーに影響を及ぼし、あまり知られていない Process Monitor の機能がトラブルシューティング プロセスで使用されたため、特に興味深いものです。この問題は、ある顧客からマイクロソフト サポートへの問い合わせに始まります。数人のユーザーがシステムにログオンする際に、次のエラー メッセージが表示されることがあるいうことでした。

図 1

これにより、Windows は、ユーザーのログオン セッションのための一時プロファイルを作成しました。各ユーザー プロファイルは、ディレクトリ %UserProfile% と、このディレクトリに格納されるレジストリ ハイブ ファイル %UserProfile%\Ntuser.dat で構成されます。アプリケーションは、このディレクトリにユーザー固有の設定やデータ ファイルを保存します。また、ユーザーがログインすると Winlogon プロセスがレジストリ ハイブ ファイルをロードします。アプリケーションは、HKEY_CURRENT_USER (HKCU) ルート キーを参照するレジストリ関数を呼び出して、レジストリ ハイブにユーザー設定を格納します。ユーザーが自分のプロファイルにアクセスできなくなるということは、すべての設定が失われ、自分のプロファイル ディレクトリに格納されているファイルにアクセスできなくなるということなので、重大な問題です。多くの場合は、ユーザーが会社のサポート デスクに問い合わせると、問題が自然に解決されるまで再起動とログインをやり直してみるように指示されます。

マイクロソフト サポートは、他の問題の場合と同様に、最初に、システム構成、インストールされているソフトウェア、および最近会社がシステムに対して行った変更について尋ねました。この事例で明らかになったこととして、問題が発生したシステムではすべて、最近、Citrix Corporation の ICA クライアントというリモート デスクトップ アプリケーションが新しいバージョンにアップグレードされていました。マイクロソフトは、この新しいクライアントの問題を認識しているかどうか Citrix サポートに問い合わせました。Citrix は問題を認識していませんでしたが、調査してみるということでした。

ICA クライアントのアップグレードがプロファイルの問題の原因であるかどうかは不明でしたが、マイクロソフト サポートは、顧客に、プロファイル ログを有効にするように指示しました。プロファイル ログを有効にするには、サポート技術情報の記事「製品版 Windows でユーザー環境デバッグ ログを有効にする方法」に記載されているようにレジストリ キーを設定します。顧客が必要なレジストリ変更を行うスクリプトをシステムに適用すると間もなく、別のユーザーからプロファイルの問題に関する問い合わせがありました。顧客は、システムの %SystemRoot%\Debug\UserMode\Userenv.log からプロファイル ログをコピーしてマイクロソフトに送りました。このログで原因は特定できませんでしたが、重要な手がかりが得られました。このログは、ユーザーのプロファイルがロードに失敗したのはエラー 32 (ERROR_SHARING_VIOLATION) が原因であることを示していました。

図 2 [拡大図]

プロセスがファイルを開く際は、そのファイルに対してどのような種類の共有が許可されるかを指定します。たとえば、プロセスがファイルに書き込みを行う場合、他のプロセスにそのファイルの読み取りは許可しても、書き込みは許可しないように指定できます。このログ ファイルにある共有違反は、ログオン プロセスがファイルを開く方法とは互換性のない方法で、別のプロセスがユーザーのレジストリ ハイブを開いていたことを示していました。

この間にも、世界中の顧客からマイクロソフトと Citrix にこの問題に関する問い合わせが寄せられていました。そして、それらの顧客もすべて新しい ICA クライアントを展開していました。間もなく、Citrix サポートから、この共有違反は ICA クライアントのプロセスの 1 つ (Ssonvr.exe) が原因である疑いがあると報告されました。ICA クライアントは、インストール時に、Windows Multiple Provider Notification Application (%SystemRoot%\System32\Mpnotify.exe) がシステムの起動時に呼び出すネットワーク プロバイダー DLL (Pnsson.dll) を登録します。Mpnotify.exe 自体は、Winlogon プロセスによってログオン時に起動されます。Citrix の通知 DLL は、ユーザーのログオンとは非同期に Ssonvr.exe プロセスを起動します。

図 3 [拡大図]

この仮説の唯一の問題点は、このプロセスはユーザー レジストリ プロファイルをロードしようとはせず、プロファイルからキーまたは値を読み取りすらしないと Citrix の開発者が断言したことでした。マイクロソフトと Citrix は途方に暮れました。

マイクロソフトは、診断情報を追加した Winlogon とカーネルを作成し、問題のクライアントと同じように構成された実験システムで問題の再現を試みましたが、うまくいきませんでした。顧客も、変更された Windows イメージではこの問題を再現できませんでした。恐らく、これらのイメージではシステムの何らかのタイミングが変化したために問題が回避されたのだと思われます。この時点で、マイクロソフト サポートのエンジニアは、Process Monitor を使用してログオン アクティビティのトレースをキャプチャすることを顧客に提案しました。

ログオン操作を記録できるように Process Monitor を設定する方法は 2 つあります。1 つめの方法は、ログオフから次のログオンまで Process Monitor を実行したままにするために、Sysinternals PsExec (英語) を使用して Process Monitor をセッション 0 で起動します。もう 1 つの方法は、ブート ログ機能を使用して、起動の最初期段階 (ログオンを含む) からのアクティビティをキャプチャします。このエンジニアは後者の方法を選択しました。そこで、繰り返し問題が発生するシステムで Process Monitor を実行し、Process Monitor の [オプション] メニューから [ブート ログを有効にする] を選択し、再起動するという手順を、問題が再現されるまで繰り返すように顧客に指示しました。この手順は、起動プロセスの初期段階に Process Monitor ドライバーをロードして、アクティビティを %SystemRoot%\Procmon.pmb に記録するように設定します。ユーザーがログオンして問題が発生したら、Process Monitor を再度実行します。この時点で、ドライバーはログを停止し、Process Monitor はブート ログを標準の Process Monitor ログ ファイルに変換します。

ユーザーは、何度かこの手順を実行した後、ブート ログ ファイルをキャプチャしてマイクロソフトに提出しました。マイクロソフト サポートのエンジニアがそのログを確認したところ、Winlogon がユーザーのレジストリ ハイブをロードしようとしたときに、共有違反エラーが発生していたことがわかりました。

図 4 [拡大図]

このエラーの直前の操作から明らかになったことは、ハイブを開いたプロセスが Ssonsvr.exe であることでした。なぜ Ssonsvr.exe がレジストリ ハイブを開いたのでしょうか。この疑問に答えるため、エンジニアは Process Monitor のスタック トレース機能を利用しました。Process Monitor は、各操作の呼び出しスタックをキャプチャします。呼び出しスタックには、操作に関与する関数呼び出しのネスト構造が示されます。この呼び出しスタックを参照することで、操作を実行したプロセスだけからは明らかにならない操作の根本原因を特定できることがよくあります。たとえば、プロセスにロードされたある DLL によって操作が実行されたことがスタックからわかることがあります。また、シンボルを設定し、シンボルを含む Windows イメージなどのイメージから呼び出しが行われた場合は、関与した関数の名前がわかることもあります。

Ssonsvr.exe が Ntuser.dat ファイルを開く操作のスタックには、操作の実際の原因は Ssonsvr.exe ではなく、Windows Windows Logical Prefetcher であることが示されていました。

図 5

Windows XP で導入された Logical Prefetcher は、プロセス起動の最初の 10 秒間を監視するカーネル コンポーネントです。その時間内にプロセスからアクセスされるディレクトリやファイルの部分を %SystemRoot%\Prefetch 内のファイルに記録します。Logical Prefetcher は、異なるディレクトリにある同じ名前の複数の実行可能ファイルがそれぞれのプリフェッチ ファイルを使用できるように、実行可能ファイル イメージ名とイメージが格納されているパスのハッシュを連結したファイル名 (NOTEPAD.EXE-D8414F97.pf など) をプリフェッチ ファイルに付けます。次のように、Sysinternals の Strings (英語) ユーティリティを使用してプリフェッチ ファイルをスキャンすることで、アプリケーションが前回の起動時に参照した内容として Logical Prefetcher が記録したファイルやディレクトリを実際に確認できます。

strings <prefetch file>

次にこのアプリケーションが起動すると、プロセスの最初のスレッドのコンテキストで Logical Prefetcher が実行されて、プリフェッチ ファイルが検索されます。プリフェッチ ファイルが存在する場合、Logical Prefetcher はそこにリストされたディレクトリをそれぞれ開き、各ディレクトリのメタデータがまだない場合は、それをメモリに読み込みます。次に、Logical Prefetcher は、プリフェッチ ファイルにリストされたファイルをそれぞれ解析し、前回アプリケーションが実行されたときにアクセスされた部分を参照して、それらもメモリに読み込みます。このように Logical Prefetcher は、一般のアプリケーションが起動時に行うようにファイル データに対して小さなランダム アクセスを繰り返すのではなく、連続的な I/O をまとめて行うようにすることで、アプリケーションの起動時間を短縮します。

しかし、プロファイルの問題に Logical Prefetcher が関係することがわかっても、さらに疑問が増すだけでした。Ssonsvr.exe 自体はレジストリ プロファイルにアクセスしないのに、なぜ Logical Prefetcher は Ssonsvr.exe のコンテキストでユーザーのハイブ ファイルをプリフェッチしたのでしょうか。マイクロソフト サポートは、Logical Prefetcher の開発チームに問い合わせました。開発者によると、Windows XP のレジストリは、キャッシュされたファイル I/O 操作を使用してメモリに読み込まれます。つまり、Cache Manager の先読みスレッドが、ハイブの一部を積極的に先読みするということでした。先読みスレッドが System プロセス内で実行され、Logical Prefethcer が System プロセスのアクティビティを現在起動中のプロセスに関連付けるため、システムの起動とログオンの間にプロセスの起動とアクティビティが特定のタイミングと順序で行われる結果、Logical Prefetcher からはハイブ アクセスが Ssonsvr.exe の起動操作の一環として認識される可能性があります。この順序が次回の起動とログオンで多少異なると、キャプチャしたブート ログに示されているように、Winlogon が Logical Prefetcher と競合する可能性があります。

Logical Prefetcher は、システム内の他のアクティビティから透過的に実行されるはずですが、Windows XP システムでは、Logical Prefetcher のファイル参照によってこのような共有違反が発生する可能性があります (サーバー システムでは、Logical Prefetcher は起動アクティビティのみをプリフェッチします。これは、起動プロセスが進行する前に同期的に行われます)。このため、Windows Vista および Windows 7 システムの Logical Prefetcher は、ファイル システム ミニフィルター ドライバー Fileinfo (%SystemRoot%\System32\Drivers\Fileinfo.sys) を使用して、共有違反につながる潜在的な競合を監視します。また、Logical Prefetcher がファイルを閉じるまで Logical Prefetcher からアクセスされているファイルをさらに開く操作を抑止することで、共有違反を回避します。

ついに問題の原因が判明しました。マイクロソフトと Citrix は顧客に適用してもらう回避策について検討すると共に、Citrix は共有違反を回避するために ICA クライアントのアップデートに取り掛かりました。1 つの回避策は、アプリケーションのプリフェッチを無効にすることです。もう 1 つの回避策は、Ssonsvr.exe プリフェッチ ファイルを削除するログオフ スクリプトを作成することです。Citrix は、Citrix Knowledge Base (英語)の記事で回避策を公開し、マイクロソフトは、マイクロソフト サポート技術情報の記事で回避策を公開しています。数日後、ICA クライアントのアップデートが公開されました。このアップデートでは、Ssonsvr.exe の起動 10 秒後に Mpnotify.exe に制御が返すようにネットワーク プロバイダー DLL が変更されました。Winlogon は Mpnotify の終了を待ってからユーザーをログオンさせるため、Logical Prefetcher が Winlogon によるユーザーのハイブへのアクセスを Ssonsvr.exe の起動に関連付けることはありません。

冒頭でも述べましたが、根本原因の分析のために、ほとんど知られていない Process Monitor 機能、ブート ログ、およびスタック トレースの威力を具体的に示す例として、これは特に興味深い問題であると思いました。この 2 つの主要なツールは、あらゆるユーザーのトラブルシューティングに有効な武器になります。また、修正プログラムがない場合や、ベンダーが修正プログラムを提供するまで待つ必要がある場合でも、トラブルシューティングによって回避策が得られることもあるという成功例を示しています。Process Monitor を使用して、また 1 つ問題が解決されました。未解決の問題に関するスクリーン ショットやログ ファイルがあれば、引き続き募集しています。

公開: 2009 年 8 月 10 日月曜日 5:00 PM 投稿者: markrussinovich (英語)