frapposelli / vagrant-vcloud

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

Vagrant provision with winrm fails on slow start #65

Closed StefanScherer closed 10 years ago

StefanScherer commented 10 years ago

Similar to #56, vagrant up may fail while provisioning with winrm communicator a windows guest.

I'm inside my vOrg and so the edge gateway is not configured which also may result in a faster startup as the bridged mode.

$ vagrant up --provider=vcloud
Bringing machine 'tst' up with 'vcloud' provider...
Bringing machine 'tst2' up with 'vcloud' provider...
==> tst: Building vApp...
==> tst: vApp vcloud-win-vagrant-basebox-slave-4a5a5713 successfully created.
==> tst: Setting VM hardware...
==> tst: Powering on VM...
==> tst: Fixed port collision for 22 => 2222. Now on port 2277.
==> tst: Fixed port collision for 3389 => 3389. Now on port 2278.
==> tst: Fixed port collision for 5985 => 55985. Now on port 2279.
==> tst: Forwarding Ports: VM port 22 -> vShield Edge port 2277
==> tst: Forwarding Ports: VM port 3389 -> vShield Edge port 2278
==> tst: Forwarding Ports: VM port 5985 -> vShield Edge port 2279
==> tst: Waiting for SSH Access on 10.115.4.4:2277 ...
==> tst: Warning! Folder sync disabled because the rsync binary is missing.
==> tst: Make sure rsync is installed and the binary can be found in the PATH.
==> tst: Running provisioner: shell...
An error occurred executing a remote WinRM command.

Shell: powershell
Command:             $p = "$Env:SystemRoot"
            if ((Test-Path $p) -and (get-item $p).PSIsContainer) {
              exit 0
            }
            exit 1

if ($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 0 }
Message: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. - connect(2) (http://10.115.4.4:2279)

First the SSH port of the windows guest will be checked. As there is also a OpenSSH running in my guest, it finally get a connection. Then tries rsync, but rsync is not in path at the moment. I have to fix this. Then the WinRM connection fails, perhaps the WinRM is not up and running as fast as the OpenSSH is. Perhaps a retry loop is also needed here for port 5985.

StefanScherer commented 10 years ago

Afterwards a vagrant provision tst works fine. Then powering on second VM with vagrant up --provider=vcloud a similar problem occurs. This time while looking for rsync in guest:

$ vagrant up --provider=vcloud
Bringing machine 'tst' up with 'vcloud' provider...
Bringing machine 'tst2' up with 'vcloud' provider...
==> tst: VM is already running
==> tst2: Adding VM to existing vApp...
==> tst2: Setting VM hardware...
==> tst2: Powering on VM...
==> tst2: Fixed port collision for 22 => 2222. Now on port 2280.
==> tst2: Fixed port collision for 3389 => 3389. Now on port 2281.
==> tst2: Fixed port collision for 5985 => 55985. Now on port 2282.
==> tst2: Forwarding Ports: VM port 22 -> vShield Edge port 2280
==> tst2: Forwarding Ports: VM port 3389 -> vShield Edge port 2281
==> tst2: Forwarding Ports: VM port 5985 -> vShield Edge port 2282
==> tst2: Waiting for SSH Access on 10.115.4.4:2280 ...
An error occurred executing a remote WinRM command.

Shell: powershell
Command:             $command = [Array](Get-Command rsync -errorAction SilentlyContinue)
            if ($null -eq $command) { exit 1 }
            write-host $command[0].Definition
            exit 0

if ($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 0 }
Message: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. - connect(2) (http://10.115.4.4:2282)

I also think that the rsync lookup is done with winrm, the rsync itself connects with SSH. Is there a better way than rsync for windows guests? Any experiences in the vCloud?

tsugliani commented 10 years ago

Hi @StefanScherer,

I was just going through the vagrant code, and I did stumble upon this, which might also fix the SSH problem I fixed in another way, maybe in the proper way:

http://docs.vagrantup.com/v2/vagrantfile/machine_settings.html

It relies on config.vm.boot_timeout (Actual default configuration is 300s)

Related Source files: https://github.com/mitchellh/vagrant/blob/master/plugins/kernel_v2/config/vm.rb https://github.com/mitchellh/vagrant/blob/master/lib/vagrant/action/builtin/wait_for_communicator.rb

StefanScherer commented 10 years ago

The default is 300 seconds, I haven't changed it in any of my Vagrantfiles.

It think the thread does some state checking of the machine while waiting. It is not just a simple "sleep 300". Perhaps the state that the machine is ready for communication is too early. From vagrant/lib/vagrant/action/builtin/wait_for_communicator.rb

          # Wait for ready in a thread so that we can continually check
          # for interrupts.
          ready_thr = Thread.new do
            Thread.current[:result] = env[:machine].communicate.wait_for_ready(
              env[:machine].config.vm.boot_timeout)
          end
StefanScherer commented 10 years ago

This still occurs occasionally with version 0.4.0. Even with the "Waiting for WinRM Access on ..." workaround. Seems that OpenSSHd service starts much faster than WinRM service. Our next try is to start OpenSSHd with a dependency on WinRM service, so the plugin might wait a little longer for SSH to be available before doing rsync over WinRM. I will have a deeper look into vagrant's code to understand the wait_for_ready.

StefanScherer commented 10 years ago

Had a look into the wait_for_ready in the ssh communicator:

      def wait_for_ready(timeout)
        Timeout.timeout(timeout) do
          # Wait for ssh_info to be ready
          ssh_info = nil
          while true
            ssh_info = @machine.ssh_info
            break if ssh_info
            sleep 0.5
          end

Current finding: Seems to me that we just should return nil from ssh_info if connection does not work. Vagrant does the loop then by itself.

StefanScherer commented 10 years ago

Today I have watched a first "Powering on VM" with the live monitor view from vCloud Director of the Windows 8 guest in a vApp just created with vagrant-vcloud 0.4.0.

While the plugin shows the "Waiting for SSH Access .." messages, the Windows guest was booted, auto logged in with user vagrant, and then rebooted while the Waiting loop is active.

So I believe that the guest customization reboots the guest so late while the plugin just wants to connect the SSH and later the WinRM ports. I think that could be a problem if the OpenSSHd already answers request while the reboot for the guest customization (hostname renamed...) will happen.

Is there a task to wait for finishing the guest customization?

StefanScherer commented 10 years ago

Got another issue provisioning a Windows box running within the vCloud, so no Edge Gateway port forwardings are done here and so the vagrant-vcloud plugin tries to connect to the newly created windows guest much faster:

Here is the console output (by gripping the debug output):

$ grep "INFO interface:" ../shared/winrm.txt 
01:01:22.334  INFO interface: info: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:22.334  INFO interface: info: ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:28.821  INFO interface: info: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:28.821  INFO interface: info: ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 

Here are the calls to our read_ssh_info function for the different communicator ports:

$ grep ssh_info ../shared/winrm.txt 
01:01:01.341 DEBUG read_ssh_info: SSH INFO: IP 10.115.4.4 and Port 2224
01:01:22.334 DEBUG read_ssh_info: SSH Connection Timeout...
01:01:28.821 DEBUG read_ssh_info: SSH Connection Timeout...
01:01:34.823 DEBUG read_ssh_info: SSH Connection successful !
01:01:34.902 DEBUG read_ssh_info: Getting vApp information...
01:01:35.241 DEBUG read_ssh_info: Getting port forwarding rules...
01:01:35.483 DEBUG read_ssh_info: WinRM INFO: IP 10.115.4.4 and Port 2226
01:01:35.484 DEBUG read_ssh_info: WinRM Connection successful !

So after connecting to SSH it tries to find the port of WinRM, which also seems ok, so a simple TCP connect worked. So Vagrant will go to the next step and start provisioning.

And here to debug output of the captured situation. There is a timeout of about 23 seconds (in the log file at 01:01:35 there is a jump to 01:01:58 with the first WinRM error) and the first WinRM command crashed and so does Vagrant.

Any ideas how to fix this? My first thought is not to just open a socket, but to call a test WinRM command inside the wait loop until everything works.

Isn't Windows lovely?

01:01:01.341 DEBUG read_ssh_info: SSH INFO: IP 10.115.4.4 and Port 2224
01:01:22.334 DEBUG read_ssh_info: SSH Connection Timeout...
01:01:22.334  INFO interface: info: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:22.334  INFO interface: info: ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:22.335 ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:28.821 DEBUG read_ssh_info: SSH Connection Timeout...
01:01:28.821  INFO interface: info: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:28.821  INFO interface: info: ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:28.822 ==> tst: Waiting for SSH Access on 10.115.4.4:2224 ... 
01:01:34.823 DEBUG read_ssh_info: SSH Connection successful !
01:01:34.823  INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ReadSSHInfo:0x2517348>
01:01:34.823  INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x1959fc0>
01:01:34.841 DEBUG provider: Searching for cap: winrm_info
01:01:34.841 DEBUG provider: Checking in: vcloud
01:01:34.841 DEBUG provider: Found cap: winrm_info in vcloud
01:01:34.901 DEBUG provider: Searching for cap: winrm_info
01:01:34.901 DEBUG provider: Checking in: vcloud
01:01:34.901 DEBUG provider: Found cap: winrm_info in vcloud
01:01:34.901  INFO provider: Execute capability: winrm_info [#<Vagrant::Machine: tst (VagrantPlugins::VCloud::Provider)>] (vcloud)
01:01:34.902  INFO machine: Calling action: read_winrm_info on provider vCloud (1a23fcff-9acd-4c74-bf42-4126e8f4fdb5)
01:01:34.902  INFO runner: Preparing hooks for middleware sequence...
01:01:34.902  INFO runner: 1 hooks defined.
01:01:34.902  INFO runner: Running action: #<Vagrant::Action::Builder:0x30bc958>
01:01:34.902  INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x30cc360>
01:01:34.902  INFO connect_vcloud: Already logged in, using current session
01:01:34.902 DEBUG connect_vcloud: x-vcloud-authorization=DH4qxCzU9lU8bHhLqqitIQsk8OUldlkw2J5FiAWIDQw=
01:01:34.902  INFO warden: Calling IN action: #<VagrantPlugins::VCloud::Action::ReadSSHInfo:0x311d5e8>
01:01:34.902 DEBUG read_ssh_info: Getting vApp information...
01:01:34.908 "[Mon Jun 30 11:57:46 2014] -> SEND GET https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d"
01:01:35.191 "[Mon Jun 30 11:57:46 2014] <- RECV 200"
01:01:35.191 "RECV HEADERS"
01:01:35.191 {
01:01:35.191               "Date" => "Mon, 30 Jun 2014 09:57:45 GMT",
01:01:35.191               "Vary" => "Accept-Encoding",
01:01:35.191       "Content-Type" => "application/vnd.vmware.vcloud.vApp+xml;version=5.1",
01:01:35.192     "Content-Length" => "28608"
01:01:35.192 }
01:01:35.192 "RECV BODY"
01:01:35.199 <?xml version="1.0" encoding="UTF-8"?>
01:01:35.199 <VApp xmlns="http://www.vmware.com/vcloud/v1.5" xmlns:ovf="http://schemas.dmtf.org/ovf/envelope/1" xmlns:vssd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData" xmlns:rasd="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData" xmlns:vmw="http://www.vmware.com/schema/ovf" xmlns:ovfenv="http://schemas.dmtf.org/ovf/environment/1" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" ovfDescriptorUploaded="true" deployed="true" status="4" name="windows_2008_r2-100gb-vagrant-vmware-slave-49d5d176" id="urn:vcloud:vapp:395d08ec-99b1-4b41-baf4-d171d97db78d" type="application/vnd.vmware.vcloud.vApp+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d" xsi:schemaLocation="http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_VirtualSystemSettingData http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2.22.0/CIM_VirtualSystemSettingData.xsd http://www.vmware.com/schema/ovf http://www.vmware.com/schema/ovf http://schemas.dmtf.org/ovf/envelope/1 http://schemas.dmtf.org/ovf/envelope/1/dsp8023_1.1.0.xsd http://schemas.dmtf.org/ovf/environment/1 http://schemas.dmtf.org/ovf/envelope/1/dsp8027_1.1.0.xsd http://www.vmware.com/vcloud/v1.5 http://roecloud001/api/v1.5/schema/master.xsd http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2/CIM_ResourceAllocationSettingData http://schemas.dmtf.org/wbem/wscim/1/cim-schema/2.22.0/CIM_ResourceAllocationSettingData.xsd">
01:01:35.202     <Link rel="power:powerOff" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/power/action/powerOff"/>
01:01:35.202     <Link rel="power:reboot" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/power/action/reboot"/>
01:01:35.202     <Link rel="power:reset" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/power/action/reset"/>
01:01:35.203     <Link rel="power:shutdown" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/power/action/shutdown"/>
01:01:35.203     <Link rel="power:suspend" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/power/action/suspend"/>
01:01:35.203     <Link rel="deploy" type="application/vnd.vmware.vcloud.deployVAppParams+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/action/deploy"/>
01:01:35.204     <Link rel="undeploy" type="application/vnd.vmware.vcloud.undeployVAppParams+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/action/undeploy"/>
01:01:35.204     <Link rel="down" type="application/vnd.vmware.vcloud.vAppNetwork+xml" name="Vagrant-vApp-Net" href="https://roecloud001/api/network/794acb54-2831-4a4f-9e80-b73f42bdb978"/>
01:01:35.204     <Link rel="down" type="application/vnd.vmware.vcloud.controlAccess+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/controlAccess/"/>
01:01:35.204     <Link rel="controlAccess" type="application/vnd.vmware.vcloud.controlAccess+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/action/controlAccess"/>
01:01:35.205     <Link rel="up" type="application/vnd.vmware.vcloud.vdc+xml" href="https://roecloud001/api/vdc/ea5a7837-1f8f-4e5b-8b75-511a7869995f"/>
01:01:35.205     <Link rel="edit" type="application/vnd.vmware.vcloud.vApp+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d"/>
01:01:35.205     <Link rel="down" type="application/vnd.vmware.vcloud.owner+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/owner"/>
01:01:35.205     <Link rel="down" type="application/vnd.vmware.vcloud.metadata+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/metadata"/>
01:01:35.205     <Link rel="ovf" type="text/xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/ovf"/>
01:01:35.205     <Link rel="down" type="application/vnd.vmware.vcloud.productSections+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/productSections/"/>
01:01:35.206     <Link rel="snapshot:create" type="application/vnd.vmware.vcloud.createSnapshotParams+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/action/createSnapshot"/>
01:01:35.206     <Description>vApp created by vagrant running on vmware-slave using vagrant-vcloud on June 30, 2014</Description>
01:01:35.206     <LeaseSettingsSection type="application/vnd.vmware.vcloud.leaseSettingsSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/leaseSettingsSection/" ovf:required="false">
01:01:35.206         <ovf:Info>Lease settings section</ovf:Info>
01:01:35.206         <Link rel="edit" type="application/vnd.vmware.vcloud.leaseSettingsSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/leaseSettingsSection/"/>
01:01:35.207         <DeploymentLeaseInSeconds>259200</DeploymentLeaseInSeconds>
01:01:35.207         <StorageLeaseInSeconds>2592000</StorageLeaseInSeconds>
01:01:35.207         <DeploymentLeaseExpiration>2014-07-03T11:56:50.397+02:00</DeploymentLeaseExpiration>
01:01:35.207     </LeaseSettingsSection>
01:01:35.207     <ovf:StartupSection xmlns:vcloud="http://www.vmware.com/vcloud/v1.5" vcloud:href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/startupSection/" vcloud:type="application/vnd.vmware.vcloud.startupSection+xml">
01:01:35.207         <ovf:Info>VApp startup section</ovf:Info>
01:01:35.207         <ovf:Item ovf:stopDelay="0" ovf:stopAction="powerOff" ovf:startDelay="0" ovf:startAction="powerOn" ovf:order="0" ovf:id="tst"/>
01:01:35.208         <Link rel="edit" type="application/vnd.vmware.vcloud.startupSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/startupSection/"/>
01:01:35.208     </ovf:StartupSection>
01:01:35.208     <ovf:NetworkSection xmlns:vcloud="http://www.vmware.com/vcloud/v1.5" vcloud:href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/networkSection/" vcloud:type="application/vnd.vmware.vcloud.networkSection+xml">
01:01:35.208         <ovf:Info>The list of logical networks</ovf:Info>
01:01:35.208         <ovf:Network ovf:name="Vagrant-vApp-Net">
01:01:35.208             <ovf:Description/>
01:01:35.208         </ovf:Network>
01:01:35.208     </ovf:NetworkSection>
01:01:35.208     <NetworkConfigSection type="application/vnd.vmware.vcloud.networkConfigSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/networkConfigSection/" ovf:required="false">
01:01:35.209         <ovf:Info>The configuration parameters for logical networks</ovf:Info>
01:01:35.209         <Link rel="edit" type="application/vnd.vmware.vcloud.networkConfigSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/networkConfigSection/"/>
01:01:35.209         <NetworkConfig networkName="Vagrant-vApp-Net">
01:01:35.209             <Link rel="repair" href="https://roecloud001/api/admin/network/794acb54-2831-4a4f-9e80-b73f42bdb978/action/reset"/>
01:01:35.209             <Link rel="syncSyslogSettings" type="application/vnd.vmware.vcloud.task+xml" href="https://roecloud001/api/admin/network/794acb54-2831-4a4f-9e80-b73f42bdb978/action/syncSyslogServerSettings"/>
01:01:35.210             <Description/>
01:01:35.210             <Configuration>
01:01:35.210                 <IpScopes>
01:01:35.210                     <IpScope>
01:01:35.210                         <IsInherited>false</IsInherited>
01:01:35.210                         <Gateway>10.1.1.1</Gateway>
01:01:35.210                         <Netmask>255.255.255.0</Netmask>
01:01:35.210                         <Dns1>8.8.8.8</Dns1>
01:01:35.210                         <Dns2>8.8.4.4</Dns2>
01:01:35.210                         <IsEnabled>true</IsEnabled>
01:01:35.210                         <IpRanges>
01:01:35.210                             <IpRange>
01:01:35.210                                 <StartAddress>10.1.1.2</StartAddress>
01:01:35.210                                 <EndAddress>10.1.1.254</EndAddress>
01:01:35.211                             </IpRange>
01:01:35.211                         </IpRanges>
01:01:35.211                         <AllocatedIpAddresses>
01:01:35.211                             <IpAddress>10.1.1.2</IpAddress>
01:01:35.211                             <IpAddress>10.1.1.1</IpAddress>
01:01:35.211                         </AllocatedIpAddresses>
01:01:35.211                     </IpScope>
01:01:35.211                 </IpScopes>
01:01:35.211                 <ParentNetwork name="SS-INTERNAL" id="3fd7a97b-b182-41a0-8df5-3b67b5c08b27" href="https://roecloud001/api/admin/network/3fd7a97b-b182-41a0-8df5-3b67b5c08b27"/>
01:01:35.211                 <FenceMode>natRouted</FenceMode>
01:01:35.212                 <RetainNetInfoAcrossDeployments>false</RetainNetInfoAcrossDeployments>
01:01:35.212                 <Features>
01:01:35.212                     <FirewallService>
01:01:35.212                         <IsEnabled>false</IsEnabled>
01:01:35.212                         <DefaultAction>drop</DefaultAction>
01:01:35.212                         <LogDefaultAction>false</LogDefaultAction>
01:01:35.212                     </FirewallService>
01:01:35.212                     <NatService>
01:01:35.212                         <IsEnabled>true</IsEnabled>
01:01:35.212                         <NatType>portForwarding</NatType>
01:01:35.212                         <Policy>allowTraffic</Policy>
01:01:35.213                         <NatRule>
01:01:35.213                             <Id>65537</Id>
01:01:35.213                             <VmRule>
01:01:35.213                                 <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.213                                 <ExternalPort>2224</ExternalPort>
01:01:35.213                                 <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.213                                 <VmNicId>0</VmNicId>
01:01:35.213                                 <InternalPort>22</InternalPort>
01:01:35.213                                 <Protocol>TCP</Protocol>
01:01:35.213                             </VmRule>
01:01:35.213                         </NatRule>
01:01:35.213                         <NatRule>
01:01:35.213                             <Id>65538</Id>
01:01:35.213                             <VmRule>
01:01:35.214                                 <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.214                                 <ExternalPort>2225</ExternalPort>
01:01:35.214                                 <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.214                                 <VmNicId>0</VmNicId>
01:01:35.214                                 <InternalPort>3389</InternalPort>
01:01:35.214                                 <Protocol>TCP</Protocol>
01:01:35.214                             </VmRule>
01:01:35.214                         </NatRule>
01:01:35.214                         <NatRule>
01:01:35.214                             <Id>65539</Id>
01:01:35.214                             <VmRule>
01:01:35.214                                 <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.214                                 <ExternalPort>2226</ExternalPort>
01:01:35.215                                 <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.215                                 <VmNicId>0</VmNicId>
01:01:35.215                                 <InternalPort>5985</InternalPort>
01:01:35.215                                 <Protocol>TCP</Protocol>
01:01:35.215                             </VmRule>
01:01:35.215                         </NatRule>
01:01:35.215                     </NatService>
01:01:35.215                 </Features>
01:01:35.215                 <SyslogServerSettings/>
01:01:35.215                 <RouterInfo>
01:01:35.215                     <ExternalIp>10.115.4.4</ExternalIp>
01:01:35.215                 </RouterInfo>
01:01:35.215             </Configuration>
01:01:35.215             <IsDeployed>true</IsDeployed>
01:01:35.215         </NetworkConfig>
01:01:35.215     </NetworkConfigSection>
01:01:35.216     <SnapshotSection type="application/vnd.vmware.vcloud.snapshotSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/snapshotSection" ovf:required="false">
01:01:35.216         <ovf:Info>Snapshot information section</ovf:Info>
01:01:35.216     </SnapshotSection>
01:01:35.216     <DateCreated>2014-06-30T11:54:20.480+02:00</DateCreated>
01:01:35.216     <Owner type="application/vnd.vmware.vcloud.owner+xml">
01:01:35.216         <User type="application/vnd.vmware.admin.user+xml" name="vagrant" href="https://roecloud001/api/admin/user/258ca929-d860-4d64-9607-17f5e9251384"/>
01:01:35.216     </Owner>
01:01:35.216     <InMaintenanceMode>false</InMaintenanceMode>
01:01:35.216     <Children>
01:01:35.216         <Vm nestedHypervisorEnabled="false" needsCustomization="false" deployed="true" status="4" name="tst" id="urn:vcloud:vm:1a23fcff-9acd-4c74-bf42-4126e8f4fdb5" type="application/vnd.vmware.vcloud.vm+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5">
01:01:35.217             <Link rel="power:powerOff" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/power/action/powerOff"/>
01:01:35.217             <Link rel="power:reboot" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/power/action/reboot"/>
01:01:35.217             <Link rel="power:reset" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/power/action/reset"/>
01:01:35.217             <Link rel="power:shutdown" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/power/action/shutdown"/>
01:01:35.217             <Link rel="power:suspend" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/power/action/suspend"/>
01:01:35.218             <Link rel="undeploy" type="application/vnd.vmware.vcloud.undeployVAppParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/action/undeploy"/>
01:01:35.218             <Link rel="edit" type="application/vnd.vmware.vcloud.vm+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5"/>
01:01:35.218             <Link rel="down" type="application/vnd.vmware.vcloud.metadata+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/metadata"/>
01:01:35.218             <Link rel="down" type="application/vnd.vmware.vcloud.productSections+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/productSections/"/>
01:01:35.219             <Link rel="screen:thumbnail" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/screen"/>
01:01:35.219             <Link rel="screen:acquireTicket" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/screen/action/acquireTicket"/>
01:01:35.219             <Link rel="media:insertMedia" type="application/vnd.vmware.vcloud.mediaInsertOrEjectParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/media/action/insertMedia"/>
01:01:35.219             <Link rel="media:ejectMedia" type="application/vnd.vmware.vcloud.mediaInsertOrEjectParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/media/action/ejectMedia"/>
01:01:35.219             <Link rel="disk:attach" type="application/vnd.vmware.vcloud.diskAttachOrDetachParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/disk/action/attach"/>
01:01:35.220             <Link rel="disk:detach" type="application/vnd.vmware.vcloud.diskAttachOrDetachParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/disk/action/detach"/>
01:01:35.220             <Link rel="installVmwareTools" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/action/installVMwareTools"/>
01:01:35.220             <Link rel="snapshot:create" type="application/vnd.vmware.vcloud.createSnapshotParams+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/action/createSnapshot"/>
01:01:35.221             <Link rel="reconfigureVm" type="application/vnd.vmware.vcloud.vm+xml" name="tst" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/action/reconfigureVm"/>
01:01:35.221             <Link rel="up" type="application/vnd.vmware.vcloud.vApp+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d"/>
01:01:35.221             <ovf:VirtualHardwareSection xmlns:vcloud="http://www.vmware.com/vcloud/v1.5" ovf:transport="" vcloud:href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/" vcloud:type="application/vnd.vmware.vcloud.virtualHardwareSection+xml">
01:01:35.221                 <ovf:Info>Virtual hardware requirements</ovf:Info>
01:01:35.221                 <ovf:System>
01:01:35.221                     <vssd:ElementName>Virtual Hardware Family</vssd:ElementName>
01:01:35.222                     <vssd:InstanceID>0</vssd:InstanceID>
01:01:35.222                     <vssd:VirtualSystemIdentifier>tst</vssd:VirtualSystemIdentifier>
01:01:35.222                     <vssd:VirtualSystemType>vmx-09</vssd:VirtualSystemType>
01:01:35.222                 </ovf:System>
01:01:35.222                 <ovf:Item>
01:01:35.222                     <rasd:Address>00:50:56:01:0d:5b</rasd:Address>
01:01:35.222                     <rasd:AddressOnParent>0</rasd:AddressOnParent>
01:01:35.222                     <rasd:AutomaticAllocation>true</rasd:AutomaticAllocation>
01:01:35.222                     <rasd:Connection vcloud:ipAddress="10.1.1.2" vcloud:primaryNetworkConnection="true" vcloud:ipAddressingMode="POOL">Vagrant-vApp-Net</rasd:Connection>
01:01:35.222                     <rasd:Description>Vmxnet3 ethernet adapter on "Vagrant-vApp-Net"</rasd:Description>
01:01:35.223                     <rasd:ElementName>Network adapter 0</rasd:ElementName>
01:01:35.223                     <rasd:InstanceID>1</rasd:InstanceID>
01:01:35.223                     <rasd:ResourceSubType>VMXNET3</rasd:ResourceSubType>
01:01:35.223                     <rasd:ResourceType>10</rasd:ResourceType>
01:01:35.223                 </ovf:Item>
01:01:35.223                 <ovf:Item>
01:01:35.223                     <rasd:Address>0</rasd:Address>
01:01:35.223                     <rasd:Description>SCSI Controller</rasd:Description>
01:01:35.224                     <rasd:ElementName>SCSI Controller 0</rasd:ElementName>
01:01:35.224                     <rasd:InstanceID>2</rasd:InstanceID>
01:01:35.224                     <rasd:ResourceSubType>lsilogicsas</rasd:ResourceSubType>
01:01:35.224                     <rasd:ResourceType>6</rasd:ResourceType>
01:01:35.224                 </ovf:Item>
01:01:35.224                 <ovf:Item>
01:01:35.224                     <rasd:AddressOnParent>0</rasd:AddressOnParent>
01:01:35.224                     <rasd:Description>Hard disk</rasd:Description>
01:01:35.224                     <rasd:ElementName>Hard disk 1</rasd:ElementName>
01:01:35.224                     <rasd:HostResource vcloud:capacity="102400" vcloud:busSubType="lsilogicsas" vcloud:busType="6"/>
01:01:35.224                     <rasd:InstanceID>2000</rasd:InstanceID>
01:01:35.225                     <rasd:Parent>2</rasd:Parent>
01:01:35.225                     <rasd:ResourceType>17</rasd:ResourceType>
01:01:35.225                 </ovf:Item>
01:01:35.225                 <ovf:Item vcloud:href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/cpu" vcloud:type="application/vnd.vmware.vcloud.rasdItem+xml">
01:01:35.225                     <rasd:AllocationUnits>hertz * 10^6</rasd:AllocationUnits>
01:01:35.225                     <rasd:Description>Number of Virtual CPUs</rasd:Description>
01:01:35.225                     <rasd:ElementName>2 virtual CPU(s)</rasd:ElementName>
01:01:35.225                     <rasd:InstanceID>3</rasd:InstanceID>
01:01:35.225                     <rasd:Reservation>0</rasd:Reservation>
01:01:35.225                     <rasd:ResourceType>3</rasd:ResourceType>
01:01:35.226                     <rasd:VirtualQuantity>2</rasd:VirtualQuantity>
01:01:35.226                     <rasd:Weight>0</rasd:Weight>
01:01:35.226                     <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/cpu"/>
01:01:35.226                 </ovf:Item>
01:01:35.226                 <ovf:Item vcloud:href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/memory" vcloud:type="application/vnd.vmware.vcloud.rasdItem+xml">
01:01:35.226                     <rasd:AllocationUnits>byte * 2^20</rasd:AllocationUnits>
01:01:35.226                     <rasd:Description>Memory Size</rasd:Description>
01:01:35.226                     <rasd:ElementName>2048 MB of memory</rasd:ElementName>
01:01:35.227                     <rasd:InstanceID>4</rasd:InstanceID>
01:01:35.227                     <rasd:Reservation>0</rasd:Reservation>
01:01:35.227                     <rasd:ResourceType>4</rasd:ResourceType>
01:01:35.227                     <rasd:VirtualQuantity>2048</rasd:VirtualQuantity>
01:01:35.227                     <rasd:Weight>0</rasd:Weight>
01:01:35.227                     <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/memory"/>
01:01:35.227                 </ovf:Item>
01:01:35.227                 <Link rel="edit" type="application/vnd.vmware.vcloud.virtualHardwareSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/"/>
01:01:35.227                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/cpu"/>
01:01:35.228                 <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/cpu"/>
01:01:35.228                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/memory"/>
01:01:35.228                 <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItem+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/memory"/>
01:01:35.228                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/disks"/>
01:01:35.229                 <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/disks"/>
01:01:35.229                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/media"/>
01:01:35.229                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/networkCards"/>
01:01:35.230                 <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/networkCards"/>
01:01:35.230                 <Link rel="down" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/serialPorts"/>
01:01:35.230                 <Link rel="edit" type="application/vnd.vmware.vcloud.rasdItemsList+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/virtualHardwareSection/serialPorts"/>
01:01:35.230             </ovf:VirtualHardwareSection>
01:01:35.230             <ovf:OperatingSystemSection xmlns:vcloud="http://www.vmware.com/vcloud/v1.5" ovf:id="102" vcloud:href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/operatingSystemSection/" vcloud:type="application/vnd.vmware.vcloud.operatingSystemSection+xml" vmw:osType="windows7Server64Guest">
01:01:35.231                 <ovf:Info>Specifies the operating system installed</ovf:Info>
01:01:35.231                 <ovf:Description>Microsoft Windows Server 2008 R2 (64-bit)</ovf:Description>
01:01:35.231                 <Link rel="edit" type="application/vnd.vmware.vcloud.operatingSystemSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/operatingSystemSection/"/>
01:01:35.231             </ovf:OperatingSystemSection>
01:01:35.231             <NetworkConnectionSection type="application/vnd.vmware.vcloud.networkConnectionSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/networkConnectionSection/" ovf:required="false">
01:01:35.232                 <ovf:Info>Specifies the available VM network connections</ovf:Info>
01:01:35.232                 <PrimaryNetworkConnectionIndex>0</PrimaryNetworkConnectionIndex>
01:01:35.232                 <NetworkConnection network="Vagrant-vApp-Net" needsCustomization="false">
01:01:35.232                     <NetworkConnectionIndex>0</NetworkConnectionIndex>
01:01:35.232                     <IpAddress>10.1.1.2</IpAddress>
01:01:35.232                     <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.232                     <IsConnected>true</IsConnected>
01:01:35.232                     <MACAddress>00:50:56:01:0d:5b</MACAddress>
01:01:35.232                     <IpAddressAllocationMode>POOL</IpAddressAllocationMode>
01:01:35.232                 </NetworkConnection>
01:01:35.233                 <Link rel="edit" type="application/vnd.vmware.vcloud.networkConnectionSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/networkConnectionSection/"/>
01:01:35.233             </NetworkConnectionSection>
01:01:35.233             <GuestCustomizationSection type="application/vnd.vmware.vcloud.guestCustomizationSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/guestCustomizationSection/" ovf:required="false">
01:01:35.233                 <ovf:Info>Specifies Guest OS Customization Settings</ovf:Info>
01:01:35.233                 <Enabled>true</Enabled>
01:01:35.233                 <ChangeSid>false</ChangeSid>
01:01:35.233                 <VirtualMachineId>1a23fcff-9acd-4c74-bf42-4126e8f4fdb5</VirtualMachineId>
01:01:35.234                 <JoinDomainEnabled>false</JoinDomainEnabled>
01:01:35.234                 <UseOrgSettings>false</UseOrgSettings>
01:01:35.234                 <AdminPasswordEnabled>false</AdminPasswordEnabled>
01:01:35.234                 <AdminPasswordAuto>true</AdminPasswordAuto>
01:01:35.234                 <ResetPasswordRequired>false</ResetPasswordRequired>
01:01:35.234                 <ComputerName>tst</ComputerName>
01:01:35.234                 <Link rel="edit" type="application/vnd.vmware.vcloud.guestCustomizationSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/guestCustomizationSection/"/>
01:01:35.235             </GuestCustomizationSection>
01:01:35.235             <RuntimeInfoSection xmlns:vcloud="http://www.vmware.com/vcloud/v1.5" vcloud:href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/runtimeInfoSection" vcloud:type="application/vnd.vmware.vcloud.virtualHardwareSection+xml">
01:01:35.235                 <ovf:Info>Specifies Runtime info</ovf:Info>
01:01:35.235                 <VMWareTools version="9410"/>
01:01:35.235             </RuntimeInfoSection>
01:01:35.235             <SnapshotSection type="application/vnd.vmware.vcloud.snapshotSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/snapshotSection" ovf:required="false">
01:01:35.235                 <ovf:Info>Snapshot information section</ovf:Info>
01:01:35.236             </SnapshotSection>
01:01:35.236             <VAppScopedLocalId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedLocalId>
01:01:35.236             <ovfenv:Environment xmlns:ns10="http://www.vmware.com/schema/ovfenv" ovfenv:id="" ns10:vCenterId="vm-38818">
01:01:35.236                 <ovfenv:PlatformSection>
01:01:35.236                     <ovfenv:Kind>VMware ESXi</ovfenv:Kind>
01:01:35.236                     <ovfenv:Version>5.5.0</ovfenv:Version>
01:01:35.236                     <ovfenv:Vendor>VMware, Inc.</ovfenv:Vendor>
01:01:35.236                     <ovfenv:Locale>en</ovfenv:Locale>
01:01:35.236                 </ovfenv:PlatformSection>
01:01:35.236                 <ovfenv:PropertySection>
01:01:35.236                     <ovfenv:Property ovfenv:value="None" ovfenv:key="vCloud_UseSysPrep"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="1" ovfenv:key="vCloud_bitMask"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="static" ovfenv:key="vCloud_bootproto_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="tst" ovfenv:key="vCloud_computerName"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="8.8.8.8" ovfenv:key="vCloud_dns1_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="8.8.4.4" ovfenv:key="vCloud_dns2_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="10.1.1.1" ovfenv:key="vCloud_gateway_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="10.1.1.2" ovfenv:key="vCloud_ip_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="00:50:56:01:0d:5b" ovfenv:key="vCloud_macaddr_0"/>
01:01:35.237                     <ovfenv:Property ovfenv:value="9c21a5fa-88be-4bb9-a105-429e9c7856bd" ovfenv:key="vCloud_markerid"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="255.255.255.0" ovfenv:key="vCloud_netmask_0"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="1" ovfenv:key="vCloud_numnics"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="0" ovfenv:key="vCloud_primaryNic"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="724152379" ovfenv:key="vCloud_reconfigToken"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="0" ovfenv:key="vCloud_resetPassword"/>
01:01:35.238                     <ovfenv:Property ovfenv:value="" ovfenv:key="vCloud_suffix_0"/>
01:01:35.238                 </ovfenv:PropertySection>
01:01:35.238                 <ve:EthernetAdapterSection xmlns:ve="http://www.vmware.com/schema/ovfenv" xmlns="http://schemas.dmtf.org/ovf/environment/1" xmlns:oe="http://schemas.dmtf.org/ovf/environment/1">
01:01:35.239                     <ve:Adapter ve:mac="00:50:56:01:0d:5b" ve:network="vxw-dvs-3650-virtualwire-652-sid-5060-dvs.VCDVSVagrant-vApp-Net-33c7843a-7c8f-4c" ve:unitNumber="7"/>
01:01:35.239    
01:01:35.239                 </ve:EthernetAdapterSection>
01:01:35.239             </ovfenv:Environment>
01:01:35.239             <VmCapabilities type="application/vnd.vmware.vcloud.vmCapabilitiesSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/vmCapabilities/">
01:01:35.239                 <Link rel="edit" type="application/vnd.vmware.vcloud.vmCapabilitiesSection+xml" href="https://roecloud001/api/vApp/vm-1a23fcff-9acd-4c74-bf42-4126e8f4fdb5/vmCapabilities/"/>
01:01:35.240                 <MemoryHotAddEnabled>false</MemoryHotAddEnabled>
01:01:35.240                 <CpuHotAddEnabled>false</CpuHotAddEnabled>
01:01:35.240             </VmCapabilities>
01:01:35.240             <StorageProfile type="application/vnd.vmware.vcloud.vdcStorageProfile+xml" name="*" href="https://roecloud001/api/vdcStorageProfile/59bc6f09-4ba6-48b6-ac21-636e778917bd"/>
01:01:35.240         </Vm>
01:01:35.240     </Children>
01:01:35.240 </VApp>
01:01:35.241 DEBUG read_ssh_info: Getting port forwarding rules...
01:01:35.241 "[Mon Jun 30 11:57:46 2014] -> SEND GET https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/networkConfigSection"
01:01:35.473 "[Mon Jun 30 11:57:47 2014] <- RECV 200"
01:01:35.473 "RECV HEADERS"
01:01:35.474 {
01:01:35.474               "Date" => "Mon, 30 Jun 2014 09:57:45 GMT",
01:01:35.475               "Vary" => "Accept-Encoding",
01:01:35.475       "Content-Type" => "application/vnd.vmware.vcloud.networkconfigsection+xml;version=5.1",
01:01:35.475     "Content-Length" => "4864"
01:01:35.475 }
01:01:35.475 "RECV BODY"
01:01:35.475 <?xml version="1.0" encoding="UTF-8"?>
01:01:35.475 <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-395d08ec-99b1-4b41-baf4-d171d97db78d/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">
01:01:35.476     <ovf:Info>The configuration parameters for logical networks</ovf:Info>
01:01:35.476     <Link rel="edit" type="application/vnd.vmware.vcloud.networkConfigSection+xml" href="https://roecloud001/api/vApp/vapp-395d08ec-99b1-4b41-baf4-d171d97db78d/networkConfigSection/"/>
01:01:35.477     <NetworkConfig networkName="Vagrant-vApp-Net">
01:01:35.478         <Link rel="repair" href="https://roecloud001/api/admin/network/794acb54-2831-4a4f-9e80-b73f42bdb978/action/reset"/>
01:01:35.478         <Link rel="syncSyslogSettings" type="application/vnd.vmware.vcloud.task+xml" href="https://roecloud001/api/admin/network/794acb54-2831-4a4f-9e80-b73f42bdb978/action/syncSyslogServerSettings"/>
01:01:35.478         <Description/>
01:01:35.478         <Configuration>
01:01:35.478             <IpScopes>
01:01:35.478                 <IpScope>
01:01:35.478                     <IsInherited>false</IsInherited>
01:01:35.478                     <Gateway>10.1.1.1</Gateway>
01:01:35.478                     <Netmask>255.255.255.0</Netmask>
01:01:35.478                     <Dns1>8.8.8.8</Dns1>
01:01:35.478                     <Dns2>8.8.4.4</Dns2>
01:01:35.478                     <IsEnabled>true</IsEnabled>
01:01:35.478                     <IpRanges>
01:01:35.479                         <IpRange>
01:01:35.479                             <StartAddress>10.1.1.2</StartAddress>
01:01:35.479                             <EndAddress>10.1.1.254</EndAddress>
01:01:35.479                         </IpRange>
01:01:35.479                     </IpRanges>
01:01:35.479                     <AllocatedIpAddresses>
01:01:35.479                         <IpAddress>10.1.1.2</IpAddress>
01:01:35.479                         <IpAddress>10.1.1.1</IpAddress>
01:01:35.479                     </AllocatedIpAddresses>
01:01:35.479                 </IpScope>
01:01:35.479             </IpScopes>
01:01:35.479             <ParentNetwork name="SS-INTERNAL" id="3fd7a97b-b182-41a0-8df5-3b67b5c08b27" href="https://roecloud001/api/admin/network/3fd7a97b-b182-41a0-8df5-3b67b5c08b27"/>
01:01:35.479             <FenceMode>natRouted</FenceMode>
01:01:35.479             <RetainNetInfoAcrossDeployments>false</RetainNetInfoAcrossDeployments>
01:01:35.480             <Features>
01:01:35.480                 <FirewallService>
01:01:35.480                     <IsEnabled>false</IsEnabled>
01:01:35.480                     <DefaultAction>drop</DefaultAction>
01:01:35.480                     <LogDefaultAction>false</LogDefaultAction>
01:01:35.480                 </FirewallService>
01:01:35.480                 <NatService>
01:01:35.480                     <IsEnabled>true</IsEnabled>
01:01:35.480                     <NatType>portForwarding</NatType>
01:01:35.480                     <Policy>allowTraffic</Policy>
01:01:35.480                     <NatRule>
01:01:35.480                         <Id>65537</Id>
01:01:35.480                         <VmRule>
01:01:35.480                             <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.481                             <ExternalPort>2224</ExternalPort>
01:01:35.481                             <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.481                             <VmNicId>0</VmNicId>
01:01:35.481                             <InternalPort>22</InternalPort>
01:01:35.481                             <Protocol>TCP</Protocol>
01:01:35.481                         </VmRule>
01:01:35.481                     </NatRule>
01:01:35.481                     <NatRule>
01:01:35.481                         <Id>65538</Id>
01:01:35.481                         <VmRule>
01:01:35.481                             <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.481                             <ExternalPort>2225</ExternalPort>
01:01:35.481                             <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.482                             <VmNicId>0</VmNicId>
01:01:35.482                             <InternalPort>3389</InternalPort>
01:01:35.482                             <Protocol>TCP</Protocol>
01:01:35.482                         </VmRule>
01:01:35.482                     </NatRule>
01:01:35.482                     <NatRule>
01:01:35.482                         <Id>65539</Id>
01:01:35.482                         <VmRule>
01:01:35.482                             <ExternalIpAddress>10.115.4.4</ExternalIpAddress>
01:01:35.482                             <ExternalPort>2226</ExternalPort>
01:01:35.482                             <VAppScopedVmId>e3594203-874a-48ae-b882-7696055d3e16</VAppScopedVmId>
01:01:35.482                             <VmNicId>0</VmNicId>
01:01:35.482                             <InternalPort>5985</InternalPort>
01:01:35.482                             <Protocol>TCP</Protocol>
01:01:35.483                         </VmRule>
01:01:35.483                     </NatRule>
01:01:35.483                 </NatService>
01:01:35.483             </Features>
01:01:35.483             <SyslogServerSettings/>
01:01:35.483             <RouterInfo>
01:01:35.483                 <ExternalIp>10.115.4.4</ExternalIp>
01:01:35.483             </RouterInfo>
01:01:35.483         </Configuration>
01:01:35.483         <IsDeployed>true</IsDeployed>
01:01:35.483     </NetworkConfig>
01:01:35.483 </NetworkConfigSection>
01:01:35.483 DEBUG read_ssh_info: WinRM INFO: IP 10.115.4.4 and Port 2226
01:01:35.484 DEBUG read_ssh_info: WinRM Connection successful !
01:01:35.484  INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ReadSSHInfo:0x311d5e8>
01:01:35.485  INFO warden: Calling OUT action: #<VagrantPlugins::VCloud::Action::ConnectVCloud:0x30cc360>
01:01:35.485 DEBUG winrmshell: initializing WinRMShell
01:01:35.486 DEBUG winrmshell: powershell executing:
01:01:35.486             $command = [Array](Get-Command rsync -errorAction SilentlyContinue)
01:01:35.486             if ($null -eq $command) { exit 1 }
01:01:35.486             write-host $command[0].Definition
01:01:35.486             exit 0
01:01:35.486 

01:01:35.486 if ($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 0 }
01:01:35.487  INFO winrmshell: Attempting to connect to WinRM...
01:01:35.487  INFO winrmshell:   - Host: 10.115.4.4
01:01:35.487  INFO winrmshell:   - Port: 2226
01:01:35.488  INFO winrmshell:   - Username: vagrant
01:01:58.137 ERROR warden: Error occurred: An error occurred executing a remote WinRM command.
01:01:58.137 
01:01:58.137 Shell: powershell
01:01:58.137 Command:             $command = [Array](Get-Command rsync -errorAction SilentlyContinue)
01:01:58.137             if ($null -eq $command) { exit 1 }
01:01:58.137             write-host $command[0].Definition
01:01:58.137             exit 0
01:01:58.137 

01:01:58.137 if ($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 0 }
01:01:58.137 Message: A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. - connect(2) (http://10.115.4.4:2226)
01:01:58.138  INFO warden: Beginning recovery process...
01:01:58.138  INFO warden: Calling recover: #<Vagrant::Action::Builtin::Call:0x3137088>
01:01:58.138  INFO warden: Beginning recovery process...
01:01:58.138  INFO warden: Recovery complete.
01:01:58.138  INFO warden: Recovery complete.
01:01:58.138  INFO warden: Beginning recovery process...
01:01:58.138  INFO warden: Recovery complete.
01:01:58.138 ERROR warden: Error occurred: An error occurred executing a remote WinRM command.
01:01:58.138 
01:01:58.138 Shell: powershell
01:01:58.139 Command:             $command = [Array](Get-Command rsync -errorAction SilentlyContinue)
01:01:58.139             if ($null -eq $command) { exit 1 }
01:01:58.139             write-host $command[0].Definition
01:01:58.139             exit 0
01:01:58.139 
StefanScherer commented 10 years ago

This "Get-Command rsync" comes from the vagrant-vcloud/action/rsync_folders.rb in this line:

          unless Vagrant::Util::Which.which('rsync')

The "wait_for_communicator" is not used until then. Perhaps we have to get rid of the plugin internal rsync feature and use Vagrants core functions. I'll try to dig deeper...

frapposelli commented 10 years ago

@StefanScherer good point, I've been holding back the move to the sync builtin to maintain compatibility with older Vagrant versions, but I think it's time to move on, marking this for 0.5.0.

StefanScherer commented 10 years ago

I had the luck to watch a Windows 2012 R2 guest powering on for the first time and the vagrant up console in parallel.

C:\Users\vagrant\Documents\project1>vagrant up --provider=vcloud
Bringing machine 'default' up with 'vcloud' provider...
==> default: Building vApp...
==> default: vApp Vagrant-vagrant-vagrant-2012-5c3f0821 successfully created.
==> default: Setting VM hardware...
==> default: Powering on VM...
==> default: Fixed port collision for 22 => 2222. Now on port 2209.
==> default: Forwarding Ports: VM port 22 -> vShield Edge port 2209
==> default: Rsyncing folder: /cygdrive/C/Users/vagrant/Documents/project1/ => /vagrant

The box auto logins (as my vagrant boxes do). This is a very simple Vagrantfile without any provisioning scripts. Right after the last message, the VM shuts down and reboots.

So I am sure that the guest customization reboot for the windows hosts kicks in too late and the plugin just wants to rsync and provision. That could explain why sometimes the first WinRM command works and another command just crashes.

How to wait until the guest customization is really finished?

WinRM + SSH ports are open for a short time, and the plugin steps further, then the VM reboots. After the reboot, the windows guest comes up with the login screen, no more auto login.

StefanScherer commented 10 years ago

I have captured a short video showing the issue.

Here is the debug output of the last 8000 lines (my cmd shell was set too small) in a gist: https://gist.github.com/StefanScherer/8aea7db4c2dcea47936c#file-vagrant-up-tst

What I did: vagrant up a vApp with two windows machines, then destroy one of them, and then create it again. This reduces the vagrant up time, because the Edge Gateway Forwardings are still there and so the vagrant plugin speeds up a little bit.

The steps not shown in the video are:

git clone https://github.com/StefanScherer/vcloud-scenarios
cd vcloud-scenarios\windows\vappnetwork\windows_2008_r2
vagrant up --provider=vcloud
vagrant destroy -f tst

Then I started the screen capture and just did

vagrant up tst --provider=vcloud

In the video the Windows machine is rebooted just after the plugin checked the SSH port and the WinRM port and thinks it could start provisioning.

The video is here:

https://www.dropbox.com/s/qbgxnc3miq5plk4/vagrant-up-winrm-provisioning-fails.webm

The problem does not occur every time, but it occurs very often.

My thoughts what to do with this problem are:

Any better ideas?

StefanScherer commented 10 years ago

Instead of adding a sleep to read_ssh_info I had a look into vagrant's source and have found another interesting function:

In action.rb I have modified the action_boot to call WaitForCommunicatorin advance to Provision and SyncFolders. That seem to do the trick.

      def self.action_boot
        Vagrant::Action::Builder.new.tap do |b|
          b.use ConfigValidate
          b.use PowerOn
          b.use Call, IsCreated do |env, b2|
            unless env[:bridged_network]
              b2.use HandleNATPortCollisions
              b2.use ForwardPorts
            end
          end
          b.use WaitForCommunicator, [:starting, :running] 
          b.use Provision
          b.use SyncFolders
        end
      end

See also Vagrant plugins/providers/virtualbox/action.rb

I'll do some more testing with Unix boxes as well.

mikecali commented 7 years ago

I encounter issue like this. I am using virtualbox as my provider.

$ vagrant up Bringing machine 'windows' up with 'virtualbox' provider... ==> windows: Importing base box 'ferventcoder/win2008r2-x64-nocm'... ==> windows: Matching MAC address for NAT networking... ==> windows: Checking if box 'ferventcoder/win2008r2-x64-nocm' is up to date... ==> windows: Setting the name of the VM: windows ==> windows: Clearing any previously set network interfaces... ==> windows: Preparing network interfaces based on configuration... windows: Adapter 1: nat windows: Adapter 2: hostonly ==> windows: Forwarding ports... windows: 3389 (guest) => 3389 (host) (adapter 1) windows: 5985 (guest) => 5985 (host) (adapter 1) windows: 5985 (guest) => 55985 (host) (adapter 1) windows: 5986 (guest) => 55986 (host) (adapter 1) ==> windows: Running 'pre-boot' VM customizations... ==> windows: Booting VM... ==> windows: Waiting for machine to boot. This may take a few minutes... windows: WinRM address: 127.0.0.1:5985 windows: WinRM username: vagrant windows: WinRM execution_time_limit: PT2H windows: WinRM transport: plaintext An error occurred executing a remote WinRM command.

Shell: powershell Command: $ProgressPreference='SilentlyContinue'; hostname if ($?) { exit 0 } else { if($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 1 } } Message: uninitialized constant WinRM::WinRMWebService Did you mean? WinRM::WinRMWMIError

This error actually produce a running VM. But when I tried to reload the result will be below:

$ vagrant reload ==> windows: Attempting graceful shutdown of VM... An error occurred executing a remote WinRM command.

Shell: powershell Command: $ProgressPreference='SilentlyContinue'; hostname if ($?) { exit 0 } else { if($LASTEXITCODE) { exit $LASTEXITCODE } else { exit 1 } } Message: uninitialized constant WinRM::WinRMWebService Did you mean? WinRM::WinRMWMIError

Here is my linux host environment:

VirtualBox Graphical User Interface Version 5.1.14 r112924 (Qt5.6.2)

$ vagrant plugin list hostmanager (1.2.2) vagrant-cachier (1.2.1, system) vagrant-vbguest (0.13.0) winrm (2.1.3) winrm-fs (1.0.1)

$ vagrant -v Vagrant 1.8.1

Here is my Vagrantfile:

Vagrant.configure("2") do |config| config.vm.define "windows" do |windows| windows.vm.box = "ferventcoder/win2008r2-x64-nocm" windows.vm.network :private_network, ip: "192.168.58.64" windows.vm.network "forwarded_port", host: 3389, guest: 3389 windows.vm.network :forwarded_port, guest: 5985, host: 5985 windows.vm.communicator = "winrm" windows.winrm.retry_limit = 30 windows.winrm.retry_delay = 10 windows.vm.provider :virtualbox do |v| v.name = "windows" v.memory = 2048 v.cpus = 1 end end end

By the way, I am running this on Fedora 25.

Note that I tried to set my environment variable to no_proxy/NO_PROXY but still to no avail.