chef-soloでパイプやリダイレクトを使ったときにログの出力フォーマットが変わってしまう件の対策

chef-solo (に限らずchef clientでも) で出力をパイプに渡すと、出力フォーマットが変わってしまうという変な仕様があります。

結論

パイプに渡したときに挙動を同じにするには、"-l warn -F doc"オプションを付ければよい。
つまり下記３つのコマンドは等価である。

$ sudo chef-solo  -c solo.rb -o hello
$ sudo chef-solo  -c solo.rb -o hello -l warn -F doc
$ sudo chef-solo  -c solo.rb -o hello -l warn -F doc | cat

一方、下記２つのコマンドも等価である。(上記とは振る舞いが異なる)

$ sudo chef-solo  -c solo.rb -o hello | cat
$ sudo chef-solo  -c solo.rb -o hello -l info -F null

解説

chef-soloを普通に呼び出した場合、下記のようになります。

$  sudo chef-solo  -c solo.rb -o hello
Starting Chef Client, version 12.0.3
[2015-06-13T01:43:23+09:00] WARN: Run List override has been provided.
[2015-06-13T01:43:23+09:00] WARN: Original Run List: []
[2015-06-13T01:43:23+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 updated in 2.976551 seconds

これは、表面上はわかりませんが、フォーマッタに"doc"を、ログレベルに"warn"を指定したのと同じことになっています。

実際、下記コマンドを叩くと同じ出力が得られます。

$ sudo chef-solo  -c solo.rb -o hello -l warn -F doc

パイプに渡すとどうなるのか

出力先をパイプ(やリダイレクト)にすると、この挙動が変わります。

$  sudo chef-solo  -c solo.rb -o hello | cat
[2015-06-13T01:52:08+09:00] INFO: Forking chef instance to converge...
[2015-06-13T01:52:08+09:00] INFO: *** Chef 12.0.3 ***
[2015-06-13T01:52:08+09:00] INFO: Chef-client pid: 28241
[2015-06-13T01:52:11+09:00] WARN: Run List override has been provided.
[2015-06-13T01:52:11+09:00] WARN: Original Run List: []
[2015-06-13T01:52:11+09:00] WARN: Overridden Run List: [recipe[hello]]
[2015-06-13T01:52:11+09:00] INFO: Run List is [recipe[hello]]
[2015-06-13T01:52:11+09:00] INFO: Run List expands to [hello]
[2015-06-13T01:52:11+09:00] INFO: Starting Chef Run for DQNEO-no-MacBook-Air.local
[2015-06-13T01:52:11+09:00] INFO: Running start handlers
[2015-06-13T01:52:11+09:00] INFO: Start handlers complete.
[2015-06-13T01:52:12+09:00] INFO: Processing log[hello world] action write (hello::default line 1)
[2015-06-13T01:52:12+09:00] INFO: hello world
[2015-06-13T01:52:12+09:00] INFO: Chef Run complete in 0.497036 seconds
[2015-06-13T01:52:12+09:00] INFO: Skipping removal of unused files from the cache
[2015-06-13T01:52:12+09:00] INFO: Running report handlers
[2015-06-13T01:52:12+09:00] INFO: Report handlers complete

これは、フォーマッタに"null"を、ログレベルに"info"を指定したのと同じです。
実際、下記コマンドを叩くと同じ出力が得られます。

$ sudo chef-solo  -c solo.rb -o hello -l info -F null

教訓

暗黙のオプションデフォルト値に頼っていると混乱のもとになるので、慣れるまでは-l とか -F とかを明示的に指定して呼び出す癖をつけるのがよいと思います。