Debugging Chef Runs with CHEF_LOG

When you have experience with troubleshooting Vagrant, you probably know that you can enable detailed logging by setting the VAGRANT_LOG environment variable to a specific log level. For example, the info level will make Vagrant much more chatty:

$ VAGRANT_LOG=info vagrant up
 INFO global: Vagrant version: 1.3.4
 INFO manager: Registered plugin: box command
 INFO manager: Registered plugin: destroy command
 INFO manager: Registered plugin: halt command
 INFO manager: Registered plugin: help command
...

While this is helpful for debugging Vagrant itself, I’ve always wanted to have something similar for Vagrant’s provisioners–in particular the Chef Solo provisioner, which I’m using most of the time. In order to get more detailed information about a Chef run, here is how you can enable debug-level logging in your Vagrantfile:

Vagrant.configure("2") do |config|
  # ...
  config.vm.provision :chef_solo do |chef|
    # ...
    chef.log_level = :debug
  end
end

Since the very verbose debug output makes it hard to spot events during normal Chef runs, I used to reduce the log level from debug to info (the default) after each debugging session by commenting out the line. Of course, I don’t like toggling log levels in source code, and neither does Git. As a result, I came up with this VAGRANT_LOG-like solution:

Vagrant.configure("2") do |config|
  # ...
  config.vm.provision :chef_solo do |chef|
    # ...
    chef.log_level = ENV.fetch("CHEF_LOG", "info").downcase.to_sym
  end
end

This bit of Ruby code allows you to configure Chef’s log level via the environment variable CHEF_LOG, which must be set to debug, info, warn, error, or fatal.

Now, debugging Chef runs boils down to:

$ CHEF_LOG=debug vagrant provision
...
[default] Running provisioner: chef_solo...
Generating chef JSON and uploading...
Running chef-solo...
stdin: is not a tty
[2013-10-07T09:40:15+00:00] INFO: Forking chef instance to converge...
[2013-10-07T09:40:15+00:00] DEBUG: Fork successful. Waiting for new chef pid: 1653
[2013-10-07T09:40:15+00:00] DEBUG: Forked instance now converging
[2013-10-07T09:40:15+00:00] INFO: *** Chef 11.6.0 ***
[2013-10-07T09:40:16+00:00] DEBUG: Building node object for cats
[2013-10-07T09:40:16+00:00] DEBUG: Extracting run list from JSON attributes provided on command line
[2013-10-07T09:40:16+00:00] INFO: Setting the run_list to ["recipe[cats::default]"] from JSON
[2013-10-07T09:40:16+00:00] DEBUG: Applying attributes from json file
[2013-10-07T09:40:16+00:00] DEBUG: Platform is ubuntu version 12.04
...

This works with both Chef Solo and Chef Client. It should be trivial to implement the same mechanism for other provisioners like Puppet (using --debug or --test) or Shell (with set -x).

CHEF_FORMAT (added on 2013-12-13)

Besides the log level discussed above, there’s another configuration option you can set in your Vagrantfiles to influence the output of Chef: formatter. This one, as its name implies, changes the output format of Chef. Valid formats are doc, min (or minimal), and null. Chef uses doc by default whenever you run it directly from the command line. Vagrant, on the other hand, applies null by default, which effectively reduces output to log messages.

Similar to CHEF_LOG, it’s straightforward to make the output format configurable via an environment variable–say hello to CHEF_FORMAT. The final code looks like the following:

Vagrant.configure("2") do |config|
  config.vm.provision :chef_solo do |chef|
    # Configure Chef output
    chef.formatter = ENV.fetch("CHEF_FORMAT", "null").downcase.to_sym
    chef.log_level = ENV.fetch("CHEF_LOG", "info").downcase.to_sym
  end
end

As an example, this combination of CHEF_FORMAT and CHEF_LOG will cause Chef to only print out the most basic information:

$ CHEF_FORMAT=min CHEF_LOG=warn vagrant provision

Happy logging!