vCenter refresh issues in RC2

stacybrock · April 15, 2015, 8:22pm

I’m seeing an issue with Botvinnik-1-RC1 where changes made to VMs in vCenter are not being propagated to vmdb.

For example, I created a new VM called testvm-03 in vCenter.

The event is being caught:

[----] I, [2015-04-09T13:03:19.711748 #1954:457e8c]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [18340], MiqWorker id: [116], Zone: [OSU_SIG], Role: [ems_inventory], Server: [], Ident: [ems_1], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.vc_update], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [1, {:server=>"REDACTED", :username=>"REDACTED", :op=>"create", :objType=>"VirtualMachine", :mor=>"vm-111"}], Dequeued in: [3.003519811] seconds
[----] I, [2015-04-09T13:03:19.711913 #1954:457e8c]  INFO -- : MIQ(MiqQueue.deliver)    Message id: [18340], Delivering...
[----] D, [2015-04-09T13:03:19.712433 #1954:457e8c] DEBUG -- : MIQ(EmsRefresh.vc_create_event) Ignoring refresh for EMS id: [1] on event [VirtualMachine-create]
[----] I, [2015-04-09T13:03:19.712793 #1954:457e8c]  INFO -- : MIQ(MiqQueue.delivered)  Message id: [18340], State: [ok], Delivered in [0.000785503] seconds
[----] I, [2015-04-09T13:03:59.780394 #1954:457e8c]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [18344], MiqWorker id: [116], Zone: [OSU_SIG], Role: [ems_inventory], Server: [], Ident: [ems_1], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.vc_update], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [1, {:server=>"REDACTED", :username=>"REDACTED", :op=>"update", :objType=>"VirtualMachine", :mor=>"vm-111", :changedProps=>["config.cpuAffinity.affinitySet", "config.defaultPowerOps.standbyAction", "config.hardware.device", "config.hardware.numCoresPerSocket", "config.version", ...TRIMMED FOR LENGTH... {"name"=>"summary.config.uuid", "op"=>"assign", "val"=>"4213cca9-d64b-cee7-f423-f750e361bf6b"}, {"name"=>"summary.config.vmPathName", "op"=>"assign", "val"=>"[test_vcenter_2] testvm-03/testvm-03.vmx"}, {"name"=>"summary.guest.toolsStatus", "op"=>"assign", "val"=>"toolsNotRunning"}, {"name"=>"summary.runtime.host", "op"=>"assign", "val"=>"host-87"}], :key=>nil, :newKey=>"[test_vcenter_2] testvm-03/testvm-03.vmx"}], Dequeued in: [10.050601271] seconds
[----] I, [2015-04-09T13:03:59.782606 #1954:457e8c]  INFO -- : MIQ(MiqQueue.deliver)    Message id: [18344], Delivering...
[----] I, [2015-04-09T13:03:59.785094 #1954:457e8c]  INFO -- : MIQ(MiqQueue.delivered)  Message id: [18344], State: [ok], Delivered in [0.002485213] seconds

However, the VM never appears in vmdb:

bot_vmdb_production=# select id, name from vms;
 id |    name
----+------------
  2 | CentOS_6.6
  3 | testvm-01
  1 | vctr-vd01
  4 | testvm-02
(4 rows)

Upon restarting EVM, any changes previously made are then picked up and vmdb will again reflect the current state of vCenter.

Another wrinkle is that for a brief period of time after an EVM restart, I can make state changes to the VM in vCenter (powerOn, powerOff, etc) and those will propagate to vmdb as expected. However, after a period of time, even this stops working. (Such events are no longer caught by the EMS worker.)

There are no obvious error messages in the logs. Per the advice of @blomquisg, I’ve bumped up the logging levels to debug on “level”, “level_vim”, and “level_vim_in_evm”.

I also have an instance of ManageIQ anand-1 running against the same vCenter, and changes are propagating there correctly.

Any ideas where to look next?

johnmark · April 9, 2015, 9:01pm

hang tight - RC2 has just been spun. You can grab it now from here: http://releases.manageiq.org/

And it should be integrated into the download workflow in a jiff.

-JM

stacybrock · April 14, 2015, 6:32pm

Edited to say that I am still seeing this issue in RC2 after all.

After starting EVM, I’m able to make changes to VMs in our vCenter via the manageIQ UI for approximately 25 minutes. After that time, manageIQ loses its connection to vCenter and never successfully reconnects.

I am currently putting together a more complete description of the problem and will post it here.

stacybrock · April 15, 2015, 8:22pm

In botvinnik-1-RC2 OVA, we’re seeing issues with connections to vCenter failing silently after approximately 25 minutes of runtime. This prevents the ems workers from being able to properly refresh the current state of vCenter, as well as the event catcher from catching events generated by vCenter. After a services restart, things return to normal for another 25 minutes, before silently beginning to fail again.

There are no obvious errors in the logs. We are seeing mIQ attempt to connect but never returning a “Connected” log entry, like so:

[----] I, [2015-04-13T14:05:17.876385 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:05:17.898688 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] vcenterhost.oregonstate.edu is VC, API version: 5.5
[----] I, [2015-04-13T14:05:17.898799 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-13T14:05:48.770934 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:05:48.792914 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] vcenterhost.oregonstate.edu is VC, API version: 5.5
[----] I, [2015-04-13T14:05:48.793017 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-13T14:09:16.739780 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:09:16.762562 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] vcenterhost.oregonstate.edu is VC, API version: 5.5
[----] I, [2015-04-13T14:09:16.762674 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-13T14:09:39.797028 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:09:39.818807 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] vcenterhost.oregonstate.edu is VC, API version: 5.5
[----] I, [2015-04-13T14:09:39.818928 #2521:11b9e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-13T14:15:51.553632 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:15:51.576668 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] vcenterhost.oregonstate.edu is VC, API version: 5.5
[----] I, [2015-04-13T14:15:51.576795 #2487:10b5e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-13T14:19:04.919127 #2484:5bde98]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:29:00.393795 #4441:ae7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...
[----] I, [2015-04-13T14:34:18.096573 #4563:a93e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [vcenterhost.oregonstate.edu], userid: [username@vsphere.local]...

Corresponding tcpdump on the mIQ box shows no traffic after 14:19:50:

14:16:50.094157 IP miqhost.oregonstate.edu.32859 > vcenterhost.oregonstate.edu.https: Flags [.], ack 9185, win 286, options [nop,nop,TS val 268333211 ecr 131351346], length 0
14:19:05.039284 IP miqhost.oregonstate.edu.32964 > vcenterhost.oregonstate.edu.https: Flags [P.], seq 2602:2639, ack 5420, win 181, options [nop,nop,TS val 268468155 ecr 131337004], length 37
14:19:05.039412 IP miqhost.oregonstate.edu.32964 > vcenterhost.oregonstate.edu.https: Flags [F.], seq 2639, ack 5420, win 181, options [nop,nop,TS val 268468156 ecr 131337004], length 0
14:19:05.040098 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32964: Flags [.], ack 2639, win 172, options [nop,nop,TS val 131385093 ecr 268468155], length 0
14:19:05.040264 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32964: Flags [F.], seq 5420, ack 2640, win 172, options [nop,nop,TS val 131385093 ecr 268468156], length 0
14:19:05.040274 IP miqhost.oregonstate.edu.32964 > vcenterhost.oregonstate.edu.https: Flags [.], ack 5421, win 181, options [nop,nop,TS val 268468157 ecr 131385093], length 0
14:19:05.040983 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [S], seq 2274512904, win 14600, options [mss 1460,sackOK,TS val 268468157 ecr 0,nop,wscale 7], length 0
14:19:05.042174 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [S.], seq 2941576007, ack 2274512905, win 14480, options [mss 1380,sackOK,TS val 131385094 ecr 268468157,nop,wscale 7], length 0
14:19:05.042185 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [.], ack 1, win 115, options [nop,nop,TS val 268468158 ecr 131385094], length 0
14:19:05.042511 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [P.], seq 1:304, ack 1, win 115, options [nop,nop,TS val 268468159 ecr 131385094], length 303
14:19:05.043101 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [.], ack 304, win 122, options [nop,nop,TS val 131385094 ecr 268468159], length 0
14:19:05.043421 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [.], seq 1:1369, ack 304, win 122, options [nop,nop,TS val 131385094 ecr 268468159], length 1368
14:19:05.043428 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [.], ack 1369, win 136, options [nop,nop,TS val 268468160 ecr 131385094], length 0
14:19:05.043450 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [P.], seq 1369:2573, ack 304, win 122, options [nop,nop,TS val 131385094 ecr 268468159], length 1204
14:19:05.043455 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [.], ack 2573, win 157, options [nop,nop,TS val 268468160 ecr 131385094], length 0
14:19:05.044102 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [P.], seq 304:630, ack 2573, win 157, options [nop,nop,TS val 268468160 ecr 131385094], length 326
14:19:05.050848 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [P.], seq 2573:2632, ack 630, win 130, options [nop,nop,TS val 131385096 ecr 268468160], length 59
14:19:05.090138 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [.], ack 2632, win 157, options [nop,nop,TS val 268468207 ecr 131385096], length 0
14:19:50.070873 IP vcenterhost.oregonstate.edu.https > miqhost.oregonstate.edu.32982: Flags [F.], seq 2632, ack 630, win 130, options [nop,nop,TS val 131396351 ecr 268468207], length 0
14:19:50.110127 IP miqhost.oregonstate.edu.32982 > vcenterhost.oregonstate.edu.https: Flags [.], ack 2633, win 157, options [nop,nop,TS val 268513227 ecr 131396351], length 0

vim.log:

[----] I, [2015-04-13T14:15:52.607945 #2556:30dc494]  INFO -- : HandSoap Request  [62557840]: length: [855], URI: [https://vcenterhost.oregonstate.edu/sdk], Content-Type: [text/xml;charset=UT
F-8], SOAPAction: [RetrieveProperties]
[----] I, [2015-04-13T14:15:52.611962 #2556:30dc494]  INFO -- : HandSoap Response [62557840]: length: [541], HTTP-Status: [200], Content-Type: [text/xml; charset=utf-8]
[----] I, [2015-04-13T14:15:52.690647 #2556:3a2021c]  INFO -- : HandSoap Response [57241200]: length: [1314], HTTP-Status: [200], Content-Type: [text/xml; charset=utf-8]
[----] I, [2015-04-13T14:15:52.691776 #2556:3a2021c]  INFO -- : MiqVimUpdate.monitorUpdatesSince (vcenterhost.oregonstate.edu_username@vsphere.local): call to waitForUpdates...Complete (version
 = 30)
[----] I, [2015-04-13T14:15:52.691921 #2556:3a2021c]  INFO -- : MiqVimUpdate.monitorUpdatesSince (vcenterhost.oregonstate.edu_username@vsphere.local): applying update...Starting (version = 32)
[----] D, [2015-04-13T14:15:52.692607 #2556:3a2021c] DEBUG -- : MiqVimUpdate.updateProps (vcenterhost.oregonstate.edu_username@vsphere.local): server = vcenterhost.oregonstate.edu, mor = (Vir
tualMachine, vm-109)
[----] D, [2015-04-13T14:15:52.692697 #2556:3a2021c] DEBUG -- : MiqVimUpdate.updateProps (vcenterhost.oregonstate.edu_username@vsphere.local): changedProps = [ config.hardware.device[3002].conn
ectable.status, summary.runtime.bootTime, summary.runtime.powerState, summary.storage.committed, summary.storage.unshared ]
[----] I, [2015-04-13T14:15:52.692923 #2556:3a2021c]  INFO -- : MiqVimUpdate.monitorUpdatesSince (vcenterhost.oregonstate.edu_username@vsphere.local): applying update...Complete (version = 32)
[----] I, [2015-04-13T14:15:52.693037 #2556:3a2021c]  INFO -- : MiqVimUpdate.monitorUpdatesSince (vcenterhost.oregonstate.edu_username@vsphere.local): call to waitForUpdates...Starting (version
 = 32)
[----] I, [2015-04-13T14:15:52.693445 #2556:3a2021c]  INFO -- : HandSoap Request  [62701040]: length: [379], URI: [https://vcenterhost.oregonstate.edu/sdk], Content-Type: [text/xml;charset=UT
F-8], SOAPAction: [WaitForUpdates]
[----] I, [2015-04-13T14:15:53.099669 #2526:32ff3c0]  INFO -- : HandSoap Request  [71846660]: length: [379], URI: [https://10.214.4.11/sdk], Content-Type: [text/xml;charset=UTF-8], SOAPAction:
[WaitForUpdates]
[----] I, [2015-04-13T14:15:53.613522 #2556:30dc494]  INFO -- : HandSoap Request  [64430940]: length: [855], URI: [https://vcenterhost.oregonstate.edu/sdk], Content-Type: [text/xml;charset=UT
F-8], SOAPAction: [RetrieveProperties]
[----] I, [2015-04-13T14:19:05.037780 #2556:3fa73ac]  INFO -- : MiqVimBroker.getMiqVim: found connection for vcenterhost.oregonstate.edu_username@vsphere.local
[----] I, [2015-04-13T14:19:05.038074 #2556:3fa73ac]  INFO -- : MiqVimInventory(vcenterhost.oregonstate.edu, username@vsphere.local).getMoProp_local: calling retrieveProperties(SessionManager)
[----] I, [2015-04-13T14:19:05.038785 #2556:3fa73ac]  INFO -- : HandSoap Request  [33384100]: length: [792], URI: [https://vcenterhost.oregonstate.edu/sdk], Content-Type: [text/xml;charset=UTF-8], SOAPAction: [RetrieveProperties]
[----] I, [2015-04-13T14:25:51.480935 #2556:318f5bc]  INFO -- : MiqBrokerObjRegistry.release: MiqVimVm object_id: 60180640
[----] I, [2015-04-13T14:25:51.481077 #2556:318f5bc]  INFO -- : MiqBrokerObjRegistry.unregisterBrokerObj: MiqVimVm object_id: 60180640 => SessionId: 2487
[----] I, [2015-04-13T14:25:51.481222 #2556:318f5bc]  INFO -- : MiqBrokerObjRegistry.unregisterBrokerObj: MiqVimVm object_id: 60180640 => Connection: vcenterhost.oregonstate.edu_username@vsphere.local
[----] I, [2015-04-13T14:25:51.584716 #2487:10b5e90]  INFO -- : Client releaseSession: 2487
[----] I, [2015-04-13T14:25:51.585400 #2556:318f5bc]  INFO -- : Server releaseSession: 2487
[----] I, [2015-04-13T14:26:13.757570 #2307:951e88]  INFO -- : Client releaseSession: 2487
[----] I, [2015-04-13T14:26:13.760155 #2556:30e2bf0]  INFO -- : Server releaseSession: 2487
[----] I, [2015-04-13T14:26:58.298910 #2556:22ea23c]  INFO -- : MiqVimBroker status start

We’re seeing the same behavior with selinux and iptables disabled.

We also have a mIQ instance running anand-1 which is connecting to the exact same vCenter, and it is working properly.

Any ideas on how to troubleshoot this further would be welcome. Thanks!

johnmark · April 16, 2015, 2:04am

Time for RC3? Paging @Fryguy and @jrafanie.

Fryguy · April 20, 2015, 5:17pm

@jrafanie has been looking into this one.

jrafanie · April 20, 2015, 6:56pm

@stacybrock was there any other information on your scenario? I haven’t see it failing after 25 minutes… what I am looking out is the broker slowly growing in virt memory size (reported by top) and a possibly related thing of having many CLOSE_WAIT connections on it’s DRb port as reported by lsof -p $BROKER_PID.

stacybrock · April 21, 2015, 5:41pm

What’s the best way to identify the $BROKER_PID?

The server was started at 9:24 and by 9:43 it had stopped connecting to vCenter:

[root@miqhost log]# grep m._connect evm.log
[----] I, [2015-04-21T09:24:03.856110 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:04.542195 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:04.542364 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:05.621175 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:05.810556 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:05.810614 #7798:f17e94]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:09.267373 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:09.788426 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:09.788493 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:17.066317 #7874:9afe98]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:17.384060 #7874:9afe98]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:17.384194 #7874:9afe98]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:22.492336 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:25.745339 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:25.745399 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:38.001075 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:38.116643 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:38.116696 #7831:ef7e8c]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] Connected
[----] I, [2015-04-21T09:24:45.425430 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:24:45.447833 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:24:45.447919 #7806:c71e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:17.916047 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:18.065185 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:18.065326 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:18.635901 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:18.678667 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:18.688530 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:18.688642 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:19.057673 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:19.057786 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:19.734251 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:20.072825 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:20.072944 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:31.247825 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:31.258748 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:31.258861 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:35:31.491711 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T09:35:31.501319 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] 10.214.4.11 is VC, API version: 5.5
[----] I, [2015-04-21T09:35:31.501406 #7840:f91e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connected
[----] I, [2015-04-21T09:43:43.165196 #7842:e47e88]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...
[----] I, [2015-04-21T10:13:02.718857 #9869:c41e90]  INFO -- : MIQ(MiqFaultTolerantVim._connect) EMS: [DEV vCenter] [Broker] Connecting with address: [10.214.4.11], userid: [username@vsphere.local]...

Is 9869 the right PID for the broker?

jrafanie · April 21, 2015, 6:00pm

@stacybrock you’d have to either vmdb && bin/rake evm:status to see the list of all workers, browse the UI…somewhere we show the workers by pid, or grep for BrokerWorker in the evm.log and look for the #1234 in the log message to find the pid.

Also, can you grep your logs for this error:
Handsoap::Fault { :code => 'ServerFaultCode', :reason => 'A specified parameter was not correct.

Are you getting that anywhere? Is it happening just before things go bad?

stacybrock · April 21, 2015, 6:32pm

Going off of rake evm:status:

 MiqUiWorker                  | started | 1423 |  7866 |       | http://127.0.0.1:3000   | 2015-04-21T16:24:10Z | 2015-04-21T18:15:13Z
 MiqVimBrokerWorker           | started | 1424 |  7874 | 9683  | druby://127.0.0.1:41480 | 2015-04-21T16:24:14Z | 2015-04-21T18:15:09Z
 MiqWebServiceWorker          | started | 1425 |  7880 |       | http://127.0.0.1:4000   | 2015-04-21T16:24:11Z | 2015-04-21T18:15:13Z

[root@miqhost vmdb]# lsof -p 7874
COMMAND  PID USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
ruby    7874 root  cwd    DIR  253,0     4096 419819 /var/www/miq/vmdb
ruby    7874 root  rtd    DIR  253,0     4096      2 /
ruby    7874 root  txt    REG  253,0   100319 171637 /opt/rubies/ruby-2.0.0-p643/bin/ruby
ruby    7874 root  mem    REG  253,0   157032 173066 /lib64/ld-2.12.so
ruby    7874 root  mem    REG  253,0    22536 173069 /lib64/libdl-2.12.so
ruby    7874 root  mem    REG  253,0  1926760 173067 /lib64/libc-2.12.so
ruby    7874 root  mem    REG  253,0   145896 173074 /lib64/libpthread-2.12.so
ruby    7874 root  mem    REG  253,0    47112 173075 /lib64/librt-2.12.so
ruby    7874 root  mem    REG  253,0    91096 135237 /lib64/libz.so.1.2.3
ruby    7874 root  mem    REG  253,0   599392 173080 /lib64/libm-2.12.so
ruby    7874 root  mem    REG  253,0    16656 160029 /lib64/libgpg-error.so.0.5.0
ruby    7874 root  mem    REG  253,0   124624 148430 /lib64/libselinux.so.1
ruby    7874 root  mem    REG  253,0  1965856 149615 /usr/lib64/libcrypto.so.1.0.1e
ruby    7874 root  mem    REG  253,0   113952 173100 /lib64/libresolv-2.12.so
ruby    7874 root  mem    REG  253,0    12776 173070 /lib64/libfreebl3.so
ruby    7874 root  mem    REG  253,0    43392 173071 /lib64/libcrypt-2.12.so
ruby    7874 root  mem    REG  253,0   247192 156650 /lib64/libnspr4.so
ruby    7874 root  mem    REG  253,0   182112 173084 /usr/lib64/libnssutil3.so
ruby    7874 root  mem    REG  253,0    21288 173082 /lib64/libplc4.so
ruby    7874 root  mem    REG  253,0    17128 173083 /lib64/libplds4.so
ruby    7874 root  mem    REG  253,0  1302776 173085 /usr/lib64/libnss3.so
ruby    7874 root  mem    REG  253,0   257120 156748 /usr/lib64/libssl3.so
ruby    7874 root  mem    REG  253,0   183936 173108 /usr/lib64/libsmime3.so
ruby    7874 root  mem    REG  253,0    17256 173103 /lib64/libcom_err.so.2.1
ruby    7874 root  mem    REG  253,0   108728 173116 /usr/lib64/libsasl2.so.2.0.23
ruby    7874 root  mem    REG  253,0    12592 133960 /lib64/libkeyutils.so.1.3
ruby    7874 root  mem    REG  253,0    63336 173115 /lib64/liblber-2.4.so.2.10.2
ruby    7874 root  mem    REG  253,0    46368 173101 /lib64/libkrb5support.so.0.1
ruby    7874 root  mem    REG  253,0   177520 173102 /lib64/libk5crypto.so.3.1
ruby    7874 root  mem    REG  253,0   944712 173104 /lib64/libkrb5.so.3.3
ruby    7874 root  mem    REG  253,0   280520 173118 /lib64/libgssapi_krb5.so.2.2
ruby    7874 root  mem    REG  253,0   444168 173119 /usr/lib64/libssl.so.1.0.1e
ruby    7874 root  mem    REG  253,0  1384424 148080 /usr/lib64/libxml2.so.2.7.6
ruby    7874 root  mem    REG  253,0   244007 282381 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/trans/single_byte.so
ruby    7874 root  mem    REG  253,0    27424 133071 /lib64/libnss_dns-2.12.so
ruby    7874 root  mem    REG  253,0    65928 133073 /lib64/libnss_files-2.12.so
ruby    7874 root  mem    REG  253,0   123313 282335 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/io/wait.so
ruby    7874 root  mem    REG  253,0   351920 148456 /lib64/libldap_r-2.4.so.2.10.2
ruby    7874 root  mem    REG  253,0   185872 154372 /opt/rh/postgresql92/root/usr/lib64/libpq.so.postgresql92-5.5
ruby    7874 root  mem    REG  253,0   414613  19673 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/pg-0.12.2/lib/pg_ext.so
ruby    7874 root  mem    REG  253,0   481064 173094 /lib64/libgcrypt.so.11.5.3
ruby    7874 root  mem    REG  253,0   250640 148133 /usr/lib64/libxslt.so.1.1.26
ruby    7874 root  mem    REG  253,0    84296 135913 /usr/lib64/libexslt.so.0.8.15
ruby    7874 root  mem    REG  253,0  4126386 553151 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/nokogiri-1.5.11/lib/nokogiri/nokogiri.so
ruby    7874 root  mem    REG  253,0   162972  17623 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/io-extra-1.2.8/lib/io/extra.so
ruby    7874 root  mem    REG  253,0   126100 423550 /var/www/miq/lib/disk/modules/MiqBlockDevOps.so
ruby    7874 root  mem    REG  253,0    97152 282396 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/digest/md5.so
ruby    7874 root  mem    REG  253,0   125776 282332 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/racc/cparse.so
ruby    7874 root  mem    REG  253,0   169231  21687 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/thin-1.3.1/lib/thin_parser.so
ruby    7874 root  mem    REG  253,0   527124 554974 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/eventmachine-1.0.7/lib/rubyeventmachine.so
ruby    7874 root  mem    REG  253,0   263140 553479 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/json-1.8.2/lib/json/ext/generator.so
ruby    7874 root  mem    REG  253,0    56812 282361 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/utf_32le.so
ruby    7874 root  mem    REG  253,0    56788 282363 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/utf_32be.so
ruby    7874 root  mem    REG  253,0    58388 282338 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/utf_16le.so
ruby    7874 root  mem    REG  253,0    58372 282347 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/utf_16be.so
ruby    7874 root  mem    REG  253,0   170008 553484 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/json-1.8.2/lib/json/ext/parser.so
ruby    7874 root  mem    REG  253,0   323447 172398 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/zlib.so
ruby    7874 root  mem    REG  253,0    93320 135153 /lib64/libgcc_s-4.4.7-20120601.so.1
ruby    7874 root  mem    REG  253,0   989840 148700 /usr/lib64/libstdc++.so.6.0.13
ruby    7874 root  mem    REG  253,0  9142736  21511 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/therubyracer-0.12.2/lib/v8/init.so
ruby    7874 root  mem    REG  253,0   378900 172409 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/bigdecimal.so
ruby    7874 root  mem    REG  253,0  1256328 172401 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/date_core.so
ruby    7874 root  mem    REG  253,0   127496 149347 /usr/lib64/libyaml-0.so.2.0.4
ruby    7874 root  mem    REG  253,0   576573  19813 /opt/rubies/ruby-2.0.0-p643/lib/ruby/gems/2.0.0/gems/psych-2.0.13/lib/psych.so
ruby    7874 root  mem    REG  253,0   175786 282397 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/digest/sha2.so
ruby    7874 root  mem    REG  253,0   178258 172410 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/strscan.so
ruby    7874 root  mem    REG  253,0   198983 172399 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/stringio.so
ruby    7874 root  mem    REG  253,0 21901062 172393 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/openssl.so
ruby    7874 root  mem    REG  253,0    90881 172396 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/fcntl.so
ruby    7874 root  mem    REG  253,0  2522528 172402 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/socket.so
ruby    7874 root  mem    REG  253,0   117278 172390 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/digest.so
ruby    7874 root  mem    REG  253,0   171760 282395 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/digest/sha1.so
ruby    7874 root  mem    REG  253,0   146890 172383 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/etc.so
ruby    7874 root  mem    REG  253,0   185400 172400 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/pathname.so
ruby    7874 root  mem    REG  253,0    17610 282372 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/trans/transdb.so
ruby    7874 root  mem    REG  253,0    16383 282345 /opt/rubies/ruby-2.0.0-p643/lib/ruby/2.0.0/x86_64-linux/enc/encdb.so
ruby    7874 root  mem    REG  253,0    26060 133352 /usr/lib64/gconv/gconv-modules.cache
ruby    7874 root  mem    REG  253,0 99158576 133042 /usr/lib/locale/locale-archive
ruby    7874 root  mem    REG  253,0 16466137 171640 /opt/rubies/ruby-2.0.0-p643/lib/libruby.so.2.0.0
ruby    7874 root    0u   CHR  136,0      0t0      3 /dev/pts/0
ruby    7874 root    1w   CHR    1,3      0t0   3805 /dev/null
ruby    7874 root    2w   REG  253,0  3311718 550837 /var/www/miq/vmdb/log/evm.log
ruby    7874 root    3r  FIFO    0,8      0t0 882439 pipe
ruby    7874 root    4w  FIFO    0,8      0t0 882439 pipe
ruby    7874 root    5r  FIFO    0,8      0t0 882440 pipe
ruby    7874 root    6w  FIFO    0,8      0t0 882440 pipe
ruby    7874 root    7w   REG  253,0  3311718 550837 /var/www/miq/vmdb/log/evm.log
ruby    7874 root    8w   REG  253,0    42065 557620 /var/www/miq/vmdb/log/production.log
ruby    7874 root    9w   REG  253,0      963 557621 /var/www/miq/vmdb/log/audit.log
ruby    7874 root   10w   REG  253,0    38188 557622 /var/www/miq/vmdb/log/fog.log
ruby    7874 root   11w   REG  253,0     8831 557623 /var/www/miq/vmdb/log/policy.log
ruby    7874 root   12w   REG  253,0   169821 557624 /var/www/miq/vmdb/log/vim.log
ruby    7874 root   13w   REG  253,0        0 557625 /var/www/miq/vmdb/log/rhevm.log
ruby    7874 root   14w   REG  253,0        0 557626 /var/www/miq/vmdb/log/aws.log
ruby    7874 root   15w   REG  253,0        0 557627 /var/www/miq/vmdb/log/kubernetes.log
ruby    7874 root   16w   REG  253,0        0 557628 /var/www/miq/vmdb/log/scvmm.log
ruby    7874 root   17w   REG  253,0        0 557629 /var/www/miq/vmdb/log/api.log
ruby    7874 root   18w   REG  253,0     7752 557630 /var/www/miq/vmdb/log/automation.log
ruby    7874 root   19u  IPv4 882547      0t0    TCP miqhost.oregonstate.edu:39767->dbhost.oregonstate.edu:postgres (ESTABLISHED)
ruby    7874 root   20u  IPv4 882554      0t0    TCP localhost:41480 (LISTEN)
ruby    7874 root   21u  IPv4 886003      0t0    TCP miqhost.oregonstate.edu:40793->vcenterhost.oregonstate.edu:https (CLOSE_WAIT)
ruby    7874 root   22u  IPv4 882572      0t0    TCP localhost:47277->localhost:60251 (ESTABLISHED)
ruby    7874 root   23u  IPv4 882766      0t0    TCP localhost:41480->localhost:48376 (ESTABLISHED)
ruby    7874 root   24u  IPv4 883875      0t0    TCP localhost:41480->localhost:48421 (CLOSE_WAIT)
ruby    7874 root   25u  IPv4 882771      0t0    TCP localhost:41480->localhost:48378 (ESTABLISHED)
ruby    7874 root   26u  IPv4 886336      0t0    TCP miqhost.oregonstate.edu:40809->vcenterhost.oregonstate.edu:https (CLOSE_WAIT)
ruby    7874 root   27u  IPv4 892282      0t0    TCP localhost:41480->localhost:48543 (CLOSE_WAIT)
ruby    7874 root   28u  IPv4 883887      0t0    TCP localhost:41480->localhost:48424 (CLOSE_WAIT)
ruby    7874 root   29u  IPv4 889043      0t0    TCP localhost:41480->localhost:48510 (CLOSE_WAIT)
ruby    7874 root   30u  IPv4 890062      0t0    TCP localhost:41480->localhost:48520 (ESTABLISHED)
ruby    7874 root   31u  IPv4 891015      0t0    TCP localhost:41480->localhost:48527 (CLOSE_WAIT)
ruby    7874 root   32u  IPv4 893196      0t0    TCP localhost:41480->localhost:48552 (CLOSE_WAIT)

[root@miqhost vmdb]# grep '\s7874' log/top_output.log
 7874  7617 root      23   3  947m 138m  11m S 18.5  2.4   0:11.11 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.4  2.4   0:11.33 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.34 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.35 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.37 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.39 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.41 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.42 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.43 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.44 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  947m 138m  11m S  0.0  2.4   0:11.47 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 153m  11m S  6.4  2.6   0:15.34 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 153m  11m S  0.0  2.6   0:15.36 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 153m  11m S  0.0  2.6   0:15.38 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 153m  11m S  0.0  2.6   0:15.39 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 153m  11m S  0.2  2.6   0:15.54 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.57 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.58 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.59 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.60 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.60 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.62 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.63 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.64 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.65 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.65 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.66 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.67 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.68 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  973m 156m  11m S  0.0  2.7   0:15.69 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.1  2.6   0:15.76 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.78 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.78 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.80 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.81 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.82 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.82 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.83 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.84 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.84 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.86 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.87 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.87 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.89 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  970m 153m  11m S  0.0  2.6   0:15.90 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  972m 153m  11m S  0.1  2.6   0:15.97 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  972m 153m  11m S  0.0  2.6   0:15.97 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  972m 153m  11m S  0.0  2.6   0:15.98 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  972m 153m  11m S  0.0  2.6   0:15.99 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.01 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.02 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.02 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.03 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.04 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.05 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.06 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.07 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.08 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  974m 153m  11m S  0.0  2.6   0:16.09 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  978m 153m  11m S  0.0  2.6   0:16.10 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.1  2.6   0:16.17 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.18 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.20 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.20 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.21 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.22 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.23 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.24 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.25 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.25 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  980m 153m  11m S  0.0  2.6   0:16.27 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  982m 153m  11m S  0.0  2.6   0:16.28 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  982m 153m  11m S  0.0  2.6   0:16.29 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  982m 153m  11m S  0.0  2.6   0:16.30 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  982m 153m  11m S  0.0  2.6   0:16.31 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.1  2.6   0:16.38 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.39 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.40 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.40 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.41 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.42 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.43 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.44 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.45 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.46 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.46 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.47 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.48 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.49 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  984m 153m  11m S  0.0  2.6   0:16.50 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  986m 153m  11m S  0.1  2.6   0:16.57 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.59 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.59 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.60 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.61 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.61 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.63 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.64 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.64 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.65 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.66 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  990m 153m  11m S  0.0  2.6   0:16.66 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  992m 153m  11m S  0.0  2.6   0:16.68 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  992m 153m  11m S  0.0  2.6   0:16.69 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  992m 153m  11m S  0.0  2.6   0:16.69 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.1  2.6   0:16.77 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.0  2.6   0:16.78 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.0  2.6   0:16.79 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.0  2.6   0:16.79 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.0  2.6   0:16.80 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  994m 153m  11m S  0.0  2.6   0:16.81 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  996m 153m  11m S  0.0  2.6   0:16.82 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.83 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.84 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.85 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.86 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.86 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.87 /var/www/miq/vmdb/lib/workers/bin/worker.rb
 7874  7617 root      23   3  998m 153m  11m S  0.0  2.6   0:16.89 /var/www/miq/vmdb/lib/workers/bin/worker.rb

No results are returned when grepping for Handsoap errors:

[root@miqhost log]# grep -i handsoap * | grep Fault
[root@miqhost log]#

jrafanie · April 21, 2015, 7:39pm

@stacybrock it looks somewhat similar, but we’re seeing those handsoap fault errors right before our normal cleanup code no longer runs as it possibly should. See this bug, please add to it if you find similar symptoms: https://bugzilla.redhat.com/show_bug.cgi?id=1207018

jrafanie · May 5, 2015, 9:31pm

@stacybrock we just merged a change that might be related to your issue with vsphere.

Do you have an ability to test your issue with this change?

You should be able to snapshot/clone your botvinnik rc build and do this (it should apply cleanly):

vmdb
service evmserverd kill
git stash
wget https://patch-diff.githubusercontent.com/raw/ManageIQ/manageiq/pull/2759.patch
git am 2759.patch
git stash pop
rm -f log/*.log
service miqtop restart
service evmserverd start

Any results you find would be helpful… Thanks!

stacybrock · May 5, 2015, 11:40pm

@jrafanie I applied the patch as requested. EVM’s been running over an hour and both the refresh and event catcher processes are looking good. Going to let it run overnight and see how things are in the morning.

jrafanie · May 6, 2015, 3:20pm

Cool, @stacybrock, any further updates?

stacybrock · May 6, 2015, 4:49pm

@jrafanie It’s working.

Power on/off, reconfigure, delete VM from disk (via vCenter) – all are working correctly.

jrafanie · May 6, 2015, 6:39pm

That’s great to hear, thanks @stacybrock!