Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Chef-Solo + remote_file + Bad HTTP response returned from server (500) #2

Closed
dpetzel opened this issue Jun 11, 2012 · 3 comments
Closed

Comments

@dpetzel
Copy link
Contributor

dpetzel commented Jun 11, 2012

First all, thanks for this plugin. I'm really liking it.

I am having an issue, which I'm not sure is caused by this plugin, but at the very least its intertwined. I've got everything working so that I can vagrant up a windows box and it comes online and fires the chef-solo provisioner

While running through a series of cookbooks via the chef-solo provisioner it always bombs on a remote file download with a 500 response from winrm. After bombing the vm is immediately destroyed. I believe the automatic destruction is a separate issue than 500 on remote file.

I'll start with the automatic destruction as I think I have this narrowed down a little.
In https://github.com/mitchellh/vagrant/blob/master/lib/vagrant/action/vm/import.rb#L41 there is a check that the error class is Errors::VagrantError. Any other class results in a vm destruction.

In the case of this error the error class is WinRM::WinRMHTTPTransportError. As a result the VM gets trashed every time I hit the 500 response. I've been able to work around this for now by updated type checking in that block of code. I only mention it as it might make sense to incorporate the fix.

The larger issue I have, which I'm at a lose for is why do I get the 500 response code on the remote file? It feels like a timeout issue while the file is downloading (its a couple hundred megs), but I've adjusted the timeout value of @{MaxTimeoutms="1800000"} as outlined in the documentation. I've turned on debug logging for vagrant, but I don't see much of value.

So I'm hoping someone has some insight into what might be causing this, and what additional things I look at.

Snippet of output around the failure:
?[36mwinrm?[0m [Mon, 11 Jun 2012 05:46:49 -0700] INFO: Processing remote_file[/tmp/vagrant-chef-1/MyZipFile.zip] action create (dynamically defined)
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
INFO warden: Calling recover: #Vagrant::Action::VM::Import:0x3a2b9b8
INFO subprocess: Starting process: ["C:\Program Files\Oracle\VirtualBox\VBoxManage.exe", "showvminfo", "dcdaa6f6-3bfe-4a4d-8dec-d636a15342a0", "--machinereadable"]
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
ERROR warden: Error occurred: Bad HTTP response returned from server (500).
C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/http/transport.rb:48:in send_request': Bad HTTP response returned from server (500). (WinRM::WinRMH TTPTransportError) from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:368:insend_message'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:155:in get_command_output' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:inget_command_output'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:in get_command_output' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:inget_command_output'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:in get_command_output' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:inget_command_output'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:174:in get_command_output' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/winrm-1.1.2/lib/winrm/winrm_service.rb:267:inrun_powershell_script'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-windows-0.0.3/lib/vagrant-windows/communication/winrm.rb:164:in shell_execute' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-windows-0.0.3/lib/vagrant-windows/communication/winrm.rb:72:inblock in execute'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/util/retryable.rb:14:in retryable' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-windows-0.0.3/lib/vagrant-windows/communication/winrm.rb:70:inexecute'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-windows-0.0.3/lib/vagrant-windows/communication/winrm.rb:51:in sudo' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/provisioners/chef_solo.rb:203:inblock in run_chef_solo'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/provisioners/chef_solo.rb:189:in times' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/provisioners/chef_solo.rb:189:inrun_chef_solo'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/provisioners/chef_solo.rb:96:in provision!' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/provision.rb:34:inblock in call'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/provision.rb:31:in each' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/provision.rb:31:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/forward_ports.rb:24:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/check_port_collisions.rb:42:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/env/set.rb:16:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/clear_forwarded_ports.rb:13:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/clean_machine_folder.rb:17:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/check_accessible.rb:18:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/general/validate.rb:13:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/general/check_virtualbox.rb:23:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/match_mac_address.rb:16:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/default_name.rb:17:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/check_guest_additions.rb:33:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/import.rb:31:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/check_box.rb:28:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/vm/check_accessible.rb:18:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/general/validate.rb:13:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/general/check_virtualbox.rb:23:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/warden.rb:33:in call' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/builder.rb:92:incall'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/runner.rb:49:in block in run' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/util/busy.rb:19:inbusy'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/action/runner.rb:49:in run' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/vm.rb:192:inrun_action'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/vm.rb:145:in up' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/command/up.rb:31:inblock in execute'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/command/base.rb:116:in block in with_target_vms' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/command/base.rb:111:ineach'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/command/base.rb:111:in with_target_vms' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/command/up.rb:24:inexecute'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/cli.rb:42:in execute' from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/lib/vagrant/environment.rb:167:incli'
from C:/vagrant/vagrant/embedded/lib/ruby/gems/1.9.1/gems/vagrant-1.0.3/bin/vagrant:43:in <top (required)>' from C:/vagrant/vagrant/bin//../embedded/bin/vagrant:19:inload'
from C:/vagrant/vagrant/bin//../embedded/bin/vagrant:19:in `

'

@dpetzel
Copy link
Contributor Author

dpetzel commented Jun 12, 2012

So I believe I got to the bottom of these 500's today. Thanks to http://www.windowsitpro.com/blog/powershell-with-a-purpose-blog-36/scripting-languages/tools-for-troubleshooting-powershell-remoting-and-winrm-part-2-137463 I was able to enable tracing on the WinRM calls and could see the following in the XML <w:OperationTimeout>PT60S</w:OperationTimeout>

After some digging it appears that 60S is the default timeout as configured on the WinRM Library: https://github.com/zenchild/WinRM/blob/master/lib/winrm/winrm_service.rb#L24

Combine that with https://github.com/BIAINC/vagrant-windows/blob/master/lib/vagrant-windows/communication/winrm.rb#L103 and it appears
the code does a check if a custom timeout should be said, but the timeout key in the opts has is not populated from the value defined in the
vagrant file. I was unable to determine any path in which opts[:operation_timeout] would ever have a value (I'm a bit of a ruby newb, so
its possible there is a valid path for that to happen).

I've submitted #3 with a potential fix for this allowing us to set a higher timeout via
the VagrantFile. This pull request doesnt attempt to address the error class mismatch which causes the immediate destrcution of the VM.

@pmorton
Copy link
Contributor

pmorton commented Jul 25, 2012

So it seems that #3 address the operation timeout. Thanks for fixing my bug!

WRT the Exception Mismatch. I am thinking about wrapping some calls in shell_execute to re-raise a vagrant exception. This should leave your machine in a workable state after a failed provision. I am testing the changes now and will have an update shortly

@pmorton
Copy link
Contributor

pmorton commented Jul 25, 2012

@dpetzel Thanks for your help! You make the community rock.

leftathome pushed a commit to leftathome/vagrant-windows that referenced this issue Sep 10, 2012
…t error, Hack WinRb#4 by calling net use to "warm-up" virtual box"
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants