I have this in my recipe:
log mylog1 do
level :info
message 'WHY I NO SEE THIS?'
end
log mylog2 do
level :info
message 'WHY I NO SEE THIS?'
end
This is what I see when doing kitchen converge -l debug:
...
Converging 3 resources
Recipe: mybook::myrecipe
* log[mylog1] action write
* log[mylog1] action write
...
There are two parts of this question:
First, The log level passed to kitchen with "-l debug" is for the kitchen executable and not for the provisioner, in this case "chef-solo". Therefore, if you run the kitchen with debug option, you would see that, provisioner is running with log_level as "auto" as below, even when kitchen in debug mode:
[SSH] [email protected]<{:user_known_hosts_file=>"/dev/null",
:paranoid=>false, :port=>"2222", :compression=>false, :compression_level=>0,
:keepalive=>true, :keepalive_interval=>60, :timeout=>15, :keys_only=>true,
:keys=>["/Users/mpriyada/myWorks/.kitchen/kitchen-vagrant/kitchen-default-centos/.vagrant/machines/default/virtualbox/private_key"],
:auth_methods=>["publickey"], :user=>"vagrant"}> (sh -c 'sudo -E /opt/chef/bin/chef-solo
--config /tmp/kitchen/solo.rb --log_level auto --force-formatter --no-color
--json-attributes /tmp/kitchen/dna.json')
Which means that, in chef-solo logging priority, "auto" comes par with "warn" level. And hence no output is logged if log level is set as info in the "log" resource. Try below code, you observe the difference:
log "mylog1" do
level :warn
message 'WHY I NO SEE THIS?'
end
log "mylog2" do
level :info
message 'WHY I NO SEE THIS?'
end
Output:
Recipe: test3::default
* log[mylog1] action write[2016-08-17T03:55:16+00:00] WARN: WHY I NO SEE THIS?
* log[mylog2] action write
Running handlers:
Running handlers complete
Now, Second part, if you don't want to run your kitchen in "auto" log_level, you can go to "/opt/chefdk/embedded/lib/ruby/gems/2.1.0/gems/test-kitchen-1.10.0/lib/kitchen/provisioner/chef_base.rb" and change the hard coded log level from auto to whatever chef-solo logging permits https://docs.chef.io/config_rb_solo.html.