Created attachment 1153846 [details] merged evm.log and production.log files for ems refresh worker Process # 2886 Description of problem:When VMware returns a HOST instance named "localhost" to the EmsRefresh worker process, the process enters an infinite loop repetitively issueing SQL commands and effectively stopping any further ems refresh activity until restart_interval or message timeout is encountered. Version-Release number of selected component (if applicable):5.4.4.2 Build: 20151130143928_89a28ce How reproducible: Create a HOST instance with the name of "localhost" and then perform a full ems refresh on the provider. Steps to Reproduce: 1. 2. 3. Actual results: ems refresh worker enters a loop repeatedly issuing sql queries until process is terminated. Expected results: ems refresh processing to continue as usual and continue processing data returned from VC until refresh is complete. Additional info: evm.log file with debug log as well as production log with rails debug log active showing repeated sql queries after last log line from evm.log which is still in the middle of ems refresh processing when it stops logging. log extract showing entry to sql loop processing follows: ========================== [----] I, [2016-05-03T17:43:26.483170 #2886:6e1e8c] INFO -- : MIQ(EmsRefresh.save_hosts_inventory) EMS: [chrcnc02-vcsv-01], id: [20000000000001] Creating Host [localhost] hostname: [localhost] IP: [localhost] ems_ref: [host-80790] [----] D, [2016-05-03T17:43:26.485980 #2886:6e1e8c] DEBUG -- : (0.7ms) BEGIN [----] D, [2016-05-03T17:43:26.488364 #2886:6e1e8c] DEBUG -- : Host Exists (1.0ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost' LIMIT 1 [----] D, [2016-05-03T17:43:26.494934 #2886:6e1e8c] DEBUG -- : (0.6ms) ROLLBACK [----] D, [2016-05-03T17:43:26.497625 #2886:6e1e8c] DEBUG -- : Host Load (1.0ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.498051 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.2ms - 1rows) [----] D, [2016-05-03T17:43:26.499308 #2886:6e1e8c] DEBUG -- : (1.0ms) BEGIN [----] D, [2016-05-03T17:43:26.502153 #2886:6e1e8c] DEBUG -- : Host Exists (1.5ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.504581 #2886:6e1e8c] DEBUG -- : (0.6ms) ROLLBACK [----] D, [2016-05-03T17:43:26.506261 #2886:6e1e8c] DEBUG -- : Host Load (1.1ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.506507 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.507665 #2886:6e1e8c] DEBUG -- : (1.0ms) BEGIN [----] D, [2016-05-03T17:43:26.510139 #2886:6e1e8c] DEBUG -- : Host Exists (1.5ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.512302 #2886:6e1e8c] DEBUG -- : (0.7ms) ROLLBACK [----] D, [2016-05-03T17:43:26.513962 #2886:6e1e8c] DEBUG -- : Host Load (1.0ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.514188 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.514887 #2886:6e1e8c] DEBUG -- : (0.5ms) BEGIN [----] D, [2016-05-03T17:43:26.517355 #2886:6e1e8c] DEBUG -- : Host Exists (1.5ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.519488 #2886:6e1e8c] DEBUG -- : (0.7ms) ROLLBACK [----] D, [2016-05-03T17:43:26.521073 #2886:6e1e8c] DEBUG -- : Host Load (0.9ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.521298 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.522519 #2886:6e1e8c] DEBUG -- : (1.0ms) BEGIN [----] D, [2016-05-03T17:43:26.525100 #2886:6e1e8c] DEBUG -- : Host Exists (1.5ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.527296 #2886:6e1e8c] DEBUG -- : (0.6ms) ROLLBACK [----] D, [2016-05-03T17:43:26.528888 #2886:6e1e8c] DEBUG -- : Host Load (0.9ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.529127 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.530338 #2886:6e1e8c] DEBUG -- : (1.0ms) BEGIN [----] D, [2016-05-03T17:43:26.532570 #2886:6e1e8c] DEBUG -- : Host Exists (1.3ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.535274 #2886:6e1e8c] DEBUG -- : (1.0ms) ROLLBACK [----] D, [2016-05-03T17:43:26.537195 #2886:6e1e8c] DEBUG -- : Host Load (1.3ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.537457 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.538688 #2886:6e1e8c] DEBUG -- : (1.0ms) BEGIN [----] D, [2016-05-03T17:43:26.540346 #2886:6e1e8c] DEBUG -- : Host Exists (0.7ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.542522 #2886:6e1e8c] DEBUG -- : (0.5ms) ROLLBACK [----] D, [2016-05-03T17:43:26.544470 #2886:6e1e8c] DEBUG -- : Host Load (1.3ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.544761 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.545556 #2886:6e1e8c] DEBUG -- : (0.6ms) BEGIN [----] D, [2016-05-03T17:43:26.548887 #2886:6e1e8c] DEBUG -- : Host Exists (0.7ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.551391 #2886:6e1e8c] DEBUG -- : (1.0ms) ROLLBACK [----] D, [2016-05-03T17:43:26.553478 #2886:6e1e8c] DEBUG -- : Host Load (1.5ms) SELECT "hosts".* FROM "hosts" WHERE (name LIKE 'localhost%') ORDER BY name DESC LIMIT 1 [----] D, [2016-05-03T17:43:26.553725 #2886:6e1e8c] DEBUG -- : Host Inst Including Associations (0.1ms - 1rows) [----] D, [2016-05-03T17:43:26.554803 #2886:6e1e8c] DEBUG -- : (0.9ms) BEGIN [----] D, [2016-05-03T17:43:26.556499 #2886:6e1e8c] DEBUG -- : Host Exists (0.7ms) SELECT 1 AS one FROM "hosts" WHERE "hosts"."name" = 'localhost - 1000' LIMIT 1 [----] D, [2016-05-03T17:43:26.558906 #2886:6e1e8c] DEBUG -- : (1.0ms) ROLLBACK ======================================
Created attachment 1153847 [details] isolated evm.log file for process 2886 - ems refresh worker
Created attachment 1153848 [details] isolated production log with rails debug trace active for process 2886 - ems refresh worker
Created attachment 1153981 [details] CPU Utilization chart for process 2886 showing > 60% busy after the "localhost" item returned from ems refresh until process is terminated
complete set of current logs with evm debug, rails debug and vim broker debug active can be found at http://file.rdu.redhat.com/~thenness/TWC/sf%2001620979/2016-05-03-debug-logging/
Looks like this is probably the fix: https://github.com/ManageIQ/manageiq/pull/7146 Was hit by an upstream user with a similar situation.
Since the problem described in this bug report should be resolved in a recent advisory, it has been closed with a resolution of ERRATA. For information on the advisory, and where to find the updated files, follow the link below. If the solution does not work for you, open a new bug report. https://access.redhat.com/errata/RHBA-2016:1348
*** Bug 1305203 has been marked as a duplicate of this bug. ***