はじめに

珍しく仕事でバッチ処理を書く機会があり、PowerShell で書いてみました。その際に、ログを残すべきと思ったものの、普段書き慣れないため満足できる書き方ができませんでした。そのため PowerShell では、多分こんな感じでログを出力できたら嬉しいと思うものを形にしてみました。

成果物と README.md は github に置きました。せっかちな方はそちらを参照ください。

asterisk9101/Invoke-Logger

バッチログについて

バッチ処理に処理の経過を記録するログは付き物です。処理が転けた場合に、原因を追求するために参考となるログが理想ではありますが、欲しい情報が残っていないログに遭遇することは珍しくありません。また、ログが複数のファイルに分割されている場合に、横断的にログを参照できたりすると便利ですが、実際は記録形式がバラバラで大変見づらく、時系列に並べ直すにも手間がかかる場合があり、大変辛いことがあります。

バッチ処理におけるログは単純に echo しているだけであることが多く、作った人によって書き方の流派があります。そのため、欲しい情報が残っていなかったり、ログファイル毎のフォーマットがバラバラになって横断的な検索に手間が掛かるという問題が発生すると考えられます。そこで、ログを記録するための共通のインターフェース（コマンド）を作成することで、ログ出力の手間を軽減しつつ最低限の情報を含んだログが残せるのではないかと考えました。

環境について

Windows10, PowerShell v5 で作成しました。PowerShell v2 では不具合を見つけましたが根本的な対処はしていません。

コマンドと機能について

ログを記録するためのインターフェース（コマンド）として Invoke-Logger と New-LoggerConfig を作成しました。

Invoke-Logger は実際にログを出力するためのコマンドで、エイリアスとして logger を使うことができます。Invoke-Logger はログ出力にだけ集中できるようにするため、ほとんどの動作はデフォルトで決まっており、明示的に指定する必要があるパラメータはログレベルとログメッセージだけです。

# ログレベルとメッセージを指定すれば動作する
Invoke-Logger -Info hogehoge

例えば、バッチログに必要な最低限の情報として以下の項目が考えられます。

ログが記録された時間
実行されたホストの名前
実行したユーザの名前
実行されたスクリプトファイルの名前

Invoke-Logger は、明示的に指定されたログレベルとログメッセージに、これらの情報を自動的に追加して出力します。これらの情報はそれぞれタブ区切りで出力されるため、隣接する情報が融合してしまうことはありません。ログが記録された時間はミリ秒単位で記録され、時系列にソートしたときに、レコードが入れ替わってしまうことを防ぎます。実行されたホストの名前と実行したユーザの名前は、環境変数から取得します。スクリプトファイルの名前は（フルパスではなく）ファイル名だけが記録されます。バッチ処理のレベルであればファル名が重複することは少ないため、ログの読みやすさを保ちつつ無用なファイルサイズの肥大を抑制するメリットがあります。

Invoke-Logger は、一連の情報を1行にまとめて（改行を全て除去して）コンソールに出力します。Invoke-Logger は、デフォルトではファイルに出力しません。ただ実際にはファイルに残す必要があるので、このデフォルトの動作は変更できなければ困ります。

New-LoggerConfig は、Invoke-Logger のデフォルトの動作を変更するために使用します。New-LoggerConfig は、Invoke-Logger の動作を指定するパラメータを受け取って、それらを詰め込んだ PSObject を生成します。この PSObject を $Global:LoggerActionPreference にセットすることで、Invoke-Logger の動作を変更することができます。

# Invoke-Logger は環境変数を参照して動作を変更する
$Global:LoggerActionPreference = New-LoggerConfig -File C:\temp\logger.log

Invoke-Logger の動作を、もっと細かく弄りたいと思うかもしれません。その場合も New-LoggerConfig を使って設定することができます。例えば、ログに書き込むと同時に画面にも表示して欲しい場合は以下のように指定します。

# -File と -Action を同時に指定すると -Action が優先される
$Global:LoggerActionPreference = New-LoggerConfig -Action {
    write-output $_
    write-output $_ | Out-File -Append C:\temp\logger.log
}

Invoke-Logger はスクリプトブロックで動作が指定できるため、ほとんどのロガーよりも拡張性に優れています。例えばログを書き込む前にファイルサイズを確認して、サイズが大きすぎる場合はファイルをローテーションすることもできます。実行される環境に応じて動的に出力先を変更することもできます。

New-LoggerConfig は、-Action の他にも、ログの区切り文字、日付のフォーマット、ログのフォーマットなどを個別に変更できます。-Action が複雑になりすぎないよう使い分けることができます。

検証

テストには Pester を使いました。直接テストコードを見た方が分かりやすいと思うので Invoke-Logger/Invoke-Logger.Tests.ps1 を参照ください。

類似するツールとの比較

PowerShell スクリプトの実行ログを出力する
考慮されていることはほぼ同じでしたが、ログのパスなどハードコードする必要があるためツールというより書捨ての関数という感じでした。Invoke-Logger であればパラメータを与えられるので関数の中を弄る必要はありません。

PowerShell でのログ出力を頑張っていたら logger オブジェクトができた - Qiita
似たようなことを考えている方。クロージャが使われてカッコイイ。ログを書き込む際の書き方がコマンドレット的ではなくなっているのですが、Invoke-Logger であれば一般的なコマンドレットと同じインターフェースです。

PowerShellとNLog | 84zume Works
多機能みたいなのですが、仕事でフリーのツールを使うのはあまり現実的ではない（悲しい）。

PowerShellからlog4netでロガー作って使ってみた - YOMON8.NET
NLog と同じく多機能故に大仰なので導入しづらい。ログが重要な仕事であればあるいは。。。

類似するツールは多数あるようなのですが、必要十分であるが故に簡素すぎたり、バッチのログという意味では多機能すぎて導入しづらかったり、ちょうど良いツールを見つけることはできませんでした。

おわりに

簡単なツールを作るだけのつもりが、考えると色々カスタマイズしたくなってしまい上手くまとまったか不明です(けっきょく拡張性をもたせて逃げました)。今回作成した Invoke-Logger は、ログメッセージに時間などを追記しているだけで、振り返ってみると全く面白みに欠けていることに気づき、若干の悲しさの中にあります。

ツールを作る過程で PowerShell の「高度な関数」と「begin ~ process ~ end ブロック」について理解が深まりました。今回得たものとしては、ツール自体よりも、ツールを作るための知識の方が大きいような気がします。これからもツール職人として頑張ろうと思います（いいのかそれで）。

ありそうなQ&A

デフォルトの挙動がコンソール出力だけな（ファイル出力しない）のは何故？
ps1 スクリプトは大抵バッチファイルから呼ばれるので、バッチファイル側で ps1 スクリプトの出力をログファイルにリダイレクトする使い方をするのであれば、コンソール出力だけの方が自然だと思ったからです。また、logger の /var/log/messages のように決まった出力先が思いつかなかったからです。

文字列しか記録しないのは PowerShell のコンセプト的に無理があるのでは？
PowerShell -v 5 辺りからは ConvertTo-Json -Compress でシリアライズできるので大きな問題にはならない認識です。

グローバル変数を使うのが気持ち悪い
冗長になりますが Invoke-Logger -Config を利用してください。

[ValidateSet("Info","Warn","Error")]で良くない？
-Level Info -Message hogehoge よりも -Info hogehoge って書きたかったんです。

Invokeの乱用は良くない、命名にはこだわるべき
すみません。