Ruby で Windows7 のイベントログを解析

Ruby

Windows 7 でのログオン／ログオフの時間が知りたかったので、120MBくらいあるセキュリティイベントのログ（XMLでエクスポートしたもの）を解析していた。
まず、標準のREXMLを素直に使ったのだが、MacBook AirではCPUが100%に張り付いてしまい、一晩たってもパースが完了しない。
（なお、Windows のイベントログはXMLで落としたそのままの状態だとの連続になっており、root タグが無くてパースできないので、まずファイルの先頭と末尾にを付加する必要がそもそもある。）
検索してみるとREXMLの遅さには定評がある？ようで（かなり頑張ってはいるがピュアRubyなのでしょうがないらしい。）、他にはLibXML、Nokogiriといったところが選択肢としてあるようだ。（他は未調査）

LibXML

公式のドキュメント
http://libxml.rubyforge.org/rdoc/
を見ると、巨大なファイルにはParserじゃなくてReaderを使ってね、とある。
ただ、Readerはノードを一つ一つ読み込んで行くカーソルライクなAPIみたいなので、xpathとか使えずに実装に難儀しそうに思い、多少メモリ食ってもいいか、ってことで、Parserを使ってみる。（この辺はコードサンプルが少なくて誤解している可能性があるので、怪しいかも。）

# gem install libxml-ruby

でインストールした後、公式ドキュメントにあるように

require "rubygems"
require "xml/libxml"

XML::Document.io(file_io)

してみたところ、（自分のコードがIOを渡す設計になっていたので）

Fatal error: Input is not proper UTF-8, indicate encoding !
Bytes: 0x83 0x70 0x83 0x58 at :1430.
Entity: line 89136: error: xmlSAX2Characters: huge text node: out of memory

と怒られてしまう。どうやら文字コードの問題と、ドキュメントがでかすぎるよってことのようだ。
わりかし予想通りであった。
文字コードはきっとShift JISを渡さなきゃいけないっぽくて、巨大なファイルはやっぱり無理なのだろうか、と思ってドキュメントを色々見ていると、

XML::Document.io(io) → XML::Document
XML::Document.io(io, :encoding => XML::Encoding::UTF_8,
:options => XML::Parser::Options::NOENT
:base_uri="http://libxml.org") → XML::Document

とあって、オプションを指定できるみたい。
どんなオプションが渡せるのか、XML::Parser::Optionsのドキュメントを見てみると、

HUGE	=	INT2NUM(XML_PARSE_HUGE)	 	 relax any hardcoded limit from the parser

てのがあった。
これを渡せばいいんじゃね？ってことで、

XML::Document.io(file_io, 
:encoding => XML::Encoding::SHIFT_JIS, 
:options => XML::Parser::Options::HUGE)

としたら無事パースできた。（数分で終わった。）
しかし、その後パースされたDocumentオブジェクトを色々弄っていると、segmentation faultが多発。
うーんと思ってまたドキュメントを眺めていると、XML::Document#findのところに

As a result, the associated document may be freed before the node list, which will cause a segmentation fault. To avoid this, use the following (non-ruby like) coding style:

nodes = doc.find('/header')
nodes.each do |node|
  ... do stuff ...
end

# nodes = nil # GC.start

と書いてあったので、findした後にGC.startしてみると、出なくなった。
しかし、全然関係ない部分を直したりしていると突然再発したりする。
やはり、こんなでかいファイルをParserで処理しようとすることに無理があるようだ。

Nokogiri

ここで、諦めてNokogiriを使うことにした。

# gem install nokogiri

としてインストール。
NokogiriにもReaderというLibXMLと似たようなAPIがありそうだったが、やはり同一の理由から普通にパースする方針を取った。
しかし、5分待ってもCPUが100%のまま終わる気配がない。
そもそも、実行するたびに5分も10分も待つのはつらいので、結局100行くらいのファイルに分割してNokogiriでパース、という手段に落ち着いた。
（最初からこうすればREXMLでも良かった可能性は大きいw）
Nokogiriに関してはWebに資料も多いし、APIも分かりやすいのでほとんどはまらなかったのだけど、イベントログは

<Event xmlns='http://schemas.microsoft.com/win/2004/08/events/event'

というnamespaceを持っているため、パースする際に

require "rubygems"
require "nokogiri"

doc = Nokogiri::XML(file_io)
doc.xpath("/Events/ms:Event", { "ms" => "http://schemas.microsoft.com/win/2004/08/events/event" }) do |event|
...
end

のようにする必要があった。

※下記を参考にさせていただいた。
http://d.hatena.ne.jp/Gimite/20090926/1253964626

ログの解析について

次に実際にログを解析する際のポイントとなった事項をメモ。

ログオン/ログオフ時間の解析

当初EventIDを使い、
http://support.microsoft.com/kb/947226/ja
あたりを見て、下のようにログオン/ログオフの時間だけ拾おうとした。
（このマシンを使用するユーザーは自分のみの前提。）

def auth_event?
    if event_id_node
      return ["4624", "4634", "4647"].include?(event_id_node.text)
    end
    return false
  end

しかし、この方法だと、ありえない深夜や早朝の時間帯にログオンしていたことになってしまう。
（裏で動いているサービス等が出力したログなのだろうか？謎である。）
違うアプローチとして、xpathで言うところの

  • /Events/ms:Event/ms:EventData/ms:Data[@Name='TargetUserName']
  • /Events/ms:Event/ms:EventData/ms:Data[@Name='SubjectUserName']

に該当するノードのtextに自分のログオンIDが含まれるイベントの最小、最大を取ったところ、どうもそれらしいログオンの時間帯になった。
（正しいかどうかは謎だが、実情から考えると正しげ。この辺は結構情報が錯綜しているような気がする。）

イベントの起こった時間

こちらは当然といえば当然なのだが、

  • /Events/ms:Event/ms:System/ms:TimeCreated

の時間はGMTなので、日本時間にするには+9時間する必要がある。