Duplicated machine on deployment request using version 0.3.0

[carlossm]

Describe the bug

Deploying a VM from a template, contained in a vSphere 6.7 U2 content library, consistently results in a duplicated virtual machine exception. It might be because of a duplicated POST request to the API, if I'm understanding the debugging output correctly.

How to reproduce

You can find below some example code I'm using to reproduce the error:
(I'm verifying there are no virtual machines before executing it)

# Client connection
client_config = ::VSphereAutomation::Configuration.new.tap do |c|
  c.host = host
  c.username = user
  c.password = pass
  c.scheme = 'https'
  c.verify_ssl = false
  c.verify_ssl_host = false
  c.debugging = true
end
client = ::VSphereAutomation::ApiClient.new(client_config)
client.default_headers['Authorization'] = client_config.basic_auth_token
session_id = ::VSphereAutomation::CIS::SessionApi.new(client).create('').value
client.default_headers['vmware-api-session-id'] = session_id

# Target
target_host_id = "host-28"
folder_id = "group-v1050"
resource_pool = "resgroup-194"
target = VSphereAutomation::VCenter::VcenterOvfLibraryItemDeploymentTarget.new(
  host_id: target_host_id,
  resource_pool_id: resource_pool,
  folder_id: folder_id
)

# Deployment
name = "test-machine"
datastore_id = "..."
template_id = "..."
network_mapping = [{:key=>"bridged", :value=>"network-o1060"}]

deploy_spec = VSphereAutomation::VCenter::VcenterOvfLibraryItemResourcePoolDeploymentSpec.new(
  name: name,
  accept_all_EULA: true,
  default_datastore_id: datastore_id,
  network_mappings: network_mapping,
  storage_provisioning: VSphereAutomation::VCenter::VcenterOvfDiskProvisioningType::THIN
)
deploy = VSphereAutomation::VCenter::VcenterOvfLibraryItemDeploy.new(
  deployment_spec: deploy_spec,
  target: target
)

VSphereAutomation::VCenter::OvfLibraryItemApi.new(client).deploy(template_id, deploy)

Output

The machine gets created, but it returns a "virtual machine" duplication error:

Calling API: OvfLibraryItemApi.deploy ...
HTTP request body param ~BEGIN~
{"target":{"resource_pool_id":"resgroup-194","host_id":"host-28","folder_id":"group-v1050"},"deployment_spec":{"name":"test-machine","accep$
_all_EULA":true,"network_mappings":[{"key":"bridged","value":"network-o1060"}],"storage_provisioning":"thin","default_datastore_id":"datast$re-39"}}                                                                                                                                    ~END~

Found bundle for host vcsa-jil.vmware.local: 0x5563b9d6fd10 [can pipeline]
Re-using existing connection! (#6) with host vcsa-jil.vmware.local
Connected to vcsa-jil.vmware.local (192.168.223.1) port 443 (#6)
POST /rest/com/vmware/vcenter/ovf/library-item/id:69eb2a19-bfe2-4b5e-85e8-c367f05008d7?~action=deploy HTTP/1.1
Host: vcsa-jil.vmware.local
User-Agent: SDK/0.3.0 Ruby/2.3.8 (linux; ; x86_64)                                                                                          Content-Type: application/json
Authorization: Basic ...
vmware-api-session-id: ...
Accept: application/json
Content-Length: 288

upload completely sent off: 288 out of 288 bytes                                                                                            Connection died, retrying a fresh connect                                                                                                   Curl_http_done: called premature == 0
Closing connection 6
TLSv1.2 (OUT), TLS alert, Client hello (1):
Issue another request to this URL: 'https://vcsa-jil.vmware.local/rest/com/vmware/vcenter/ovf/library-item/id:69eb2a19-bfe2-4b5e-85e8-c367f$
5008d7?~action=deploy'
Hostname vcsa-jil.vmware.local was found in DNS cache
  Trying 192.168.223.1...
TCP_NODELAY set
Connected to vcsa-jil.vmware.local (192.168.223.1) port 443 (#7)
ALPN, offering http/1.1
Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
successfully set certificate verify locations:
  CAfile: /etc/ssl/certs/ca-certificates.crt
  CApath: /etc/ssl/certs
SSL re-using session ID
TLSv1.2 (OUT), TLS handshake, Client hello (1):
...some binary output...
SSL connection using TLSv1.2 / ECDHE-RSA-AES256-GCM-SHA384
ALPN, server did not agree to a protocol
old SSL session ID is stale, removing
Server certificate:
 ...
POST /rest/com/vmware/vcenter/ovf/library-item/id:69eb2a19-bfe2-4b5e-85e8-c367f05008d7?~action=deploy HTTP/1.1
Host: vcsa-jil.vmware.local
User-Agent: SDK/0.3.0 Ruby/2.3.8 (linux; ; x86_64)
Content-Type: application/json
Authorization: Basic ...
vmware-api-session-id: ...
Accept: application/json
Content-Length: 288

upload completely sent off: 288 out of 288 bytes
oHTTP/1.1 200 OK
Date: Wed, 25 Sep 2019 11:36:56 GMT
Content-Type: application/json
Transfer-Encoding: chunked

Curl_http_done: called premature == 0
Connection #7 to host vcsa-jil.vmware.local left intact
HTTP response body ~BEGIN~
{"value":{"error":{"errors":[{"category":"SERVER","error":{"@class":"com.vmware.vapi.std.errors.already_exists","messages":[{"args":["VirtualMachine","test$
machine"],"default_message":"An object of type \"VirtualMachine\" named \"test-machine\" already exists.","id":"com.vmware.vdcs.util.duplic$
te_name"}]}}]},"succeeded":false}}
~END~

API called: OvfLibraryItemApi#deploy
Data: #<VSphereAutomation::VCenter::VcenterOvfLibraryItemDeployResult:0x00005563b61774f0 @value=#<VSphereAutomation::VCenter::VcenterOvfLibr
aryItemDeploymentResult:0x00005563b6176a78 @succeeded=false, @error=#<VSphereAutomation::VCenter::VcenterOvfLibraryItemResultInfo:0x00005563
b6175e20 @errors=[#<VSphereAutomation::VCenter::VcenterOvfOvfError:0x00005563b61752b8 @category="SERVER", @error={:@class=>"com.vmware.vapi.
std.errors.already_exists", :messages=>[{:args=>["VirtualMachine", "test-machine"], :default_message=>"An object of type \"VirtualMachine\"
named \"test-machine\" already exists.", :id=>"com.vmware.vdcs.util.duplicate_name"}]}>], @warnings=[], @informatio
n=[]>>>
Status code: 200
Headers: {"Date"=>"Wed, 25 Sep 2019 11:36:56 GMT", "Content-Type"=>"application/json", "Transfer-Encoding"=>"chunked"}

=> #<VSphereAutomation::VCenter::VcenterOvfLibraryItemDeployResult:0x00005563b61774f0
 @value=
  #<VSphereAutomation::VCenter::VcenterOvfLibraryItemDeploymentResult:0x00005563b6176a78
   @error=
    #<VSphereAutomation::VCenter::VcenterOvfLibraryItemResultInfo:0x00005563b6175e20
     @errors=
      [#<VSphereAutomation::VCenter::VcenterOvfOvfError:0x00005563b61752b8
        @category="SERVER",
        @error=
         {:@class=>"com.vmware.vapi.std.errors.already_exists",
          :messages=>
           [{:args=>["VirtualMachine", "test-machine"],
             :default_message=>"An object of type \"VirtualMachine\" named \"test-machine\" already exists.",
             :id=>"com.vmware.vdcs.util.duplicate_name"}]}>],
     @information=[],
     @warnings=[]>,
   @succeeded=false>>

Versions

• Ruby: tried with different versions from 2.3 to 2.6 with the same result
• vSphere Automation SDK: tried with different versions up to 0.3.0
• OS: linux

Additional notes

I wonder if this may be connected to a retry on the http client. Not sure if that output message means it is actually issuing another request:

Issue another request to this URL: 'https://vcsa-jil.vmware.local/rest/com/vmware/vcenter/ovf/library-item/id:69eb2a19-bfe2-4b5e-85e8-c367f$
5008d7?~action=deploy

It seems that the "typhoeus" dependency was removed in >= 0.4.0, not sure if that might fix the problem I'm finding. However, I haven't been able to test those versions because I'm getting NotFound errors, similar to the ones described in #57.

[jrgarcia]

Now that #57 has been fixed, please give v0.4.3 a try and see if that fixes the issue for you. Thanks for reporting @carlossm!

[carlossm]

Thank you for the fix.

Now with the latest version, it seems I'm getting an EOF error instead of the "duplicated machine":

pry(main)> VSphereAutomation::VCenter::OvfLibraryItemApi.new(client).deploy(template_id, deploy)                        
Calling API: OvfLibraryItemApi.deploy ...                                                                    
Request Body:                                                                                                            
{"target":{"resource_pool_id":"resgroup-194","host_id":"host-28","folder_id":"group-v1050"},"deployment_spec":{"name":"test-machine-8","acce
pt_all_EULA":true,"network_mappings":[{"key":"bridged","value":"network-o1060"}],"storage_provisioning":"thin","default_datastore_id":"datas
tore-39"}}

EOFError: end of file reached
lib/ruby/2.6.0/net/protocol.rb:225:in `rbuf_fill'
lib/ruby/2.6.0/net/protocol.rb:191:in `readuntil'
lib/ruby/2.6.0/net/protocol.rb:201:in `readline'
lib/ruby/2.6.0/net/http/response.rb:40:in `read_status_line'
lib/ruby/2.6.0/net/http/response.rb:29:in `read_new'
lib/ruby/2.6.0/net/http.rb:1509:in `block in transport_request'
lib/ruby/2.6.0/net/http.rb:1506:in `catch'
lib/ruby/2.6.0/net/http.rb:1506:in `transport_request'
lib/ruby/2.6.0/net/http.rb:1479:in `request'
lib/ruby/2.6.0/net/http.rb:1472:in `block in request'
lib/ruby/2.6.0/net/http.rb:920:in `start'
lib/ruby/2.6.0/net/http.rb:1470:in `request'
lib/ruby/gems/2.6.0/gems/vsphere-automation-runtime-0.4.3/lib/vsphere-automation-runtime/api_client.rb:71:in `call_api'
lib/ruby/gems/2.6.0/gems/vsphere-automation-vcenter-0.4.3/lib/vsphere-automation-vcenter/api/ovf_library_item_api.rb:123:in `deploy_with_http_info'
lib/ruby/gems/2.6.0/gems/vsphere-automation-vcenter-0.4.3/lib/vsphere-automation-vcenter/api/ovf_library_item_api.rb:82:in `deploy'
(pry):48:in `<main>'

Any ideas?

[jrgarcia]

I'll take a look. Not sure what's causing it.

[NJSchulz]

FYI...we just updated to vCenter 6.7U3 and are still seeing the same issue.

[jrgarcia]

@carlossm @NJSchulz Could you take a look at v0.4.4 and set a timeout to see if that allows the deploy to finish properly? You can configure it through the Configuration object

configuration = VSphereAutomation::Configuration.new.tap do |c|
  c.timeout = 100000
  # the rest of your configuration details
end

[carlossm]

FYI @jrgarcia, I ran some tests with the timeout option set, but it seems we still get the 'end of file' exception with any version 0.4.*. With the latest version the backtrace is similar to the one I already mentioned:

end of file reached
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/protocol.rb:225:in `rbuf_fill'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/protocol.rb:191:in `readuntil'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/protocol.rb:201:in `readline'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http/response.rb:40:in `read_status_line'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http/response.rb:29:in `read_new'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1509:in `block in transport_request'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1506:in `catch'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1506:in `transport_request'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1479:in `request'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1472:in `block in request'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:920:in `start'
/.rbenv/versions/2.6.5/lib/ruby/2.6.0/net/http.rb:1470:in `request'
/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/vsphere-automation-runtime-0.4.6/lib/vsphere-automation-runtime/api_client.rb:71:in `call_api'
/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/vsphere-automation-vcenter-0.4.6/lib/vsphere-automation-vcenter/api/ovf_library_item_api.rb:123:in `deploy_with_http_info'
/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/vsphere-automation-vcenter-0.4.6/lib/vsphere-automation-vcenter/api/ovf_library_item_api.rb:82:in `deploy'