ログ出力で各行の先頭に日時を挿入する

例えば、MovableTypeのtools/run-periodic-tasksをdaemonモードで起動した場合、標準エラー出力に出てくるログには日時が記載されておらず、あとで追っかけるのが至極困難なんですね。

tools/run-periodic-tasks --daemon >/var/log/mt.log 2>&1

TheSchwartz::work_once found no jobs
TheSchwartz::work_once found no jobs
TheSchwartz::work_once found no jobs
...

じゃあパイプで渡して日時を追加すればいいじゃない。色々なやり方を調べて見ました。ベストプラクティスだけ知りたい方は一番下へどうぞ。

awk編

みんな大好きawk。私もawk好きです。でもハマりました。

tools/run-periodic-tasks --daemon 2>&1 | awk '{print strftime(),$0}' >/var/log/mt.log

一見これで良さそうなんですが、awkがバッファしてしまい各行単位で出力されないんですね。なので強制flushすればok。

tools/run-periodic-tasks --daemon 2>&1 | awk '{print strftime(),$0;fflush()}' >/var/log/mt.log

YYYY-MM-DD hh:mm:ssで出力するならこんな感じですかね。

tools/run-periodic-tasks --daemon 2>&1 | awk '{print strftime("%F %T"),$0;fflush()}' >/var/log/mt.log

Perl編

perlはこんな感じでしょうか。

tools/run-periodic-tasks --daemon 2>&1 | perl -MPOSIX -nle '$|=1;print strftime("%F %T ",localtime),$_' >/var/log/mt.log

$|=1に相当する引数は見つけられず。
strftimeを使うためにPOSIXを読んでますが、もうちょっと綺麗にならないでしょうか。

Ruby編

まぁ順当に。

tools/run-periodic-tasks --daemon 2>&1 | ruby -nle 'STDOUT.sync=true;puts "#{Time.now.strftime("%F %T")} #{$_}"' >/var/log/mt.log

Python編

Pythonはワンライナーで書くのが大変だと知った。

tools/run-periodic-tasks --daemon 2>&1 | python -c 'import sys;import time;[(sys.stdout.write(time.strftime("%F %T ")+line),sys.stdout.flush()) for line in iter(sys.stdin.readline,"")]' >/var/log/mt.log

これはひどい。普通に書くとこんな感じでしょうか。

#!/usr/bin/env python

import sys
import time

for line in iter(sys.stdin.readline, ""):
  print time.strftime("%F %T"),line,
  sys.stdout.flush()

logger編

Python編を書いているうちに思い出した。loggerでsyslogに出せばいいじゃん。はいこれオススメ。

tools/run-periodic-tasks --daemon 2>&1 | logger -t mt-run-periodic-tasks -p local0.info

syslogサーバに飛ばすなどの場合は-nとか使ってください。詳しくはlogger --helpを参照で。