There are a couple of different techniques for logging during a chef
client run. The simplest option for debugging things in any
programming language is by adding print statements - or in the case of
Ruby, puts statements (print with a newline added). However, in
order for print statements to work, they need to be executed in a
context where stdout is available AND where you, the user, can see
stdout. When running chef manually (either using chef-client or via
test kitchen’s ‘kitchen converge’ command), you are watching output go
by on the console. So you can do things like:
puts "This is normal Ruby code inside a recipe file."And in a client run, you will see that output - in the compile phase.
$ chef-client --once --why-run --local-mode \
--config /Users/cnk/Code/sandbox/customizing_chef/part3_examples/solo.rb
--override-runlist testcookbook::default
Starting Chef Client, version 12.3.0
[2015-07-09T16:25:06-07:00] WARN: Run List override has been provided.
[2015-07-09T16:25:06-07:00] WARN: Original Run List: []
[2015-07-09T16:25:06-07:00] WARN: Overridden Run List: [recipe[testcookbook::default]]
resolving cookbooks for run list: ["testcookbook::default"]
Synchronizing Cookbooks:
- testcookbook
Compiling Cookbooks...
This is normal Ruby code inside a recipe file. ########### this is the message ##########
Converging 0 resources
Running handlers:
Running handlers complete
Chef Client finished, 0/0 resources would have been updatedYou can get nearly the same functionality - but with a timestamp and
some terminal coloring, if you use Chef::Log in the same context:
puts "This is a puts from the top of the default recipe; node info: #{node['foo']}"
Chef::Log.warn("You can log node info #{node['foo']} from a recipe using 'Chef::Log'")Gives:
$ chef-client --once --why-run --local-mode \
--config /Users/cnk/Code/sandbox/customizing_chef/part3_examples/solo.rb \
--override-runlist testcookbook::default
Starting Chef Client, version 12.3.0
[2015-07-09T16:33:44-07:00] WARN: Run List override has been provided.
[2015-07-09T16:33:44-07:00] WARN: Original Run List: []
[2015-07-09T16:33:44-07:00] WARN: Overridden Run List: [recipe[testcookbook::default]]
resolving cookbooks for run list: ["testcookbook::default"]
Synchronizing Cookbooks:
- testcookbook
Compiling Cookbooks...
This is a puts from the top of the default recipe; node info: bar
[2015-07-09T16:33:44-07:00] WARN: You can log node info bar from a recipe using 'Chef::Log'
Converging 0 resources
Running handlers:
Running handlers complete
Chef Client finished, 0/0 resources would have been updatedNB the default log level for chef-client writing messages to the
terminal is warn or higher. So if you try to use
Chef::Log.debug('something') you won’t see your message unless you
have turned up the verbosity. This unexpected feature, caused me a bit
of grief initially as I couldn’t find my log messages anywhere. Now
what I do is use Chef::Log.warn while debugging locally and then plan
to take the messages out before I commit the code.
From my experiments, just about anywhere you might use puts, you can
use Chef::Log. I think the later is probably better because it will
probably put information into actual log files in contexts like test
kitchen that write log files for examining later.
If you need something logged at converge time instead of compile time,
you have 2 options, use the log resource, or wrap Chef::Log inside
a ruby_block call. In either case, during the compile phase, a new
resource gets created and added to the resouce collection. Then during
the converge phase, that resource gets executed. Creating a Chef::Log
statement inside a ruby_block probably isn’t too useful on its own,
though it may be useful if you have created a ruby_block for some
other reason. This gist has some example code and the output:
https://gist.github.com/cnk/e5fa8cafea8c2953cf91