Support setting log level for chef-solo runs

[spiffytech]

Please add support for passing the log level parameter ("-l debug") to chef-solo.

[tmatilai]

If you run knife solo cook/bootstrap -VV ... (yeah, two Vs, the standard knife debug switch), -l debug will be passed to the chef-solo run. Does this suit your needs?

[spiffytech]

While that does increase Chef's log level, Knife Solo prints the output in a format that's very sparse and cumbersome to decipher. Compare Knife Solo's output for one task:

DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout:      [echo] Assets precompile can be toggled with the argument '-Dassets.precompile=<boolean>'
    [echo] Assets precompile can be toggled with the argument '-Dassets.precompile=<boolean>'DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout:  


DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout:                                                                                               


DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: rake-assets-precompile:                                                                       
rake-assets-precompile:DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout:                                                                        

With Chef's own, much more condensed output:

check-assets-precompile-env:                                                                                                                                                                                   
     [echo] Assets precompile can be toggled with the argument '-Dassets.precompile=<boolean>'                                                                                                                 

rake-assets-precompile:

The story is the same with log lines for Chef operations.

[matschaffer]

You should get basic chef output without -VV is that not happening?

[cyrusdavid]

When I have to -VV switch the messages get displayed twice (I think):

DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: [2014-05-06T09:08:30+08:00] DEBUG: service[nginx] running: true

[2014-05-06T09:08:30+08:00] DEBUG: service[nginx] running: true
DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: Stopping nginx: 
Stopping nginx: DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: nginx.

nginx.
DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: Starting nginx: 
Starting nginx: DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: nginx.

nginx.
DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: [2014-05-06T09:08:31+08:00] INFO: service[nginx] restarted

    - restart service service[nginx]

[2014-05-06T09:08:31+08:00] INFO: Chef Run complete in 67.083602792 seconds

Running handlers:
[2014-05-06T09:08:31+08:00] INFO: Running report handlers
Running handlers complete

[2014-05-06T09:08:31+08:00] INFO: Report handlers complete

[2014-05-06T09:08:31+08:00] INFO: service[nginx] restarted

    - restart service service[nginx]

[2014-05-06T09:08:31+08:00] INFO: Chef Run complete in 67.083602792 seconds

Running handlers:
[2014-05-06T09:08:31+08:00] INFO: Running report handlers
Running handlers complete

[2014-05-06T09:08:31+08:00] INFO: Report handlers complete
DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: Chef Client finished, 28/407 resources updated in 71.765218291 seconds

Chef Client finished, 28/407 resources updated in 71.765218291 seconds
DEBUG: sudo -p 'knife sudo password: ' chef-solo -c ~/chef-solo/solo.rb -j ~/chef-solo/dna.json -l debug stdout: [2014-05-06T09:08:31+08:00] DEBUG: Forked instance successfully reaped (pid: 32671)
[2014-05-06T09:08:31+08:00] DEBUG: Exiting

[2014-05-06T09:08:31+08:00] DEBUG: Forked instance successfully reaped (pid: 32671)
[2014-05-06T09:08:31+08:00] DEBUG: Exiting
Run finished in 180.466409303 seconds

[spiffytech]

Yeah, that matches what I see. All of the blank lines and the inconsistent use of timestamps (i.e., not having a straight left edge to the output to scan down) make it hard to read, too.

[matschaffer]

I'm open to ideas. Currently we're calling out to Chef::Log.debug so we may need some configuration or a PR against chef itself.

Here's an example:

knife-solo/lib/knife-solo/ssh_connection.rb

Line 63 in 8d1f4f8

Chef::Log.debug("#{command} stdout: #{data}")