Bug 1217226

Summary:	SmartState analysis produces xml-related errors in evm.log
Product:	Red Hat CloudForms Management Engine	Reporter:	Thom Carlin <tcarlin>
Component:	SmartState Analysis	Assignee:	Mo Morsi <mmorsi>
Status:	CLOSED ERRATA	QA Contact:	Ramesh A <rananda>
Severity:	high	Docs Contact:
Priority:	high
Version:	5.4.0	CC:	jhardy, obarenbo, roliveri, simaishi, tcarlin
Target Milestone:	GA
Target Release:	5.5.0
Hardware:	Unspecified
OS:	Unspecified
Whiteboard:
Fixed In Version:	5.5.0.1	Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2015-12-08 13:06:44 UTC	Type:	Bug
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:

Description Thom Carlin 2015-04-29 19:49:25 UTC

Description of problem:

When performing Smartstate Analysis on RHOS VM, receive unexpected messages in evm.log

Version-Release number of selected component (if applicable):

5.4.0.0.23.20150423131011_69b48fd

How reproducible:

Unsure

Steps to Reproduce:
1. Perform Smartstate Analysis on RHOS VM
2.
3.

Actual results:

[----] I, [2015-04-28T12:11:31.215307 #2610:7efea0]  INFO -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) TaskId = [d68bf612-edc0-11e4-b9c9-001a4a60db13]
[----] E, [2015-04-28T12:11:31.217129 #2610:7efea0] ERROR -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) Processing xml for [system] [data is not permitted at state finish
[----] E, [2015-04-28T12:11:31.217297 #2610:7efea0] ERROR -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) Processing xml for [system] /var/www/miq/vmdb/app/models/job/state



Expected results:

No errors, successful SmartState Analysis

Additional info:

evm.log excerpt including traceback:
[----] I, [2015-04-28T12:11:31.207731 #2610:7efea0]  INFO -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(MiqQueue.deliver)    Message id: [1475], Delivering...
[----] I, [2015-04-28T12:11:31.215307 #2610:7efea0]  INFO -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) TaskId = [d68bf612-edc0-11e4-b9c9-001a4a60db13]
[----] E, [2015-04-28T12:11:31.217129 #2610:7efea0] ERROR -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) Processing xml for [system] [data is not permitted at state finish
[----] E, [2015-04-28T12:11:31.217297 #2610:7efea0] ERROR -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(Vm-save_metadata) Processing xml for [system] /var/www/miq/vmdb/app/models/job/state
/var/www/miq/vmdb/app/models/vm_or_template/scanning.rb:45:in `save_metadata'
/var/www/miq/vmdb/app/models/miq_queue.rb:354:in `block in deliver'
/opt/rh/ruby200/root/usr/share/ruby/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/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `eval'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands/runner.rb:52:in `<top (required)>'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `require'
/opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/railties/lib/rails/commands.rb:64:in `<top (required)>'
script/rails:6:in `require'
script/rails:6:in `<main>'
[----] I, [2015-04-28T12:11:31.217510 #2610:7efea0]  INFO -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) Adding XML elements for [4] from [miq]
[----] I, [2015-04-28T12:11:31.251860 #2610:7efea0]  INFO -- : Q-task_id([d68bf612-edc0-11e4-b9c9-001a4a60db13]) MIQ(MiqQueue.delivered)  Message id: [1475], State: [ok], Delivered in [0.044114372] sec

Comment 2 Mo Morsi 2015-04-30 20:07:29 UTC

Thom, could you share the connection info and credentials of the openstack environment and vm where this issue is present?

Comment 3 Thom Carlin 2015-04-30 22:36:47 UTC

Information supplied via IRC

Comment 9 Mo Morsi 2015-07-12 18:54:14 UTC

Verified issue is fixed on latest applied & openstack fleece succeeds.

Comment 11 Ramesh A 2015-11-25 09:29:31 UTC

Good to go.  Verified and working fine in 5.5.0.12-rc2.20151124135609_653c0d4

Comment 13 errata-xmlrpc 2015-12-08 13:06:44 UTC

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/RHSA-2015:2551