WindowsイベントログをPowerShellを用いて扱う

前回（「Windowsで発生したことを確認できるWindowsイベントログを解説する」）、Windows Terminalの機能確定版が出た場合はそちらを紹介予定と記したが、12月17日にWindows Terminalの1912版が出るかと思いきや、17日になって12月31日に延期された。クリスマス休暇に入っちゃったのかと思ったが、いまだに開発は進行しているようである。まあ開発には計画変更が付きものなので、ゆっくりと待つことにしよう。今年はまだ1週間以上残されている。

githubのWindows Terminalの進行状況を示すページ。12月版のWindows Terminal（Terminal-1912）は、いまのところ50％の完成率。いまだ作業は進行しているようだ

さて、今回は前回の続きで、Windowsのイベントログを扱う。PowerShellを使って、実際に記録されているログから必要なものを取り出す方法を解説する。筆者としては、Widnows Updateで再起動が行われたときのオフライン（Windowsが起動していない状態）でのインストール作業の時間を測定したいと考えている。このため、いくつかのログを取り出し、その経過をログ上で再現してシャットダウンから起動するまでの時間を測定したい。

PowerShellでイベントログを処理する

前回も解説したように、イベントログを扱うにはいくつかの方法があるのだが、一番細かく制御できるのがPowerShellだ。さすがにマイクロソフトがシステム管理用に作っただけのことはある。

しかし、PowerShellにはイベントログを扱うコマンドが2つあり、同じイベントログを対象としているのにも関わらず、対象の扱い方やプロパティ名などに違いがある。こういうのはやめてほしいと思うのだが、片方はイベントビュアーに似たやり方やプロパティ名でイベントログを扱う。イベントログはWindowsでずっと使われてきたツールで、過去には現在とは違うログ形式を扱っていたため、プロパティ名などは過去のままになっている。おそらくevt形式からevtx形式への移行時に、見た目が変わらないようにしたのだと思われる。

実際のPowerShellコマンドとしては「Get-EventLog」と「Get-WinEvent」の2つがある。前者がイベントビュアーに似た方式で、後者がevtx形式に則したコマンドである。またGet-EventLogは、イベントビューアーで見ることができる現時点のログファイルのみを扱い、バックアップされたログファイルを扱わない。その分、コマンドのオプションで、ログ内のレコードの絞り込みや抽出が簡単にできる。

それに対して、Get-WinEventは、直接evtxファイルを開いて中身を扱うことができる。このため、現在のログファイルもバックアップされたログファイルも扱える（ただし、そのために管理者権限が必要）。ログ内のレコードの絞り込みなども不可能ではないが、-Pathオプションを使ってevtxファイルから読み込む場合には、XPathを使う「-FilterXPath」オプションを使わねばならない。

こっちは、ちょっとオプション指定が面倒だが、ログを全部出力させて、あとからWhere-Objectを使ってレコードを抽出するのに比べるとかなり速い、ざっと見たところ数～10倍程度の差が出る。ただし、柔軟な文字列比較などは、文字列比較はできないようなので、Where-Objectを適時併用するといいだろう。

evtx形式のログの構造

Get-WinEvent／Get-EventLogコマンドやイベントビューアーでイベントログを扱うとおぼろげながら、イベントログオブジェクトの構造が見えてくる。まず、すべてのイベントは、ログの登録元となるProviderName（イベントビューアーのソースに相当）とIdプロパティ（イベントビュアーではEventId）で区別されているようだ。つまり、ProviderNameごとにIdで何が起こったのかを区別できる。

イベントビューアーを見ると、さまざまな情報がテキストで表示されているが、これらの多くは、イベントレコード内の情報を元に、メッセージファイルなどからテキストを取り出して表示させているようだ。このため、Get-EventLog／Get-WinEventでは、ログの概略を示す「message」プロパティの中身が情報が見つからないというエラーメッセージになっていることがある。また、関数の中などで使うとエラーが発生することがある。

messageプロパティは、オブジェクトのように見えるが、実際にはevtxの中には記録されておらず、Idをキーにしてどこかにあるメッセージデータベースから入手したテキストとEventDataプロパティに含まれている情報を組みあわせて合成される文字列である。人間には、わかりやすいものの、たとえば、Windows 10のバージョンが違うと、メッセージデータベースが違うため、messageプロパティを作ることができなくなる。

また、イベントログは、記録された時刻を表す「TimeCreated」プロパティ（イベントビューアーの日付と時刻に相当）と別に記録された順番を示すRecordIdを持っている。時刻はミリ秒単位まで記録されているものの、複数の「ソース」が同時にログを記録しようとしているため、時間がずれる可能性がある。

このとき、RecordIdは、evtxファイルへの記録順を示すため、ソートするときに利用が可能だ。ただし、RecordIdはevtxファイルごとになるため、複数のevtxファイルを通して見る場合には注意が必要だ。

Windowsの機能アップデートやInsider Previewのインストールでは、旧バージョンのWindowsフォルダーは、C:\Windows.oldフォルダー以下に置かれるが、再起動前のログは、こっちにある。このため、2つのevtxファイルを合わせないとシャットダウンと起動のタイミングを調べることができない。このときRecordIdはそれぞれのevtxファイルで割り振られるため、つなげるときに注意が必要だ。

結局、evtxファイルから必要な情報を取り出すには、以下の表のプロパティのみを見れば良い。

再起動やその原因をログから再現する

ログには、シャットダウンや起動の記録があるが、これだけだと、原因がわからない。たとえば、Windows 10でもいきなり落ちてしまうこともあれば、ユーザーが再起動することもある。できれば、WindowsUpdateが原因の再起動のみをしらべたい。

まずは、シャットダウンと再起動だが、Windowsのカーネルからのログ「Microsoft-Windows-Kernel-General」にそれらしいものがある。Idとしては「12」（起動）、「13」（シャットダウン）がある。ただし、メッセージにある予定時間は、

id=12：`Properties.value[6]`に再起動予定時間
id=13：`Properties.value[0]`にシャットダウン予定時間

となる。では、Get-WinEventでこれを取り出してみよう。

Get-WinEvent -Path C:\Windows\system32\winevt\Logs\System.evtx -FilterXPath "Event/System[EventID=12 and Provider[@Name='Microsoft-Windows-Kernel-General']]" Select-Object RecordID,TimeCreated,Id,Message Sort-Object RecordID

これでリストから起動時のログを取り出すことができる。

Get-WinEventコマンドでシステム起動のログを取り出したところ

EventIDのところを13にすればシャットダウンのログを取り出せる。実際にやってみると、シャットダウンの予定時刻が起動の後になっていることがある。

簡単にコマンドのオプションを解説する。まず最初の「-Path C:\Windows\System32\winevt\Logs\System.evtx」は、システムログを指定している。

次の「-FilterXPath」以下は、XPathによる対象レコードの指定。イベントログはバイナリー形式だが、XMLとして扱えるようになっているようだ。イベントビューアーで、ソースが「Kernel-General」のものを選択し、詳細タブで「XMLで表示」を選ぶと、XML表現されたログレコードを見ることができる。

イベントビューアーを使うと、イベントログレコードのXML表現を見ることができる

全体はEventタグで囲われていて、その中に「System」タグと「EventData」タグがある。　「-FilterXPath」では、このXMLの中のタグと内容を指定して条件を満たすログレコードのみを取り出すわけだ。意味としてはEventIDが12、ProviderのName属性がMicrosoft-Windows-Kernel-Generalになっているものが指定されている。このXPathでは、[]の中は、同じタグレベルを表す。つまり、「Event/System[」は、Eventタグの中のSystemタグのさらに中という意味になり、EventIDとProviderは同じレベルにあることを示す。さらに@Nameは、Providerタグの属性「name=」の部分を表す。

その後ろには、出力するプロパティを選択する「Select-Object」と、RecordIdで並べ替えを行うSort-Objectが続く。

なお、Get-WinEventは、「System.Diagnostics.Eventing.Reader.EventLogRecord」というオブジェクトを出力する。このオブジェクトについては、上記のコマンドの「 select-Object……」以下を「 get-member」に置き換えてみるとわかる。

get-Memberコマンドを使えば、Get-WinEventが出力しているオブジェクトのTypeNameやプロパティ（Property）を見ることができる

これで、システムの起動時間がわかる。EventID=12を「EventID=13」とすれば、シャットダウンのログを取ることができ、2つを合わせると、再起動の様子を調べることが可能だ。

evtxファイルは中身はバイナリーで、しかも何も記録がなくても、70KBほどの大きさがある。しかも、XMLのように扱えることから、元のレコードは、XMLを圧縮したかのような形になっていると想像される。

これで思い出すのがWinFSである。Vistaに搭載されるはずだったWinFSでは、ファイルはすべてデータベースのようなレコード定義（スキーマ）を持ち、Windowsが自由にレコードやフィールドを扱うことができた。これは、XMLデータベースをベースにしていると言われ、ファイルのスキーマ（テンプレート）は、XML形式になっていた。evtx形式は、このWinFSの残骸なのではないか？そんな気がしてきた。

さて、次回は、再起動の理由やWindows Updateのログなどを扱い、Windows Updateから再起動に関わるログを取り出して、Excelで扱えるようにする。