Vagrant provision with chef client STDOUT #1006

Closed
jurek7 opened this Issue Jul 3, 2012 · 14 comments

Comments

Projects
None yet
8 participants

jurek7 commented Jul 3, 2012

Is this this possible to enable STDOUT from chef client recipes after launch vagrant provision?
Now i only see e.g:

INFO: ruby_block[test] called
INFO: ruby_block[test2] called

Contributor

leth commented Jul 3, 2012

Try adding chef.log_level = :debug into your chef provision block.

Owner

mitchellh commented Jul 3, 2012

STDOUT is already being mirrored into what Vagrant sees, so what @leth said is correct and you probably need to have a more verbose log level.

mitchellh closed this Jul 3, 2012

jurek7 commented Jul 4, 2012

You're right log level debug helps, but also prints a lot of unnecessary informations. Please compare vagrant provision output with chef-client output(running locally) If you want i can provide some.

Contributor

leth commented Jul 4, 2012

Have you checked for differences between the chef config files which might cause stdout to differ?

I'm seeing the same issue. Perhaps this is just with chef? I'm having it with chef-solo though.

If I do the following, I see STDOUT:

vagrant ssh
sudo /opt/ruby/bin/ruby /opt/ruby/bin/chef-solo -c /tmp/vagrant-chef-1/solo.rb -j /tmp/vagrant-chef-1/dna.json

If I let vagrant run provision itself, I don't see STDOUT. This behavior does not depend on log_level being :debug or :info.

Is it possible that the logging is missing STDOUT/STDERR from subprocesses somehow?

Contributor

leth commented Jul 22, 2012

Could you get some debugging info? Host, guest os's, vagrant version, chef version etc
Also the output of vagrant provision with vagrant logging set to some debugging level would be good.

Host OS is gentoo linux. Guest is ubuntu 12.04 (not the stock box, I slightly customized it to use ruby 1.9.3 instead of 1.8). Chef gem is 10.12.0. Vagrant is 1.0.3.

Here's a snippet of chef-solo running manually through vagrant ssh:

[2012-07-22T18:39:53+00:00] DEBUG: Loading cookbook bluepill's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/bluepill/definitions/bluepill_service.rb
[2012-07-22T18:39:53+00:00] DEBUG: Loading cookbook elasticsearch's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/elasticsearch/definitions/install_plugin.rb
[2012-07-22T18:39:53+00:00] DEBUG: Loading cookbook memcached's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/memcached/definitions/memcached_instance.rb
[2012-07-22T18:39:53+00:00] DEBUG: Loading cookbook nginx's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/nginx/definitions/nginx_site.rb
[2012-07-22T18:39:53+00:00] DEBUG: Loading cookbook unicorn's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/unicorn/definitions/unicorn_config.rb
[2012-07-22T18:39:53+00:00] DEBUG: Loading Recipe mongodb via include_recipe
[2012-07-22T18:39:53+00:00] DEBUG: Found recipe default in cookbook mongodb
[2012-07-22T18:39:53+00:00] DEBUG: Setting service[mongod] to the state of the prior service[mongod]
[2012-07-22T18:39:53+00:00] DEBUG: Setting service[mongod] to the state of the prior service[mongod]
[2012-07-22T18:39:53+00:00] DEBUG: Loading from cookbook_path: /tmp/vagrant-chef-1/chef-solo-1/cookbooks, /tmp/vagrant-chef-1/cookbooks/cookbooks
[2012-07-22T18:39:53+00:00] DEBUG: Converging node vagrant
[2012-07-22T18:39:53+00:00] DEBUG: Processing service[mongod] on vagrant
[2012-07-22T18:39:53+00:00] INFO: Processing service[mongod] action nothing (mongodb::default line 10)
[2012-07-22T18:39:53+00:00] DEBUG: service[mongod] falling back to process table inspection
[2012-07-22T18:39:53+00:00] DEBUG: service[mongod] attempting to match 'mongod' (/mongod/) against process list
UID        PID  PPID  C STIME TTY          TIME CMD
root         1     0  0 18:25 ?        00:00:00 /sbin/init
root         2     0  0 18:25 ?        00:00:00 [kthreadd]
root         3     2  0 18:25 ?        00:00:00 [ksoftirqd/0]
root         6     2  0 18:25 ?        00:00:00 [migration/0]
root         7     2  0 18:25 ?        00:00:00 [watchdog/0]
root         8     2  0 18:25 ?        00:00:00 [migration/1]
root        10     2  0 18:25 ?        00:00:00 [ksoftirqd/1]
root        11     2  0 18:25 ?        00:00:00 [kworker/0:1]
root        12     2  0 18:25 ?        00:00:00 [watchdog/1]
root        13     2  0 18:25 ?        00:00:00 [migration/2]
root        15     2  0 18:25 ?        00:00:00 [ksoftirqd/2]
... (I snipped here, the output is long and irrelevant)
[2012-07-22T18:39:53+00:00] DEBUG: service[mongod] running: true
[2012-07-22T18:39:53+00:00] DEBUG: Doing nothing for service[mongod]
[2012-07-22T18:39:53+00:00] DEBUG: Processing package[mongodb] on vagrant

Here's the same snippet when running vagrant provision:

[2012-07-22T18:40:24+00:00] DEBUG: Loading cookbook bluepill's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/bluepill/definitions/bluepill_service.rb
[2012-07-22T18:40:24+00:00] DEBUG: Loading cookbook elasticsearch's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/elasticsearch/definitions/install_plugin.rb
[2012-07-22T18:40:24+00:00] DEBUG: Loading cookbook memcached's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/memcached/definitions/memcached_instance.rb
[2012-07-22T18:40:24+00:00] DEBUG: Loading cookbook nginx's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/nginx/definitions/nginx_site.rb
[2012-07-22T18:40:24+00:00] DEBUG: Loading cookbook unicorn's definitions from /tmp/vagrant-chef-1/chef-solo-1/cookbooks/unicorn/definitions/unicorn_config.rb
[2012-07-22T18:40:24+00:00] DEBUG: Loading Recipe mongodb via include_recipe
[2012-07-22T18:40:24+00:00] DEBUG: Found recipe default in cookbook mongodb
[2012-07-22T18:40:24+00:00] DEBUG: Setting service[mongod] to the state of the prior service[mongod]
[2012-07-22T18:40:24+00:00] DEBUG: Setting service[mongod] to the state of the prior service[mongod]
[2012-07-22T18:40:24+00:00] DEBUG: Loading from cookbook_path: /tmp/vagrant-chef-1/chef-solo-1/cookbooks, /tmp/vagrant-chef-1/cookbooks/cookbooks
[2012-07-22T18:40:24+00:00] DEBUG: Converging node vagrant
[2012-07-22T18:40:24+00:00] DEBUG: Processing service[mongod] on vagrant
[2012-07-22T18:40:24+00:00] INFO: Processing service[mongod] action nothing (mongodb::default line 10)
[2012-07-22T18:40:24+00:00] DEBUG: service[mongod] falling back to process table inspection
[2012-07-22T18:40:24+00:00] DEBUG: service[mongod] attempting to match 'mongod' (/mongod/) against process list
[2012-07-22T18:40:24+00:00] DEBUG: service[mongod] running: true
[2012-07-22T18:40:24+00:00] DEBUG: Doing nothing for service[mongod]
[2012-07-22T18:40:24+00:00] DEBUG: Processing package[mongodb] on vagrant

It's perhaps very telling that the missing log lines are not prefixed with the [...] DEBUG prefix.

Does the STDOUT/STDERR redirection just substitute in different pipes for the chef-solo process and not instead catch all STDOUT/STDERR? I could see something like this not being inherited by subprocesses.

I tried taking a look at the vagrant source, but the channels stuff is a bit too much for me to trace through right now. Where's the relevant STDOUT/STDERR redirection/routing?

Contributor

leth commented Jul 22, 2012

I'm not familiar enough with the internals either to be honest.

You may be on to something with the subprocess idea, though that might be a chef bug rather than a vagrant bug.
Perhaps it's something to do with ssh session TTY allocation.

I've noticed this too, and I think the issue is because in the chef shell_out class the output from chef subprocesses is only streamed out if STDOUT.tty? returns true.

Contributor

hmalphettes commented Sep 2, 2013

Same issue here with 1.2.7
Anyone with a nicer workaround than rewriting the blocks to append to a file?

bassrock commented Sep 4, 2015

Is there a workaround for this? I am trying to see the full chef output, when using vagrant provision When I run chef after a vagrant ssh I can see all the live output, however when using vagrant provision I only see some very basic output only after each block has executed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment