search

frapposelli / vagrant-vcloud

Vagrant provider for VMware vCloud Director®
MIT License
67 stars 38 forks source link

Vagrant 1.6.x - Shell provisioner problem #47

Closed tsugliani closed 10 years ago

tsugliani commented 10 years ago

@StefanScherer has identified a problem with Vagrant 1.6.x and the Shell Provisioner

Below an extract of #45:

Stefan Scherer wrote: But there still are some disconnects while setting up the first VM, here directly after powering on the machine:

 INFO interface: info: Powering on VM...
 INFO interface: info: ==> web-vm: Powering on VM...
==> web-vm: Powering on VM...
"SEND POST https://roecloud001/api/vApp/vm-c7fa5641-98b1-4f6f-b596-5adb33cec414/power/action/powerOn"
"RECV 202"
<?xml version="1.0" encoding="UTF-8"?>
<Task xmlns="http://www.vmware.com/vcloud/v1.5" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" status="running" startTime="2014-05-08T06:32:29.997+02:00" serviceNamespace="com.vmware.vcloud" operationName="vappDeploy" operation="Starting Virtual Machine web-vm(c7fa5641-98b1-4f6f-b596-5adb33cec414)" expiryTime="2014-08-06T06:32:29.997+02:00" cancelRequested="false" name="task" id="urn:vcloud:task:c0d41255-2da7-4a53-9f41-c438a469cffe" type="application/vnd.vmware.vcloud.task+xml" href="https://roecloud001/api/task/c0d41255-2da7-4a53-9f41-c438a469cffe" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://roecloud001/api/v1.5/schema/master.xsd">
    <Link rel="task:cancel" href="https://roecloud001/api/task/c0d41255-2da7-4a53-9f41-c438a469cffe/action/cancel"/>
    <Owner type="application/vnd.vmware.vcloud.vm+xml" name="web-vm" href="https://roecloud001/api/vApp/vm-c7fa5641-98b1-4f6f-b596-5adb33cec414"/>
    <User type="application/vnd.vmware.admin.user+xml" name="vagrant" href="https://roecloud001/api/admin/user/258ca929-d860-4d64-9607-17f5e9251384"/>
    <Organization type="application/vnd.vmware.vcloud.org+xml" name="SS" href="https://roecloud001/api/org/14f84887-ef1c-4009-a333-0904bdcaf49e"/>
    <Details/>
</Task>
"SEND GET https://roecloud001/api/task/c0d41255-2da7-4a53-9f41-c438a469cffe"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: c0d41255-2da7-4a53-9f41-c438a469cffe, current status running
"SEND GET https://roecloud001/api/task/c0d41255-2da7-4a53-9f41-c438a469cffe"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: c0d41255-2da7-4a53-9f41-c438a469cffe, current status running
"SEND GET https://roecloud001/api/task/c0d41255-2da7-4a53-9f41-c438a469cffe"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: c0d41255-2da7-4a53-9f41-c438a469cffe, current status success
 INFO warden: Calling IN action: #<Proc:0x00000100c5e918@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::DisconnectVCloud:0x00000100c77698>
 INFO disconnect_vcloud: Disconnecting from vCloud Director...
"SEND DELETE https://roecloud001/api/session"
"RECV 204"
<?xml version="1.0"?>
 INFO disconnect_vcloud: Disconnected from vCloud Director successfully!
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::DisconnectVCloud:0x00000100c77698>
 INFO warden: Calling OUT action: #<Proc:0x00000100c5e918@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::PowerOn:0x00000100c165f0>
 INFO warden: Calling OUT action: #<Proc:0x00000100c04ee0@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Proc:0x00000100c5e238@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x00000100c166e0>
 INFO warden: Calling OUT action: #<Proc:0x00000100eb33a8@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::MessageAlreadyRunning:0x00000100eb33f8>
 INFO warden: Calling OUT action: #<Proc:0x00000100ee3eb8@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x00000100c16758>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x00000100bbc2a8>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100bbc370>
 INFO warden: Calling OUT action: #<Proc:0x00000100cb5dd0@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x00000100c77710>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::InventoryCheck:0x00000100c46098>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x00000100c1fe48>
 INFO warden: Calling OUT action: #<Proc:0x00000101404190@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Proc:0x0000010085d918@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::Call:0x00000100c1fe98>
 INFO warden: Calling OUT action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100c1fec0>
 INFO environment: Released process lock: machine-action-2d50035dad27561e22129b60f5b18746
DEBUG environment: Attempting to acquire process-lock: dotlock
 INFO environment: Acquired process lock: dotlock
 INFO environment: Released process lock: dotlock
 INFO batch_action: Starting action: #<Vagrant::Machine:0x0000010099b230> up {:destroy_on_error=>true, :parallel=>true, :provision_ignore_sentinel=>false, :provision_types=>nil}
 INFO machine: Calling action: up on provider vCloud (new)
DEBUG environment: Attempting to acquire process-lock: machine-action-3691848877293461b6e453faa5aa1c52
DEBUG environment: Attempting to acquire process-lock: dotlock
 INFO environment: Acquired process lock: dotlock
 INFO environment: Released process lock: dotlock
 INFO environment: Acquired process lock: machine-action-3691848877293461b6e453faa5aa1c52
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x000001013e4868>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x000001013ed508>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::Call:0x000001013ed4e0>
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x00000101625fa0>
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::IsCreated:0x00000100d5fd08>
 INFO is_created: vApp has been created and ID is: [d4d9d694-4112-4f6f-9b5e-106c0a39b5b5]
 WARN is_created: VM has not been added to vApp
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::IsCreated:0x00000100d5fd08>
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Warden:0x00000100ec3d98>
 INFO warden: Calling IN action: #<Proc:0x00000100d91588@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::HandleBox:0x00000100ec3cf8>
 INFO handle_box: Machine already has box. HandleBox will not run.
 INFO warden: Calling IN action: #<Proc:0x00000100ee8c38@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x000001013ed490>
 INFO connect_vcloud: Connecting to vCloud Director...
DEBUG connect_vcloud: config.hostname    : https://roecloud001
DEBUG connect_vcloud: config.username    : vagrant
DEBUG connect_vcloud: config.password    : <hidden>
DEBUG connect_vcloud: config.org_name    : SS
DEBUG meta: Finding driver for vCloud version: 5.5
 INFO meta: Using vCloud driver: VagrantPlugins::VCloud::Driver::Version_5_1
 INFO connect_vcloud: Logging into vCloud Director...
"SEND POST https://roecloud001/api/sessions"
"RECV 200"
<?xml version="1.0" encoding="UTF-8"?>
<Session xmlns="http://www.vmware.com/vcloud/v1.5" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" user="vagrant" org="SS" type="application/vnd.vmware.vcloud.session+xml" href="https://roecloud001/api/session/" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://roecloud001/api/v1.5/schema/master.xsd">
    <Link rel="down" type="application/vnd.vmware.vcloud.orgList+xml" href="https://roecloud001/api/org/"/>
    <Link rel="remove" href="https://roecloud001/api/session/"/>
    <Link rel="down" type="application/vnd.vmware.admin.vcloud+xml" href="https://roecloud001/api/admin/"/>
    <Link rel="down" type="application/vnd.vmware.vcloud.org+xml" name="SS" href="https://roecloud001/api/org/14f84887-ef1c-4009-a333-0904bdcaf49e"/>
    <Link rel="down" type="application/vnd.vmware.vcloud.query.queryList+xml" href="https://roecloud001/api/query"/>
    <Link rel="entityResolver" type="application/vnd.vmware.vcloud.entity+xml" href="https://roecloud001/api/entity/"/>
    <Link rel="down:extensibility" type="application/vnd.vmware.vcloud.apiextensibility+xml" href="https://roecloud001/api/extensibility"/>
</Session>
 INFO connect_vcloud: Logged in successfully!
DEBUG connect_vcloud: x-vcloud-authorization=0A8I4E/X8/9zNrAHWl8FqOYwMjtuPeH0bcjVzlqI+2k=
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::InventoryCheck:0x00000101424dc8>

and another disconnect after the POST for the edge gateway port forwarding rules:

</EdgeGatewayServiceConfiguration>
"RECV 202"
<?xml version="1.0" encoding="UTF-8"?>
<Task xmlns="http://www.vmware.com/vcloud/v1.5" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" status="running" startTime="2014-05-08T06:34:19.981+02:00" serviceNamespace="com.vmware.vcloud" operationName="networkConfigureEdgeGatewayServices" operation="Updating services EdgeGateway SS-EDGE(b65fcbd3-6dd6-4684-bac4-8fd1e9c5cc1b)" expiryTime="2014-08-06T06:34:19.981+02:00" cancelRequested="false" name="task" id="urn:vcloud:task:00775295-7f84-4ffa-afd8-be187fb3196e" type="application/vnd.vmware.vcloud.task+xml" href="https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e" xsi:schemaLocation="http://www.vmware.com/vcloud/v1.5 http://roecloud001/api/v1.5/schema/master.xsd">
    <Link rel="task:cancel" href="https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e/action/cancel"/>
    <Owner type="application/vnd.vmware.admin.edgeGateway+xml" name="SS-EDGE" href="https://roecloud001/api/admin/edgeGateway/b65fcbd3-6dd6-4684-bac4-8fd1e9c5cc1b"/>
    <User type="application/vnd.vmware.admin.user+xml" name="vagrant" href="https://roecloud001/api/admin/user/258ca929-d860-4d64-9607-17f5e9251384"/>
    <Organization type="application/vnd.vmware.vcloud.org+xml" name="SS" href="https://roecloud001/api/org/14f84887-ef1c-4009-a333-0904bdcaf49e"/>
    <Details/>
</Task>
"SEND GET https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: 00775295-7f84-4ffa-afd8-be187fb3196e, current status running
"SEND GET https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: 00775295-7f84-4ffa-afd8-be187fb3196e, current status running
"SEND GET https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: 00775295-7f84-4ffa-afd8-be187fb3196e, current status running
"SEND GET https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: 00775295-7f84-4ffa-afd8-be187fb3196e, current status running
"SEND GET https://roecloud001/api/task/00775295-7f84-4ffa-afd8-be187fb3196e"
"RECV 200"
DEBUG driver_5_1: Evaluating taskid: 00775295-7f84-4ffa-afd8-be187fb3196e, current status success
 INFO warden: Calling IN action: #<Proc:0x000001013460a0@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::Provision:0x000001011af638>
 INFO provision: Checking provisioner sentinel if we should run...
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::SyncFolders:0x000001012fdd50>
 INFO warden: Calling IN action: #<Proc:0x0000010136ef78@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::DisconnectVCloud:0x000001014ed4d0>
 INFO disconnect_vcloud: Disconnecting from vCloud Director...
"SEND DELETE https://roecloud001/api/session"
"RECV 204"
<?xml version="1.0"?>
 INFO disconnect_vcloud: Disconnected from vCloud Director successfully!
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::DisconnectVCloud:0x000001014ed4d0>
 INFO warden: Calling OUT action: #<Proc:0x0000010136ef78@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO machine: Calling action: read_ssh_info on provider vCloud (defb4590-58cc-45e6-874a-d96db35c19ba)
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x000001013cfb98>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100ac6b28>
 INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x00000100ac69e8>
 INFO connect_vcloud: Connecting to vCloud Director...
DEBUG connect_vcloud: config.hostname    : https://roecloud001
DEBUG connect_vcloud: config.username    : vagrant
DEBUG connect_vcloud: config.password    : <hidden>
DEBUG connect_vcloud: config.org_name    : SS
DEBUG meta: Finding driver for vCloud version: 5.5
 INFO meta: Using vCloud driver: VagrantPlugins::VCloud::Driver::Version_5_1
 INFO connect_vcloud: Logging into vCloud Director...
"SEND POST https://roecloud001/api/sessions"
"RECV 200"
<?xml version="1.0" encoding="UTF-8"?>

But your code change stabilizes the plugin. Thanks! And the disconnect/reconnects could be optimized later.

But I encounter another problem after rsyncing the folder into the guest:

Calling vagrant up --debug
 INFO interface: info: Bringing machine 'web-vm' up with 'vcloud' provider...
 INFO interface: info: Bringing machine 'ssh-vm' up with 'vcloud' provider...
 INFO interface: info: VM is already running
 INFO interface: info: ==> web-vm: VM is already running
 INFO interface: info: Powering on VM...
 INFO interface: info: ==> web-vm: Powering on VM...
 INFO interface: info: Adding VM to existing vApp...
 INFO interface: info: ==> ssh-vm: Adding VM to existing vApp...
 INFO interface: info: Powering on VM...
 INFO interface: info: ==> ssh-vm: Powering on VM...
 INFO interface: info: Fixed port collision for 80 => 8080. Now on port 2212.
 INFO interface: info: ==> ssh-vm: Fixed port collision for 80 => 8080. Now on port 2212.
 INFO interface: info: Fixed port collision for 22 => 2222. Now on port 2213.
 INFO interface: info: ==> ssh-vm: Fixed port collision for 22 => 2222. Now on port 2213.
 INFO interface: info: Forwarding Ports: VM port 80 -> vShield Edge port 2212
 INFO interface: info: ==> ssh-vm: Forwarding Ports: VM port 80 -> vShield Edge port 2212
 INFO interface: info: Forwarding Ports: VM port 22 -> vShield Edge port 2213
 INFO interface: info: ==> ssh-vm: Forwarding Ports: VM port 22 -> vShield Edge port 2213
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2212.
 INFO interface: info: ==> ssh-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2212.
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2213.
 INFO interface: info: ==> ssh-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2213.
 INFO interface: info: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
 INFO interface: info: ==> ssh-vm: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
 INFO interface: info: Running provisioner: shell...
 INFO interface: info: ==> ssh-vm: Running provisioner: shell...
 INFO interface: error: There are errors in the configuration of this machine. Please fix
 INFO interface: Machine: error-exit ["Vagrant::Errors::ConfigInvalid", "There are errors in the configuration of this machine. Please fix\nthe following errors and try again:\n\nshell provisioner:\n* The following settings shouldn't exist: vm\n\n"]

and in the debug log I find this:

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO ssh: Execute: which rsync (sudo=false)
DEBUG ssh: stdout: /usr/bin/rsync

DEBUG ssh: Exit status: 0
 INFO interface: info: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
 INFO interface: info: ==> ssh-vm: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
==> ssh-vm: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: mkdir -p '/vagrant' (sudo=true)
DEBUG ssh: stderr: stdin: is not a tty

DEBUG ssh: Exit status: 0
DEBUG ssh: Re-using SSH connection.
 INFO ssh: Execute: chown -R vagrant '/vagrant' (sudo=true)
DEBUG ssh: stderr: stdin: is not a tty

DEBUG ssh: Exit status: 0
 INFO subprocess: Starting process: ["/usr/bin/rsync", "--verbose", "--archive", "-z", "--exclude", ".vagrant/", "--exclude", "Vagrantfile", "-e", "ssh -p 2213 -o StrictHostKeyChecking=no -i '/Users/stefan/.vagrant.d/insecure_private_key' ", "/Users/stefan/code/basebox-slave/test/ubuntu1204/", "vagrant@10.100.50.4:/vagrant"]
DEBUG subprocess: Command not in installer, not touching env vars.
DEBUG subprocess: Selecting on IO
DEBUG subprocess: stderr: Warning: Permanently added '[10.100.50.4]:2213' (RSA) to the list of known hosts.
DEBUG subprocess: stdout: building file list ... 
DEBUG subprocess: stdout: done
DEBUG subprocess: stdout: ./
DEBUG subprocess: stdout: 01-vagrant-destroy-f.log
DEBUG subprocess: stdout: 02-vagrant-up.log
DEBUG subprocess: stdout: 03-vagrant-destroy-f.log
DEBUG subprocess: stdout: 04-vagrant-up.log
DEBUG subprocess: stdout: README.md
DEBUG subprocess: stdout: counter.txt
vagrantd.bat
DEBUG subprocess: stdout: vagrantd.sh
scripts/
scripts/provision.sh
DEBUG subprocess: stdout: 
sent 143715 bytes  received 230 bytes  95963.33 bytes/sec
total size is 1461257  speedup is 10.15
DEBUG subprocess: Waiting for process to exit. Remaining to timeout: 31999
DEBUG subprocess: Exit status: 0
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::SyncFolders:0x000001012fdd50>
 INFO provision: Writing provisioning sentinel so we don't provision again
 INFO interface: info: Running provisioner: shell...
 INFO interface: info: ==> ssh-vm: Running provisioner: shell...
==> ssh-vm: Running provisioner: shell...
 INFO environment: Running hook: provisioner_run
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Method: Vagrant::Action::Builtin::Provision#run_provisioner>
 INFO warden: Calling IN action: #<Proc:0x00000100bfeae0@/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:94 (lambda)>
 INFO machine: Calling action: read_ssh_info on provider vCloud (defb4590-58cc-45e6-874a-d96db35c19ba)
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x00000100c679c8>
 INFO warden: Calling IN action: #<Vagrant::Action::Builtin::ConfigValidate:0x00000100c746f0>
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000001011af7f0>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000001014ed5c0>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000001013ed4e0>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO environment: Released process lock: machine-action-3691848877293461b6e453faa5aa1c52
 INFO environment: Running hook: environment_unload
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x000001014dcbd0>
ERROR vagrant: Vagrant experienced an error! Details:
ERROR vagrant: #<Vagrant::Errors::ConfigInvalid: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

>
ERROR vagrant: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

ERROR vagrant: /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/config_validate.rb:18:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:190:in `action_raw'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:167:in `block in action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/environment.rb:397:in `lock'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:155:in `action'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/provider.rb:18:in `ssh_info'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:356:in `ssh_info'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:53:in `block (2 levels) in provision_ssh'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:51:in `tap'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:51:in `block in provision_ssh'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:174:in `with_script_file'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:49:in `provision_ssh'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/provisioners/shell/provisioner.rb:21:in `provision'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:129:in `run_provisioner'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/environment.rb:340:in `hook'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:117:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:117:in `block in call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:105:in `each'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:105:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/forward_ports.rb:22:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/handle_nat_port_collisions.rb:145:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/power_on.rb:21:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/build_vapp.rb:221:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/inventory_check.rb:15:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/connect_vcloud.rb:51:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/handle_box.rb:56:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:190:in `action_raw'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:167:in `block in action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/environment.rb:423:in `lock'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:155:in `action'
/Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/batch_action.rb:82:in `block (2 levels) in run'
 INFO interface: error: There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

There are errors in the configuration of this machine. Please fix
the following errors and try again:

shell provisioner:
* The following settings shouldn't exist: vm

 INFO interface: Machine: error-exit ["Vagrant::Errors::ConfigInvalid", "There are errors in the configuration of this machine. Please fix\nthe following errors and try again:\n\nshell provisioner:\n* The following settings shouldn't exist: vm\n\n"]

The Vagrantfile is untouched from my Repo, so I don't think there is a configuration error.

tsugliani commented 10 years ago

Hi @StefanScherer

I've tried your Vagrantfile settings for the provisioner, and indeed it fails ... This is really weird and I have no clue why OR what's happening, I also found some similar errors on Google, and they seems to be fixed by some Vagrant patchs.

Then I tried a Puppet Provisioner, and it worked.

Replaced

  node_config.vm.provision 'shell', path: 'scripts/provision.sh'

By 

  node_config.vm.provision :puppet do |puppet|
    puppet.manifests_path = 'puppet/manifests'
    puppet.manifest_file = 'site.pp'
    puppet.module_path = 'puppet/modules'
    # puppet.options = "--verbose --debug"
  end

I wonder if this isn't a Vagrant 1.6.0 issue (reproduced it on 1.6.1 too), or like a new internal process we are not really aware when developing a vagrant plugin. It's hard to find documentation other than the source code on the internal plugins API for Vagrant.

tsugliani commented 10 years ago

Can you try the following patch @StefanScherer ?

screenshot 2014-05-08 19 34 42

If you could validate it against your vagrant 1.5.x environment too ?

StefanScherer commented 10 years ago

I have commented out that line and built the vApp again. The first VM web-vm is ok, but there is a problem to ssh into the second VM ssh-vm.

$ ./vagrantd.sh up

Writing debug log file 06-vagrant-up.log
Calling vagrant up --debug
 INFO interface: info: Bringing machine 'web-vm' up with 'vcloud' provider...
 INFO interface: info: Bringing machine 'ssh-vm' up with 'vcloud' provider...
 INFO interface: info: Building vApp...
 INFO interface: info: ==> web-vm: Building vApp...
 INFO interface: success: vApp ubuntu1204-stefan-stefans-mac.local-dfc51e18 successfully created.
 INFO interface: success: ==> web-vm: vApp ubuntu1204-stefan-stefans-mac.local-dfc51e18 successfully created.
 INFO interface: info: Powering on VM...
 INFO interface: info: ==> web-vm: Powering on VM...
 INFO interface: info: Fixed port collision for 80 => 8080. Now on port 2200.
 INFO interface: info: ==> web-vm: Fixed port collision for 80 => 8080. Now on port 2200.
 INFO interface: info: Forwarding Ports: VM port 80 -> vShield Edge port 2200
 INFO interface: info: ==> web-vm: Forwarding Ports: VM port 80 -> vShield Edge port 2200
 INFO interface: info: Forwarding Ports: VM port 22 -> vShield Edge port 2222
 INFO interface: info: ==> web-vm: Forwarding Ports: VM port 22 -> vShield Edge port 2222
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2200.
 INFO interface: info: ==> web-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2200.
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2222.
 INFO interface: info: ==> web-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2222.
 INFO interface: info: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
 INFO interface: info: ==> web-vm: Rsyncing folder: /Users/stefan/code/basebox-slave/test/ubuntu1204/ => /vagrant
 INFO interface: info: Running provisioner: shell...
 INFO interface: info: ==> web-vm: Running provisioner: shell...
 INFO interface: detail: Running: /var/folders/lc/ml6r301d1293tvyv3ydn8psr0000gn/T/vagrant-shell20140508-2987-14sb9gh.sh
 INFO interface: detail:     web-vm: Running: /var/folders/lc/ml6r301d1293tvyv3ydn8psr0000gn/T/vagrant-shell20140508-2987-14sb9gh.sh
 INFO interface: info: stdin: is not a tty
 INFO interface: info: ==> web-vm: stdin: is not a tty
 INFO interface: info: Provisioning web-vm ...
 INFO interface: info: ==> web-vm: Provisioning web-vm ...
 INFO interface: info: Do a little self-check
 INFO interface: info: ==> web-vm: Do a little self-check
 INFO interface: info: Running script /tmp/vagrant-shell
 INFO interface: info: ==> web-vm: Running script /tmp/vagrant-shell
 INFO interface: info: -rwx--x--x 1 vagrant vagrant 236 May  8 14:08 /tmp/vagrant-shell
 INFO interface: info: ==> web-vm: -rwx--x--x 1 vagrant vagrant 236 May  8 14:08 /tmp/vagrant-shell
 INFO interface: info: Directory /vagrant exists
 INFO interface: info: ==> web-vm: Directory /vagrant exists
 INFO interface: info: total 2320
 INFO interface: info: ==> web-vm: total 2320
 INFO interface: info: Adding VM to existing vApp...
 INFO interface: info: ==> ssh-vm: Adding VM to existing vApp...
 INFO interface: info: Powering on VM...
 INFO interface: info: ==> ssh-vm: Powering on VM...
 INFO interface: info: Fixed port collision for 80 => 8080. Now on port 2212.
 INFO interface: info: ==> ssh-vm: Fixed port collision for 80 => 8080. Now on port 2212.
 INFO interface: info: Fixed port collision for 22 => 2222. Now on port 2213.
 INFO interface: info: ==> ssh-vm: Fixed port collision for 22 => 2222. Now on port 2213.
 INFO interface: info: Forwarding Ports: VM port 80 -> vShield Edge port 2212
 INFO interface: info: ==> ssh-vm: Forwarding Ports: VM port 80 -> vShield Edge port 2212
 INFO interface: info: Forwarding Ports: VM port 22 -> vShield Edge port 2213
 INFO interface: info: ==> ssh-vm: Forwarding Ports: VM port 22 -> vShield Edge port 2213
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2212.
 INFO interface: info: ==> ssh-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2212.
 INFO interface: info: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2213.
 INFO interface: info: ==> ssh-vm: Creating NAT rules on [SS-EDGE] for IP [10.100.50.4] port 2213.

Vagrant exited with 1. See 06-vagrant-up.log for more details

This is the rest of the debug output:

DEBUG read_ssh_info: Getting port forwarding rules...
"SEND GET https://roecloud001/api/vApp/vapp-5f712074-94ec-4a89-8665-6668e288fa65/networkConfigSection"
"RECV 200"
<?xml version="1.0" encoding="UTF-8"?>
<NetworkConfigSection xmlns="http://www.vmware.com/vcloud/v1.5" xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" type="application/vnd.vmware.vcloud.networkConfigSection+xml" href="https://roecloud001/api/vApp/vapp-5f712074-94ec-4a89-8665-6668e288fa65/networkConfigSection/" ovf:required="false" xsi:schemaLocation="http://schemas.dmtf.org/ovf/envelope/1 http://schemas.dmtf.org/ovf/envelope/1/dsp8023_1.1.0.xsd http://www.vmware.com/vcloud/v1.5 http://roecloud001/api/v1.5/schema/master.xsd">
    <ovf:Info>The configuration parameters for logical networks</ovf:Info>
    <Link rel="edit" type="application/vnd.vmware.vcloud.networkConfigSection+xml" href="https://roecloud001/api/vApp/vapp-5f712074-94ec-4a89-8665-6668e288fa65/networkConfigSection/"/>
    <NetworkConfig networkName="Vagrant-vApp-Net">
        <Link rel="repair" href="https://roecloud001/api/admin/network/89c42abc-060e-47ec-8fef-abdfcde93502/action/reset"/>
        <Link rel="syncSyslogSettings" type="application/vnd.vmware.vcloud.task+xml" href="https://roecloud001/api/admin/network/89c42abc-060e-47ec-8fef-abdfcde93502/action/syncSyslogServerSettings"/>
        <Description/>
        <Configuration>
            <IpScopes>
                <IpScope>
                    <IsInherited>false</IsInherited>
                    <Gateway>172.16.32.113</Gateway>
                    <Netmask>255.255.255.240</Netmask>
                    <Dns1>8.8.8.8</Dns1>
                    <Dns2>8.8.4.4</Dns2>
                    <IsEnabled>true</IsEnabled>
                    <IpRanges>
                        <IpRange>
                            <StartAddress>172.16.32.114</StartAddress>
                            <EndAddress>172.16.32.126</EndAddress>
                        </IpRange>
                    </IpRanges>
                    <AllocatedIpAddresses>
                        <IpAddress>172.16.32.115</IpAddress>
                        <IpAddress>172.16.32.113</IpAddress>
                        <IpAddress>172.16.32.114</IpAddress>
                    </AllocatedIpAddresses>
                </IpScope>
            </IpScopes>
            <ParentNetwork name="SS-INTERNAL" id="3fd7a97b-b182-41a0-8df5-3b67b5c08b27" href="https://roecloud001/api/admin/network/3fd7a97b-b182-41a0-8df5-3b67b5c08b27"/>
            <FenceMode>natRouted</FenceMode>
            <RetainNetInfoAcrossDeployments>false</RetainNetInfoAcrossDeployments>
            <Features>
                <FirewallService>
                    <IsEnabled>false</IsEnabled>
                    <DefaultAction>drop</DefaultAction>
                    <LogDefaultAction>false</LogDefaultAction>
                </FirewallService>
                <NatService>
                    <IsEnabled>true</IsEnabled>
                    <NatType>portForwarding</NatType>
                    <Policy>allowTraffic</Policy>
                    <NatRule>
                        <Id>65537</Id>
                        <VmRule>
                            <ExternalIpAddress>10.115.4.6</ExternalIpAddress>
                            <ExternalPort>2212</ExternalPort>
                            <VAppScopedVmId>0a327f6f-c79f-4048-aee9-c2993bb4b308</VAppScopedVmId>
                            <VmNicId>0</VmNicId>
                            <InternalPort>80</InternalPort>
                            <Protocol>TCP</Protocol>
                        </VmRule>
                    </NatRule>
                    <NatRule>
                        <Id>65538</Id>
                        <VmRule>
                            <ExternalIpAddress>10.115.4.6</ExternalIpAddress>
                            <ExternalPort>2213</ExternalPort>
                            <VAppScopedVmId>0a327f6f-c79f-4048-aee9-c2993bb4b308</VAppScopedVmId>
                            <VmNicId>0</VmNicId>
                            <InternalPort>22</InternalPort>
                            <Protocol>TCP</Protocol>
                        </VmRule>
                    </NatRule>
                    <NatRule>
                        <Id>65539</Id>
                        <VmRule>
                            <ExternalIpAddress>10.115.4.6</ExternalIpAddress>
                            <ExternalPort>2200</ExternalPort>
                            <VAppScopedVmId>b793dfbd-c44c-4e29-972b-bf78a04cb9e9</VAppScopedVmId>
                            <VmNicId>0</VmNicId>
                            <InternalPort>80</InternalPort>
                            <Protocol>TCP</Protocol>
                        </VmRule>
                    </NatRule>
                    <NatRule>
                        <Id>65540</Id>
                        <VmRule>
                            <ExternalIpAddress>10.115.4.6</ExternalIpAddress>
                            <ExternalPort>2222</ExternalPort>
                            <VAppScopedVmId>b793dfbd-c44c-4e29-972b-bf78a04cb9e9</VAppScopedVmId>
                            <VmNicId>0</VmNicId>
                            <InternalPort>22</InternalPort>
                            <Protocol>TCP</Protocol>
                        </VmRule>
                    </NatRule>
                </NatService>
            </Features>
            <SyslogServerSettings/>
            <RouterInfo>
                <ExternalIp>10.115.4.6</ExternalIp>
            </RouterInfo>
        </Configuration>
        <IsDeployed>true</IsDeployed>
    </NetworkConfig>
</NetworkConfigSection>
DEBUG read_ssh_info: We're running vagrant behind an Organization vDC
                            edge
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ReadSSHInfo:0x00000100dea890>
 INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x00000100d8a558>
DEBUG ssh: Checking key permissions: /Users/stefan/.vagrant.d/insecure_private_key
 INFO ssh: Attempting SSH connnection...
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 10.100.50.4
 INFO ssh:   - Port: 2213
 INFO ssh:   - Username: vagrant
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/stefan/.vagrant.d/insecure_private_key"]
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2014-05-08T23:10:39.144527 #2987] DEBUG -- net.ssh.transport.session[80b2a5e0]: establishing connection to 10.100.50.4:2213

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO retryable: Retryable exception raised: #<Errno::ENETUNREACH: Network is unreachable - connect(2)>
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 10.100.50.4
 INFO ssh:   - Port: 2213
 INFO ssh:   - Username: vagrant
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/stefan/.vagrant.d/insecure_private_key"]
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2014-05-08T23:10:42.269478 #2987] DEBUG -- net.ssh.transport.session[80b805f8]: establishing connection to 10.100.50.4:2213

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO retryable: Retryable exception raised: #<Errno::ENETUNREACH: Network is unreachable - connect(2)>
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 10.100.50.4
 INFO ssh:   - Port: 2213
 INFO ssh:   - Username: vagrant
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/stefan/.vagrant.d/insecure_private_key"]
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2014-05-08T23:10:45.340393 #2987] DEBUG -- net.ssh.transport.session[820bfd88]: establishing connection to 10.100.50.4:2213

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO retryable: Retryable exception raised: #<Errno::ENETUNREACH: Network is unreachable - connect(2)>
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 10.100.50.4
 INFO ssh:   - Port: 2213
 INFO ssh:   - Username: vagrant
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/stefan/.vagrant.d/insecure_private_key"]
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2014-05-08T23:10:48.413210 #2987] DEBUG -- net.ssh.transport.session[820d7e38]: establishing connection to 10.100.50.4:2213

DEBUG ssh: == Net-SSH connection debug-level log END ==
 INFO retryable: Retryable exception raised: #<Errno::ENETUNREACH: Network is unreachable - connect(2)>
 INFO ssh: Attempting to connect to SSH...
 INFO ssh:   - Host: 10.100.50.4
 INFO ssh:   - Port: 2213
 INFO ssh:   - Username: vagrant
 INFO ssh:   - Password? false
 INFO ssh:   - Key Path: ["/Users/stefan/.vagrant.d/insecure_private_key"]
DEBUG ssh: == Net-SSH connection debug-level log START ==
DEBUG ssh: D, [2014-05-08T23:10:51.484713 #2987] DEBUG -- net.ssh.transport.session[820f72d8]: establishing connection to 10.100.50.4:2213

DEBUG ssh: == Net-SSH connection debug-level log END ==
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x00000100c89640>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x000001041067d8>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x0000010520bbf0>
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
ERROR warden: Error occurred: Network is unreachable - connect(2)
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO warden: Beginning recovery process...
 INFO warden: Recovery complete.
 INFO environment: Released process lock: machine-action-3691848877293461b6e453faa5aa1c52
 INFO environment: Running hook: environment_unload
 INFO runner: Preparing hooks for middleware sequence...
 INFO runner: 1 hooks defined.
 INFO runner: Running action: #<Vagrant::Action::Builder:0x00000104209860>
/Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh/transport/session.rb:70:in `initialize': Network is unreachable - connect(2) (Errno::ENETUNREACH)
    from /Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh/transport/session.rb:70:in `open'
    from /Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh/transport/session.rb:70:in `block in initialize'
    from /Applications/Vagrant/embedded/lib/ruby/2.0.0/timeout.rb:66:in `timeout'
    from /Applications/Vagrant/embedded/lib/ruby/2.0.0/timeout.rb:97:in `timeout'
    from /Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh/transport/session.rb:67:in `initialize'
    from /Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh.rb:202:in `new'
    from /Applications/Vagrant/embedded/gems/gems/net-ssh-2.9.0/lib/net/ssh.rb:202:in `start'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/communicators/ssh/communicator.rb:352:in `block (2 levels) in connect'
    from /Applications/Vagrant/embedded/lib/ruby/2.0.0/timeout.rb:66:in `timeout'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/communicators/ssh/communicator.rb:331:in `block in connect'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/retryable.rb:17:in `retryable'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/communicators/ssh/communicator.rb:330:in `connect'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/plugins/communicators/ssh/communicator.rb:179:in `execute'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/sync_folders.rb:54:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/provision.rb:80:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/forward_ports.rb:22:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/handle_nat_port_collisions.rb:145:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/power_on.rb:21:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/build_vapp.rb:221:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/inventory_check.rb:15:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Users/stefan/.vagrant.d/gems/gems/vagrant-vcloud-0.3.1/lib/vagrant-vcloud/action/connect_vcloud.rb:51:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/handle_box.rb:56:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:95:in `block in finalize_action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/call.rb:53:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builtin/config_validate.rb:25:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/warden.rb:34:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/builder.rb:116:in `call'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `block in run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/util/busy.rb:19:in `busy'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/action/runner.rb:66:in `run'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:190:in `action_raw'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:167:in `block in action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/environment.rb:423:in `lock'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/machine.rb:155:in `action'
    from /Applications/Vagrant/embedded/gems/gems/vagrant-1.6.0/lib/vagrant/batch_action.rb:82:in `block (2 levels) in run'
tsugliani commented 10 years ago

Hi @StefanScherer

Hmm, can you give it another try, as I see it's a network problem from this line: INFO retryable: Retryable exception raised: #<Errno::ENETUNREACH: Network is unreachable - connect(2)>

I did try it with your Vagrantfile settings on my setup and 3 VMs and it seems fine. You might want to clear the environment, and maybe Redeploy the Edge Gateway in vCloud Director if this error persists.

StefanScherer commented 10 years ago

Yes, I have seen this error, too. I think, my VPN connection dropped (once again). I will clean my edge gateway settings and try again.

StefanScherer commented 10 years ago

OK, next run. Now both VM's are created and powered on and provisioned. Seems to do the job. Tested with Vagrant 1.6.1.