CNK's blog

Logging in Chef

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 updated

You 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 updated

NB 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

Comments