Bug 1332996 – Production Provisioning stops working when EmsRefresh for VMware loops until restart_interval ends when host named "localhost" encountered as host name returned from VMware provider

Bugzilla will be upgraded to version 5.0. The upgrade date is tentatively scheduled for 2 December 2018, pending final testing and feedback.

Bug 1332996 - Production Provisioning stops working when EmsRefresh for VMware loops until restart_interval ends when host named "localhost" encountered as host name returned from VMware provider

Summary:	Production Provisioning stops working when EmsRefresh for VMware loops until...

Status:	CLOSED ERRATA

Aliases:	None

Product:	Red Hat CloudForms Management Engine
Classification:	Red Hat
Component:	Providers (Show other bugs)
Sub Component:
Version:	5.4.0
Hardware:	x86_64 Linux

Priority	high Severity high
Target Milestone:	GA
Target Release:	5.6.0
Assigned To:	Adam Grare
QA Contact:	Alex Newman
Docs Contact:

URL:
Whiteboard:
Keywords:	ZStream

Duplicates:	1305203 (view as bug list)
Depends On:
Blocks:	1334937
	Show dependency tree / graph

Reported:	2016-05-04 09:39 EDT by Thomas Hennessy
Modified:	2017-12-05 19:01 EST (History)
CC List:	10 users (show)

See Also:
Fixed In Version:	5.6.0.0
Doc Type:	Bug Fix
Doc Text:
Story Points:	---
Clone Of:
Clones:	1334937 (view as bug list)
Environment:
Last Closed:	2016-06-29 11:57:24 EDT
Type:	Bug
Regression:	---
Mount Type:	---
Documentation:	---
CRM:
Verified Versions:
Category:	---
oVirt Team:	---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---

Attachments	(Terms of Use)
merged evm.log and production.log files for ems refresh worker Process # 2886 (16.20 MB, application/zip) 2016-05-04 09:39 EDT, Thomas Hennessy	no flags	Details
isolated evm.log file for process 2886 - ems refresh worker (117.37 KB, application/zip) 2016-05-04 09:42 EDT, Thomas Hennessy	no flags	Details
isolated production log with rails debug trace active for process 2886 - ems refresh worker (16.05 MB, application/zip) 2016-05-04 09:44 EDT, Thomas Hennessy	no flags	Details
CPU Utilization chart for process 2886 showing > 60% busy after the "localhost" item returned from ems refresh until process is terminated (254.78 KB, application/pdf) 2016-05-04 14:41 EDT, Thomas Hennessy	no flags	Details
Add an attachment (proposed patch, testcase, etc.)

External Trackers
Tracker	ID	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2016:1348	normal	SHIPPED_LIVE	CFME 5.6.0 bug fixes and enhancement update	2016-06-29 14:50:04 EDT

Groups: None (edit)

Description Thomas Hennessy 2016-05-04 09:39:39 EDT

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
======================================

Comment 1 Thomas Hennessy 2016-05-04 09:42 EDT

Created attachment 1153847 [details]
isolated evm.log file for process 2886 - ems refresh worker

Comment 2 Thomas Hennessy 2016-05-04 09:44 EDT

Created attachment 1153848 [details]
isolated production log with rails debug trace active for process 2886 - ems refresh worker

Comment 3 Thomas Hennessy 2016-05-04 14:41 EDT

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

Comment 4 Thomas Hennessy 2016-05-04 15:20:16 EDT

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/

Comment 5 Greg Blomquist 2016-05-04 15:34:14 EDT

Looks like this is probably the fix: https://github.com/ManageIQ/manageiq/pull/7146

Was hit by an upstream user with a similar situation.

Comment 8 errata-xmlrpc 2016-06-29 11:57:24 EDT

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

Comment 9 Adam Grare 2016-07-06 08:23:50 EDT

*** Bug 1305203 has been marked as a duplicate of this bug. ***

Note You need to log in before you can comment on or make changes to this bug.