HTTPClient ConnectTimeoutError when powering on a VM via the UI


#1

When attempting to power on a VM via the ManageIQ UI (Botvinnik-1-RC2), the VM does not power on in vCenter, and the following error appears in evm.log:

[----] E, [2015-04-10T10:06:32.000925 #9890:331c1c8] ERROR -- : <VIM> MiqVimBroker.getMiqVim: failed to create new connection for REDACTEDHOSTNAME_REDACTEDUSER
[----] E, [2015-04-10T10:06:32.001085 #9890:331c1c8] ERROR -- : <VIM> HTTPClient::ConnectTimeoutError: execution expired
[----] E, [2015-04-10T10:06:32.002023 #9550:971e90] ERROR -- : MIQ(MiqQueue.deliver)    Message id: [12950], Error: [execution expired]
[----] E, [2015-04-10T10:06:32.002204 #9550:971e90] ERROR -- : [HTTPClient::ConnectTimeoutError]: execution expired  Method:[rescue in deliver]
[----] E, [2015-04-10T10:06:32.002352 #9550:971e90] ERROR -- : (druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/timeout.rb:70:in `join'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/timeout.rb:70:in `timeout'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/timeout.rb:97:in `timeout'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:888:in `parse_header'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:849:in `connect_ssl_proxy'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:769:in `block in connect'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:762:in `connect'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:620:in `query'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient/session.rb:164:in `query'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:1161:in `do_get_block'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:962:in `block in do_request'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:1059:in `protect_keep_alive_disconnected'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:961:in `do_request'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:823:in `request'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/httpclient-2.5.3.3/lib/httpclient.rb:726:in `post'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/handsoap-daec1277652f/lib/handsoap/service.rb:280:in `dispatch'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/handsoap-daec1277652f/lib/handsoap/service.rb:192:in `invoke'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/VimService.rb:878:in `retrieveServiceContent'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/VimService.rb:21:in `initialize'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimClientBase.rb:33:in `initialize'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimInventory.rb:23:in `initialize'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVim.rb:24:in `initialize'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/DMiqVim.rb:32:in `initialize'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:389:in `new'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:389:in `block in getMiqVim'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:340:in `call'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:340:in `connSync'
(druby://127.0.0.1:58642) /var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:378:in `getMiqVim'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/drb/drb.rb:1588:in `perform_without_block'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/drb/drb.rb:1548:in `perform'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/drb/drb.rb:1626:in `block (2 levels) in main_loop'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/drb/drb.rb:1622:in `loop'
(druby://127.0.0.1:58642) /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/drb/drb.rb:1622:in `block in main_loop'
(druby://127.0.0.1:58642) /var/www/miq/vmdb/lib/extensions/ar_thread.rb:22:in `block in start_with_release'
/var/www/miq/lib/VMwareWebService/MiqVimBroker.rb:373:in `getMiqVim'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:188:in `_connect_with_broker'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:174:in `block in _connect'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:86:in `_execute_with_broker'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:75:in `_execute'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:172:in `_connect'
/var/www/miq/lib/util/miq_fault_tolerant_vim.rb:29:in `initialize'
/var/www/miq/vmdb/app/models/mixins/vim_connect_mixin.rb:24:in `new'
/var/www/miq/vmdb/app/models/mixins/vim_connect_mixin.rb:24:in `connect'
/var/www/miq/vmdb/app/models/mixins/vim_connect_mixin.rb:38:in `with_provider_connection'
/var/www/miq/vmdb/app/models/mixins/provider_object_mixin.rb:13:in `with_provider_object'
/var/www/miq/vmdb/app/models/ems_vmware.rb:406:in `invoke_vim_ws'
/var/www/miq/vmdb/app/models/ems_vmware.rb:125:in `vm_start'
/var/www/miq/vmdb/app/models/vm_or_template.rb:334:in `run_command_via_parent'
/var/www/miq/vmdb/app/models/vm_or_template/operations/power.rb:3:in `raw_start'
/var/www/miq/vmdb/app/models/vm_or_template/operations/power.rb:7:in `start'
/var/www/miq/vmdb/app/models/miq_queue.rb:356:in `block in deliver'
/opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/timeout.rb:66:in `timeout'
/var/www/miq/vmdb/app/models/miq_queue.rb:352:in `deliver'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:107:in `deliver_queue_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:135:in `deliver_message'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:152:in `block in do_work'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `loop'
/var/www/miq/vmdb/lib/workers/queue_worker_base.rb:146:in `do_work'
/var/www/miq/vmdb/lib/workers/worker_base.rb:323:in `block in do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:320:in `do_work_loop'
/var/www/miq/vmdb/lib/workers/worker_base.rb:141:in `run'
/var/www/miq/vmdb/lib/workers/worker_base.rb:122:in `start'
/var/www/miq/vmdb/lib/workers/worker_base.rb:23:in `start_worker'
/var/www/miq/vmdb/lib/workers/bin/worker.rb:3:in `<top (required)>'
/opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval'
/opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>'
/opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require'
/opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>'
script/rails:6:in `require'
script/rails:6:in `<main>'

I have an instance running anand-1 connected to the same vCenter server, and I can successfully power on VMs from there.

Let me know if there’s any additional logging/debugging information I can provide.


#2

Tracked this issue down to a bonehead mistake: I just happened to start EVM from a terminal session that had a http_proxy environment variable set. EVM picked up the variable and was trying to communicate to our vCenter through the proxy.

Apologies for the false alarm. :slight_smile: