[調査編]Chef-SoloやChef-Clientのログ出力はパイプやリダイレクトをかますとフォーマットが変わってしまう件

chef-solo(やchef-client --local-mode)のログは、普通に実行するとこういう感じなのですが

% sudo chef-solo -c .chef/solo.rb -o hello -W
Starting Chef Client, version 12.3.0
[2015-06-12T21:14:04+09:00] WARN: Run List override has been provided.
[2015-06-12T21:14:04+09:00] WARN: Original Run List: []
[2015-06-12T21:14:04+09:00] WARN: Overridden Run List: [recipe[hello]]
Compiling Cookbooks...
Converging 1 resources
Recipe: hello::default
  * log[hello world] action write


Running handlers:
Running handlers complete
Chef Client finished, 1/1 resources would have been updated

パイプやリダイレクトをかますとフォーマットが全然別の形になってしまいます。

例えば | catしただけで、こう↓なります。

% sudo chef-solo -c .chef/solo.rb -o hello -W | cat
[2015-06-12T21:14:20+09:00] INFO: Forking chef instance to converge...
[2015-06-12T21:14:20+09:00] INFO: *** Chef 12.3.0 ***
[2015-06-12T21:14:20+09:00] INFO: Chef-client pid: 17520
[2015-06-12T21:14:21+09:00] WARN: Run List override has been provided.
[2015-06-12T21:14:21+09:00] WARN: Original Run List: []
[2015-06-12T21:14:21+09:00] WARN: Overridden Run List: [recipe[hello]]
[2015-06-12T21:14:21+09:00] INFO: Run List is [recipe[hello]]
[2015-06-12T21:14:21+09:00] INFO: Run List expands to [hello]
[2015-06-12T21:14:21+09:00] INFO: Starting Chef Run for localhost
[2015-06-12T21:14:21+09:00] INFO: Running start handlers
[2015-06-12T21:14:21+09:00] INFO: Start handlers complete.
[2015-06-12T21:14:22+09:00] INFO: Processing log[hello world] action write (hello::default line 1)
[2015-06-12T21:14:22+09:00] INFO: hello world
[2015-06-12T21:14:22+09:00] INFO: Chef Run complete in 0.472361641 seconds
[2015-06-12T21:14:22+09:00] INFO: Skipping removal of unused files from the cache
[2015-06-12T21:14:22+09:00] INFO: Running report handlers
[2015-06-12T21:14:22+09:00] INFO: Report handlers complete

ファイルにリダイレクトしたときもパイプ時と同じフォーマットになります。

$ sudo chef-solo -c .chef/solo.rb -o hello -W > ~/tmp/tmp.log
$ tail  ~/tmp/tmp.log
[2015-06-12T21:14:32+09:00] INFO: Run List expands to [hello]
[2015-06-12T21:14:32+09:00] INFO: Starting Chef Run for localhost
[2015-06-12T21:14:32+09:00] INFO: Running start handlers
[2015-06-12T21:14:32+09:00] INFO: Start handlers complete.
[2015-06-12T21:14:33+09:00] INFO: Processing log[hello world] action write (hello::default line 1)
[2015-06-12T21:14:33+09:00] INFO: hello world
[2015-06-12T21:14:33+09:00] INFO: Chef Run complete in 0.500912414 seconds
[2015-06-12T21:14:33+09:00] INFO: Skipping removal of unused files from the cache
[2015-06-12T21:14:33+09:00] INFO: Running report handlers
[2015-06-12T21:14:33+09:00] INFO: Report handlers complete

(そういえばvagrant provisionしたときもこの形ですね)

うーん、なんでこんな仕様なんでしょうか...
catを通すだけで内容が変化するなんて、Unix哲学的にはありえないと思んですよね(ぶつぶつ)

例えばChef Client finished, 1/1 resources would have been updated の行だけ抜き出してメールで通知したいのですが、、パイプを使ったらメッセージフォーマットが変わってしまってこの行があらわれない。

これってアレですよね。
観察するという行為によって観察される現象に変化を与えてしまい正しい観測ができなくなるというアレですよね。

というわけで次回はChefSoloのソースコードを読んでこの件の対策を考えたいと思います。
つづく