WindowsServerでCustomLogをCloudWatch Logsへ転送する

By | 2016年6月24日

こんにちは。船田です。
普段ログの集約にはCloudWatch Logsをよく利用しています。いつもはLinuxで使うことがほとんどなのですが、Windows Serverでも同じことをしようとしたところ、少しつまづいてしまったので、つまづきポイントと回避方法について紹介します。

Linux版とは別物

Windows版もEC2上に常駐するエージェントがログを監視して転送するのは同じですが、エージェントの動作を定義する設定ファイルがJSON形式になっており、シンプルな書式のLinux版と比べるとちょっとややこしいです。
IISログやイベントログの転送については最初から雛形が用意されていますので、そちらを利用すれば特に苦労することは無いのですが、普通のテキスト形式のログを転送する場合、CustomLogタイプとして定義を作成しなければなりません。

以下は、CustomLogを転送する場合のサンプルの設定ファイルになります。

{
    "EngineConfiguration": {
        "PollInterval": "00:00:15",
        "Components": [
            {
                "Id": "CustomLogs",
                "FullName": "AWS.EC2.Windows.CloudWatch.CustomLog.CustomLogInputComponent,AWS.EC2.Windows.CloudWatch",
                "Parameters": {
                    "LogDirectoryPath": "C:\\CustomLogs\\",
                    "TimestampFormat": "yyyy-MM-dd HH:mm:ss",
                    "Encoding": "shift_jis",
                    "Filter": "sample.log",
                    "CultureName": "ja-JP",
                    "TimeZoneKind": "Local"
                }
            },
            {
                "Id": "CloudWatchLogs",
                "FullName": "AWS.EC2.Windows.CloudWatch.CloudWatchLogsOutput,AWS.EC2.Windows.CloudWatch",
                "Parameters": {
                    "AccessKey": "",
                    "SecretKey": "",
                    "Region": "ap-northeast-1",
                    "LogGroup": "SampleGroup",
                    "LogStream": "SampleStream"
                }
            }
        ],
        "Flows": {
            "Flows": 
            [
                "CustomLogs,CloudWatchLogs"
            ]
        }
    } 
}

大まかに以下のような書き方になっています。

  • 「”Id”:”CustomLogs”」のセクションで、取得対象のログを定義
  • 「”Id”:”CloudWatchLogs”」のセクションで、転送先を定義
  • 「”Flows”」のセクションで、「”Id”:”CustomLogs”」を「”Id”:”CloudWatchLogs”」へ転送することを定義
  •  
    です。
     
     
    ちょっとややこしいところとして、ログファイル名を指定する場合、「Filter」パラメータを使用する必要があるという点があります。
    「LogDirectoryPath」パラメータでログファイルの場所を指定できそうな感じがしますが、これはあくまでログが格納されているディレクトリを指定するもので、デフォルトではこのディレクトリ配下の全部のファイルが転送されるという動きになっています。
    ログファイル名を指定したい場合は「Filter」パラメータで、ファイル名を指定しなければなりません。
    (ドキュメントには「プレフィクスを指定」とありますが、ファイル名をそのまま書いても大丈夫です)
     
    そして、CustomLogタイプで一番課題になりそうな点として、ログの全行にタイムスタンプが必要になるというところがあります。
      
     
     

    ログの全行にタイムスタンプが必須

    こちらで結構苦労したのですが、CustomLogタイプでは、タイムスタンプがログの各行についていることが前提となっているようで、「TimestampFormat」パラメータにタイムスタンプの書式を指定しなければなりません。
    「TimestampFormat」パラメータ自体を指定しない場合、エラーにはなりませんが、ログ転送も実行されません。

    「”TimeStampFormat”:””」とすれば一応ログは転送されたのですが、改行が無視されて全てのログが1行として転送されてしまいました。。
     
     
     
    ということで、ログの各行にタイムスタンプが無い場合、CloudWatch Logsへログを転送するのは基本的に無理なようです。
    今回は、robocopyのログを転送させようとしていたのですが、robocopyのログにはタイムスタンプが無く、

    ...
    新しいファイル		71476234	c:\src\abcde.dat
    新しいファイル		182625290	c:\src\fuga.txt
    新しいファイル		      35	c:\src\fugafuga.doc
    新しいファイル		 1131654	c:\src\hoge.png
    新しいファイル		185771018	c:\src\hogehoge.exe
    新しいファイル		  121294	c:\src\mw32r27.lzh
    ...
    

    のようなフォーマットなので、手づまりになってしまいました。。
     

    タイムスタンプを無理やり埋め込む(sed利用)

    できればWindowsの標準の機能でなんとかしたかったのですが、どうにもならなそうでしたので、sedを使って環境変数の%date%と%time%から作成したタイムスタンプを各行に埋め込んでみることにします。

    sed for Windowsはhttp://gnuwin32.sourceforge.net/packages/sed.htmからダウンロードしました。

    robocopy c:\src c:\dest_path /MIR /COPYALL /NP /V /BYTES /NDL /NJH  | sed "s/^/%date:~0,4%-%date:~5,2%-%date:~8,2% %time:~0,8% /g" >> c:\CustomLogs\sample.log
    ...
    2016-06-22 16:06:24	  新しいファイル		71476234	c:\src\abcde.dat
    2016-06-22 16:06:24	  新しいファイル		182625290	c:\src\fuga.txt
    2016-06-22 16:06:24	  新しいファイル		      35	c:\src\fugafuga.doc
    2016-06-22 16:06:24	  新しいファイル		 1131654	c:\src\hoge.png
    2016-06-22 16:06:24	  新しいファイル		185771018	c:\src\hogehoge.exe
    2016-06-22 16:06:24	  新しいファイル		  121294	c:\src\mw32r27.lzh
    ...
    

    実行してみたところ、タイムスタンプはつくのですが、上記のように時刻が更新されませんでした。後続のログも全部同じ時刻のタイムスタンプが入ってしまいます。。

    確認してみると、

    D:\>echo 最初の時刻  :  %date% %time% && timeout 10 && echo 10秒後の時刻 : %date% %time%
    最初の時刻  :  2016/06/22 16:52:16.35
     0 秒待っています。続行するには何かキーを押してください ...
    10秒後の時刻 : 2016/06/22 16:52:16.35
    

    %date%と%time%は、コマンド実行中に更新されないようですね。
     
     
     

    タイムスタンプを無理やり埋め込む(awk利用)

    sedが悪いというより、更新されない環境変数を使用していたことが原因ですので、今度は自力で時刻を取得できるawkを使ってみることにしました。

    なお、日本語が通らないせいだと思いますが、mawk MBCS(http://www.vector.co.jp/soft/dl/win95/util/se080308.html)以外のawkではエラーがでて使用できませんでした。

    mawkでタイムスタンプを埋め込んだ結果が以下です。

    robocopy c:\src c:\dest_path /MIR /COPYALL /NP /V /BYTES /NDL /NJH | mawk32 '{print strftime("%Y-%m-%d %T") $0} {system("")}' >> c:\CustomLogs\sample.log
    ...
    2016-06-24 02:39:47	  新しいファイル		71476234	c:\src\abcde.dat
    2016-06-24 02:39:49	  新しいファイル		182625290	c:\src\fuga.txt
    2016-06-24 02:39:49	  新しいファイル		      35	c:\src\fugafuga.doc
    2016-06-24 02:39:49	  新しいファイル		 1131654	c:\src\hoge.png
    2016-06-24 02:39:52	  新しいファイル		185771018	c:\src\hogehoge.exe
    2016-06-24 02:39:52	  新しいファイル		  121294	c:\src\mw32r27.lzh
    ...
    

    ようやく、ログにリアルタイムで更新されるタイムスタンプを埋め込むことができました。

    CloudWatch Logs上でもログが転送されたことが確認できます。

    windows_customlog
     
     
    なお、{system(“”)}をつけないと、awkが出力をバッファしてしまうようで、

    ...
    2016-06-24 02:39:47	  新しいファイル		71476234	c:\src\abcde.dat
    2016-06-24 02:39:49	  新しいファイル		182625290	c:\src\fuga.txt
    2016-06-24 02:39:49	  新しいファイル		      35	c:\src\fugafuga.doc
    2016-06-24 02:39:49	  新し
    

    のように、行の途中で出力が欠けてしまうことがありました。
    エージェントはこのままログを転送し、CloudWatch Logsにも欠損のあるログが保存されてしまうので注意が必要です。
     
     
     

    まとめ

    WindowsServerからCloudWatch Logsへログを転送する場合、設定ファイルがJSONになっており、設定の書き方が違うのと、タイムスタンプが必須となることがつまづきポイントになりそうです。しかし、awkを使用してタイムスタンプを埋め込むことで、無理やりですがこれを回避できることがわかりました。

    ただ、今回はデータ転送時間が一番長くなるrobocopyのケースなので、あまり気にしなくてよいかと思っていますが、場合によってはawk呼びだしのオーバーヘッドが問題となるかも知れません。