PowerShellでApacheのログを集計する

この記事はPowerShell Advent Calendar 2012向けです。PowerShellはまだまだマスターには遠いですが、ありがたみがわかってきたので、書くことにしました。昨日の牟田口さんの記事を見るとAdd-TypeもPSObjectも使わずにPowerShellでクラスを作ってみろと言われているような気がしますが、誘惑を振り切りもともと想定していたネタです。

今日は、PowerShellを使ってApacheのログを集計してみます。Windowsを使っている人だったら、「bashとsedともげもげで十分じゃん」「Perl使うよ」と言わず、いいところがあるので見てください。特にログ集計でshもLLもわずらわしくなって、SQLiteやPostgreSQLにワンタイムのDBを作ってSQLでログ集計したことがある人におすすめです。

メリット

そもそもなにがうれしいの？という部分ですが、PowerShellには「パイプラインをオブジェクトが流れる」という特徴があり、これを利用するとshやPerlやRubyでの処理と比較して以下のようなメリットがあります。

• (shで処理する場合と比較して)パーサがパイプにテキストではなく、オブジェクト群を流せるので、再利用が容易。きちんとパイプに流れてきたオブジェクトを処理するコマンド（コマンドレット）が用意されている。空白区切りテキストを見て、「うーん、User-Agent何番目かな…1, 2, 3...」と数えなくてよい。
• (Perl等で処理する場合と比較して)sedやawk, sort等々をつなげて作っていくような考え方で、パイプに流して絞り込んでいく形で処理を記述できるので、試行錯誤で試していくのがラク。

要は、いいとこ取りというわけです。具体的にはこれから見ていきます。

対象ログ

今回対象とするのは、"combined"として定義されているタイプのログです。こんな感じです。

	127.0.0.1 - - [14/Dec/2012:18:30:24 +0900] "GET /pukiwiki/index.php?PukiWiki%2F1.4%2FManual%2FPlugin%2FA-D HTTP/1.1" 200 11450 "http://localhost/pukiwiki/index.php?WikiEngines" "Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"
	127.0.0.1 - - [14/Dec/2012:18:30:25 +0900] "GET /pukiwiki/skin/pukiwiki.css.php?charset=Shift_JIS HTTP/1.1" 200 2211 "http://localhost/pukiwiki/index.php?PukiWiki%2F1.4%2FManual%2FPlugin%2FA-D" "Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"
	127.0.0.1 - - [14/Dec/2012:18:30:25 +0900] "GET /pukiwiki/skin/pukiwiki.css.php?charset=Shift_JIS&media=print HTTP/1.1" 200 2154 "http://localhost/pukiwiki/index.php?PukiWiki%2F1.4%2FManual%2FPlugin%2FA-D" "Mozilla/5.0 (X11; Ubuntu; Linux i686; rv:12.0) Gecko/20100101 Firefox/12.0"

view raw access.log hosted with ❤ by GitHub

ひとつ正規表現を変えるだけなので、ちょっと違ってても大きな問題はないです。

パーサ(モジュール)の準備

まずは、ログのパーサを準備します。とはいっても、テキストにマッチしてオブジェクトをばんばん返す（流す）関数を書くだけです。
以下のスクリプトを（Win7/Vistaの場合）「C:\Users\（ユーザ名）\Documents\WindowsPowerShell\Modules\ApacheLogParser\ApacheLogParser.psm1」に配置します。

	function Read-ApacheLog
	{
	param(
	[Parameter(Mandatory=$true)]
	[string]
	$Path
	)
	Get-Content -Path $Path | Foreach-Object {
	# combined format
	if ($_ -notmatch "^(?<Host>.*?) (?<LogName>.*?) (?<User>.*?) \[(?<TimeString>.*?)\] `"(?<Request>.*?)`" (?<Status>.*?) (?<BytesSent>.*?) `"(?<Referer>.*?)`" `"(?<UserAgent>.*?)`"$") {
	throw "Invalid line: $_"
	}
	$entry = $matches
	$entry.Time = [DateTime]::ParseExact($entry.TimeString, "dd/MMM/yyyy:HH:mm:ss zzz", [System.Globalization.CultureInfo]::InvariantCulture)
	if ($entry.Request -match "^(?<Method>.*?) (?<Path>.*?) (?<Version>.*)$") {
	$entry.Method = $matches.Method
	$entry.Path = $matches.Path
	$entry.Version = $matches.Version
	}
	return New-Object PSObject -Property $entry
	}
	}

view raw ApacheLogParser.psm1 hosted with ❤ by GitHub

ここはあまりPowerShellっぽくないので、ポイントだけ書きます。

• 関数名は動詞-名詞にする。使える動詞は「Approved Verbs for Windows PowerShell Commands」を参照。
• 正規表現のマッチ結果である$matches ハッシュテーブルを活用する。
• PowerShellの文字列の特殊文字のエスケープは`。 例: `"。
• 正規表現では、名前つきキャプチャを活用する。 例: (?<Host>.*?)。こうすると、$matchesに指定した名前で入ってくる。
• パイプラインには、ハッシュをPSObjectにして流す。その際は、「New-Object」の-Propertyを使うと便利。

returnを書いているので、値を返すにはそうしないといけなそうに見えますが、このケースは別に書かなくても平気です。どういうことかというと、値を返すコマンドレットを使ったら、|Out-Nullとか、>$null とかして捨てないと、どんどん「流れ」ていってしまうのです。shでコマンドを実行したらstdout/stderrに出力が出るようなものです。不要なものは捨てるようにします。

Pathを受けとるのではなく、ログ本文を受け取るようにして、この関数自体をパイプで使うのが「ぽい」ような気もしますが、物理ファイルを指定するケースが多そうなのでとりあえずこの形にしました。需要に応じて変更するのがいいと思います。Perlの<>や、RubyのARGFみたいにstdin or 引数のファイルからのInputというのが簡単にできるといいのですが。

作業開始前の準備

使う段になったら、powershellを起動後、「Import-Module」で先程のモジュールをロードします。

PS C:\temp> Import-Module ApacheLogParser

試しに、「Read-ApacheLog」にログを食べさせてみましょう。そのまま出すと出すぎるので、「Select-Object（エイリアス：select）」の-Lastオプションで数を減らしたものが以下です。

各行の「 : 」の左側に書かれたプロパティ名を使って、さまざまな操作をしていくことになります。

実践

先程のパーサを使って、具体的に集計をしてみます。

トータルのアクセス数

もっともシンプルなものとして、全てのアクセス数を数えてみましょう。ここでは、いろいろ数えてくれる「Measure-Object(エイリアス: measure)」を使います。

PS C:\temp> Read-ApacheLog .\access.log | measure


Count    : 281
Average  :
Sum      :
Maximum  :
Minimum  :
Property :

281アクセスあることがわかりました（テスト用に作ったので少なくてごめんなさい）

特定のパスのみのアクセス数

先の「Measure-Object」に加えて、与えた条件を満たすもののみを流す「Where-Object(エイリアス：where、?)」を使います。

PS C:\temp> Read-ApacheLog .\access.log | where { $_.Path -eq "/favicon.ico" } | measure


Count    : 2
Average  :
Sum      :
Maximum  :
Minimum  :
Property :

"/favicon.ico"へのアクセスは2回あるようです。

ステータス別アクセス数

ステータスコードで分類してみましょう。今度は指定したプロパティが同じ値を持つオブジェクトをグループ化する「Group-Object(エイリアス：group)」と、表示順を整えるために「Sort-Object(エイリアス：sort)」を使います。

PS C:\temp> Read-ApacheLog .\access.log | group Status | sort Name

Count Name                      Group
----- ----                      -----
  259 200                       {@{Time=2012/12/14 0:09:47; Host=127.0.0.1; Request=OPTIONS * HTTP/1.0; TimeString=1...
    1 301                       {@{Time=2012/12/14 0:17:35; Host=10.0.2.2; Request=GET /mediawiki/index.php HTTP/1.1...
    1 302                       {@{Time=2012/12/14 0:17:44; Host=10.0.2.2; Request=POST /mediawiki/index.php?title=M...
   11 304                       {@{Time=2012/12/14 0:17:41; Host=10.0.2.2; Request=GET /mediawiki/skins/common/share...
    9 404                       {@{Time=2012/12/14 0:14:26; Host=10.0.2.2; Request=GET /favicon.ico HTTP/1.1; TimeSt...

200が多いですが、3xxや4xxもちらほらあることがわかります。

トップディレクトリごとのアクセス数

今度はトップディレクトリごとのアクセス数を集計してみましょう。「Group-Object」に置換を行うブロックを渡します（パスのファイル名部分と、サブディレクトリ以下をカットします）。

PS C:\temp> Read-ApacheLog .\access.log | group { $_.Path -replace '[^/]*$','' -replace '^(/.+?)/.*','$1' } | sort -Descending Count

Count Name                      Group
----- ----                      -----
  207 /pukiwiki                 {@{Time=2012/12/14 0:23:12; Host=127.0.0.1; Request=GET /pukiwiki/ HTTP/1.1; TimeStr...
   58 /mediawiki                {@{Time=2012/12/14 0:14:30; Host=10.0.2.2; Request=GET /mediawiki/ HTTP/1.1; TimeStr...
   11                           {@{Time=2012/12/14 0:09:47; Host=127.0.0.1; Request=OPTIONS * HTTP/1.0; TimeString=1...
    4 /                         {@{Time=2012/12/14 0:14:26; Host=10.0.2.2; Request=GET / HTTP/1.1; TimeString=14/Dec...
    1 /trac                     {@{Time=2012/12/14 0:17:51; Host=10.0.2.2; Request=GET /trac/ HTTP/1.1; TimeString=1...

"/pukiwiki"にたくさんアクセスされているようです。

時間帯別アクセス数

パーサスクリプトの中で、時刻はSystem.DateTime型に変換しておいたので「Hour」プロパティが使えます。今までと同じように「Group-Object」を使えばOKです。

PS C:\temp> Read-ApacheLog .\access.log | group { $_.Time.Hour }

Count Name                      Group
----- ----                      -----
  227 0                         {@{Time=2012/12/14 0:09:47; Host=127.0.0.1; Request=OPTIONS * HTTP/1.0; TimeString=1...
   54 18                        {@{Time=2012/12/14 18:30:05; Host=127.0.0.1; Request=GET /pukiwiki/index.php?InterWi...

例がとてもよくないのですが、0時台にたくさんアクセスがあり、18時台に少しアクセスがあるようです。他の時間帯には使われていません。

日付/時間帯別アクセス数をCSV出力する

CSV出力することも可能です。「Export-Csv」コマンドレットを使います。
（日付＋時間を作るには、若干トリッキーですがDateTime型の「Date」プロパティで日付部をもらい、「AddHours」メソッドを呼び出して時間を付加しています。）

PS C:\temp> Read-ApacheLog .\access.log | group { $_.Time.Date.AddHours($_.Time.Hour) } | select Name,Count | Export-Csv output.csv -Encoding default

平均レスポンスバイト数を調べる

combinedフォーマットには「%b：レスポンスのバイト数」があるので、レスポンスのサイズを集計することも可能です。「Where-Object」「Measure-Object」を使って、/pukiwiki以下の返答の平均バイト数を出してみましょう。

PS C:\temp> Read-ApacheLog .\access.log | where { $_.Path -match "/pukiwiki" } | measure -Property BytesSent -Average


Count    : 207
Average  : 3019.21256038647
Sum      :
Maximum  :
Minimum  :
Property : BytesSent

このようにひとつのログ形式に対して、パーサを1回作ってあげれば、あとは直感的に集計処理が可能になります。量的にどこまで耐えられるかは検証していないのですが、GUIな表計算ソフトでうんぬんするよりはさっくりできると思います。もちろんApacheのログでなくて、テキストのログは同じように処理することが可能ですので、しょっちゅうログを処理するような方は、試してみてはいかがでしょうか。