1205247 – RHEVM fleecing broke on "cannot load such file -- rhevm_inventory"

Bug 1205247 - RHEVM fleecing broke on "cannot load such file -- rhevm_inventory"

Summary: RHEVM fleecing broke on "cannot load such file -- rhevm_inventory"

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Red Hat CloudForms Management Engine
Classification:	Red Hat
Component:	SmartState Analysis
Sub Component:
Version:	5.4.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	GA
Target Release:	5.4.0
Assignee:	Rich Oliveri
QA Contact:	Thom Carlin
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2015-03-24 14:01 UTC by Thom Carlin
Modified:	2015-06-16 12:54 UTC (History)
CC List:	4 users (show)
Fixed In Version:	5.4.0.0.24
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2015-06-16 12:54:34 UTC
Category:	---
Cloudforms Team:	---
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Product Errata	RHBA-2015:1100	0	normal	SHIPPED_LIVE	CFME 5.4.0 bug fixes, and enhancement update	2015-06-16 16:28:42 UTC

Description Thom Carlin 2015-03-24 14:01:08 UTC

Description of problem:

Attempt to run 

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

5.4.0.0.13.20150319164909_f011a66

How reproducible:

Every time

Steps to Reproduce:
1. Configure RHEVM
2. Attempt SmartState Analysis of VM
3.

Actual results:

scan operation yielded no data. aborting

Expected results:

SmartState Analysis of VM

Additional info:

[----] I, [2015-03-24T09:43:51.331312 #6985:cb1eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) EVM SmartState Analysis Initiated for VM [s_appl_downstream-53z_150217_2vkQlgtG]
[----] W, [2015-03-24T09:43:51.331496 #6985:cb1eac]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) User event logging is not available on [EmsRedhat] Name:[RHEV-M (10.16.4.106)]
[----] I, [2015-03-24T09:43:51.552410 #6985:cb1eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-call_scan: Enter
[----] I, [2015-03-24T09:43:51.626982 #6985:cb1eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(VmRedhat#scan_metadata) category=[["vmconfig", "accounts", "software", "services", "system"]] [Array]
[----] W, [2015-03-24T09:43:51.983526 #6985:cb1eac]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        /var/www/miq/vmdb/app/models/miq_server/server_smart_proxy.rb:78 called with large payload (args: 1016 bytes, data: 0 bytes) Message id: [2096],  id: [], Zone: [default], Role: [smartproxy], Server: [c48e493e-d208-11e4-a744-001a4a2dd78a], Ident: [smartproxy], Target id: [], Instance id: [1], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [MiqServer.scan_sync_vm], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: #<OpenStruct args=["/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf", "---\nems:\n  ems:\n    :address: 10.16.4.106\n    :hostname: 10.16.4.106\n    :ipaddress: 10.16.4.106\n    :username: admin@internal\n    :password: ********\n    :class_name: EmsRedhat\n  host:\n    :address: 10.16.4.50\n    :hostname: 10.16.4.50\n    :ipaddress: 10.16.4.50\n    :username: root\n    :password: ********\n    :class_name: HostRedhat\n  connect_to: ems\n  connect: false\nsnapshot:\n  use_existing: false\n  description: \n  create_free_percent: 100\n  remove_free_percent: 100\nvmScanProfiles: []\npermissions:\n  group: 36\n"], method_name="ScanMetadata", vm_guid="eac44246-d21e-11e4-b453-001a4a2dd77b", category="vmconfig,accounts,software,services,system", taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", vm_id=7>
[----] I, [2015-03-24T09:43:51.983930 #6985:cb1eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2096],  id: [], Zone: [default], Role: [smartproxy], Server: [c48e493e-d208-11e4-a744-001a4a2dd78a], Ident: [smartproxy], Target id: [], Instance id: [1], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [MiqServer.scan_sync_vm], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: #<OpenStruct args=["/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf", "---\nems:\n  ems:\n    :address: 10.16.4.106\n    :hostname: 10.16.4.106\n    :ipaddress: 10.16.4.106\n    :username: admin@internal\n    :password: ********\n    :class_name: EmsRedhat\n  host:\n    :address: 10.16.4.50\n    :hostname: 10.16.4.50\n    :ipaddress: 10.16.4.50\n    :username: root\n    :password: ********\n    :class_name: HostRedhat\n  connect_to: ems\n  connect: false\nsnapshot:\n  use_existing: false\n  description: \n  create_free_percent: 100\n  remove_free_percent: 100\nvmScanProfiles: []\npermissions:\n  group: 36\n"], method_name="ScanMetadata", vm_guid="eac44246-d21e-11e4-b453-001a4a2dd77b", category="vmconfig,accounts,software,services,system", taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", vm_id=7>
[----] I, [2015-03-24T09:43:52.300875 #6985:cb1eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.delivered)  Message id: [2093], State: [ok], Delivered in [1.369146653] seconds
[----] I, [2015-03-24T09:43:58.364912 #7003:635eac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2096], MiqWorker id: [69], Zone: [default], Role: [smartproxy], Server: [c48e493e-d208-11e4-a744-001a4a2dd78a], Ident: [smartproxy], Target id: [], Instance id: [1], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [MiqServer.scan_sync_vm], Timeout: [1200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: #<OpenStruct args=["/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf", "---\nems:\n  ems:\n    :address: 10.16.4.106\n    :hostname: 10.16.4.106\n    :ipaddress: 10.16.4.106\n    :username: admin@internal\n    :password: ********\n    :class_name: EmsRedhat\n  host:\n    :address: 10.16.4.50\n    :hostname: 10.16.4.50\n    :ipaddress: 10.16.4.50\n    :username: root\n    :password: ********\n    :class_name: HostRedhat\n  connect_to: ems\n  connect: false\nsnapshot:\n  use_existing: false\n  description: \n  create_free_percent: 100\n  remove_free_percent: 100\nvmScanProfiles: []\npermissions:\n  group: 36\n"], method_name="ScanMetadata", vm_guid="eac44246-d21e-11e4-b453-001a4a2dd77b", category="vmconfig,accounts,software,services,system", taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", vm_id=7>, Dequeued in: [6.700382539] seconds
[----] I, [2015-03-24T09:43:58.365373 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.deliver)    Message id: [2096], Delivering...
[----] I, [2015-03-24T09:44:01.866329 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqServer.scan_sync_vm) Running Command: [scanmetadata --category="vmconfig,accounts,software,services,system" --taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b" /rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed]
[----] I, [2015-03-24T09:44:22.616006 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(agent_job_state): jobid: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] starting
[----] I, [2015-03-24T09:44:22.720246 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2135],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204662], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Scanning", "Initializing scan"]
[----] I, [2015-03-24T09:44:22.733714 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQExtract using config file: [/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]  settings: [{"ems"=>{"ems"=>{:address=>"10.16.4.106", :hostname=>"10.16.4.106", :ipaddress=>"10.16.4.106", :username=>"admin@internal", :password=>"********", :class_name=>"EmsRedhat"}, "host"=>{:address=>"10.16.4.50", :hostname=>"10.16.4.50", :ipaddress=>"10.16.4.50", :username=>"root", :password=>"********", :class_name=>"HostRedhat"}, "connect_to"=>"ems", "connect"=>true, :use_vim_broker=>false}, "snapshot"=>{"use_existing"=>false, "description"=>nil, "create_free_percent"=>100, "remove_free_percent"=>100}, "vmScanProfiles"=>[], "permissions"=>{"group"=>36}, :mount=>nil}]
[----] I, [2015-03-24T09:44:22.734204 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQExtract.set_process_permissions: Process Group ID change requested from current:<0> to <36>
[----] I, [2015-03-24T09:44:22.734676 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQExtract.set_process_permissions: Group ID changed to <36>
[----] I, [2015-03-24T09:44:22.734875 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Connecting to [ems(directly):10.16.4.106] for VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] E, [2015-03-24T09:44:22.751736 #7003:635eac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Connection to [ems(directly):10.16.4.106] failed for VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf] with error [cannot load such file -- rhevm_inventory] after [0.016816629] seconds
[----] I, [2015-03-24T09:44:22.752089 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(agent_job_state): jobid: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] starting
[----] I, [2015-03-24T09:44:24.235678 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2136],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204662], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Scanning", "Scanning completed."]
[----] I, [2015-03-24T09:44:24.235954 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Starting:  Sending scan summary to server.  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] I, [2015-03-24T09:44:24.297735 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [],  job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] enter
[----] I, [2015-03-24T09:44:24.363055 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [] found vm object id [7], job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:25.785088 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2138],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [7], Instance id: [], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [281 bytes], Args: []
[----] I, [2015-03-24T09:44:25.785285 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [] data put on queue, job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:25.785569 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Completed: Sending scan summary to server.  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] E, [2015-03-24T09:44:25.785796 #7003:635eac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.deliver)    Message id: [2096], Error: [Connection to [ems(directly):10.16.4.106] failed for VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf] with error [cannot load such file -- rhevm_inventory] after [0.016816629] seconds]
[----] E, [2015-03-24T09:44:25.786040 #7003:635eac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) [LoadError]: Connection to [ems(directly):10.16.4.106] failed for VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf] with error [cannot load such file -- rhevm_inventory] after [0.016816629] seconds  Method:[rescue in deliver]
[----] E, [2015-03-24T09:44:25.786167 #7003:635eac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) /opt/rh/cfme-gemset/bundler/gems/rails-8f014fba21f9/activesupport/lib/active_support/dependencies.rb:251:in `require'
[----] I, [2015-03-24T09:44:25.786433 #7003:635eac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.delivered)  Message id: [2096], State: [error], Delivered in [27.42109524] seconds
[----] I, [2015-03-24T09:44:40.845206 #6975:51deac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2135], MiqWorker id: [61], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204662], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Scanning", "Initializing scan"], Dequeued in: [18.223417662] seconds
[----] I, [2015-03-24T09:44:40.847556 #6975:51deac]  INFO -- : Q-task_id([agent_job_state_1427204662]) JOB([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] Agent state update: state: [Scanning], message: [Initializing scan]
[----] I, [2015-03-24T09:44:40.865683 #6978:a9dea4]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2136], MiqWorker id: [62], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204662], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Scanning", "Scanning completed."], Dequeued in: [18.109894921] seconds
[----] I, [2015-03-24T09:44:40.870170 #6978:a9dea4]  INFO -- : Q-task_id([agent_job_state_1427204662]) JOB([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] Agent state update: state: [Scanning], message: [Scanning completed.]
[----] I, [2015-03-24T09:44:44.012731 #6975:51deac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2138], MiqWorker id: [61], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [7], Instance id: [], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [281 bytes], Args: [], Dequeued in: [19.642038731] seconds
[----] I, [2015-03-24T09:44:44.012882 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.deliver)    Message id: [2138], Delivering...
[----] I, [2015-03-24T09:44:44.020312 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Vm-save_metadata) TaskId = [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:44.346784 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: starting...
[----] I, [2015-03-24T09:44:44.693217 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Document=summary
[----] I, [2015-03-24T09:44:44.694422 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: sending :synchronize
[----] I, [2015-03-24T09:44:45.080480 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-call_snapshot_delete: Enter
[----] I, [2015-03-24T09:44:45.151007 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) EVM SmartState Analysis completed for VM [s_appl_downstream-53z_150217_2vkQlgtG]
[----] W, [2015-03-24T09:44:45.151166 #6975:51deac]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) User event logging is not available on [EmsRedhat] Name:[RHEV-M (10.16.4.106)]
[----] I, [2015-03-24T09:44:45.179712 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-call_synchronize: Enter
[----] I, [2015-03-24T09:44:45.485571 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2141],  id: [], Zone: [default], Role: [smartproxy], Server: [c48e493e-d208-11e4-a744-001a4a2dd78a], Ident: [smartproxy], Target id: [], Instance id: [1], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [MiqServer.scan_sync_vm], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: #<OpenStruct args=["/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf"], method_name="SyncMetadata", vm_guid="eac44246-d21e-11e4-b453-001a4a2dd77b", category="vmconfig,accounts,software,services,system", from_time=nil, taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", vm_id=7>
[----] I, [2015-03-24T09:44:45.495067 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) dispatch_finish: Dispatch Status is 'finished'
[----] I, [2015-03-24T09:44:45.505728 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-synchronizing
[----] I, [2015-03-24T09:44:45.506521 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Vm-save_metadata) Summary XML received. [<summary created_on='1427204662' display_time='2015-03-24T13:44:22Z' taskid='bf59ccfe-d22b-11e4-b42f-]
[----] I, [2015-03-24T09:44:45.507221 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.delivered)  Message id: [2138], State: [ok], Delivered in [1.494318657] seconds
[----] I, [2015-03-24T09:44:48.537909 #7000:f89ea4]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2141], MiqWorker id: [68], Zone: [default], Role: [smartproxy], Server: [c48e493e-d208-11e4-a744-001a4a2dd78a], Ident: [smartproxy], Target id: [], Instance id: [1], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [MiqServer.scan_sync_vm], Timeout: [1200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: #<OpenStruct args=["/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf"], method_name="SyncMetadata", vm_guid="eac44246-d21e-11e4-b453-001a4a2dd77b", category="vmconfig,accounts,software,services,system", from_time=nil, taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", vm_id=7>, Dequeued in: [3.072323279] seconds
[----] I, [2015-03-24T09:44:48.538216 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.deliver)    Message id: [2141], Delivering...
[----] I, [2015-03-24T09:44:50.279279 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqServer.scan_sync_vm) Running Command: [syncmetadata --category="vmconfig,accounts,software,services,system" --from_time="" --taskid="bf59ccfe-d22b-11e4-b42f-001a4a2dd77b" /rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1c]
[----] I, [2015-03-24T09:44:52.452411 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(agent_job_state): jobid: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] starting
[----] I, [2015-03-24T09:44:52.463712 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2146],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204692], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Synchronize", "Synchronization in progress"]
[----] W, [2015-03-24T09:44:52.476300 #7000:f89ea4]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Synchronize: No data found for [vmconfig].  Items:Total[0] Selected[0]  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] W, [2015-03-24T09:44:52.487869 #7000:f89ea4]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Synchronize: No data found for [accounts].  Items:Total[0] Selected[0]  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] W, [2015-03-24T09:44:52.499677 #7000:f89ea4]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Synchronize: No data found for [software].  Items:Total[0] Selected[0]  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] W, [2015-03-24T09:44:52.511007 #7000:f89ea4]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Synchronize: No data found for [services].  Items:Total[0] Selected[0]  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] W, [2015-03-24T09:44:52.522828 #7000:f89ea4]  WARN -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Synchronize: No data found for [system].  Items:Total[0] Selected[0]  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] I, [2015-03-24T09:44:52.523120 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Starting:  Sending vm summary to server.  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] I, [2015-03-24T09:44:52.523854 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [],  job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] enter
[----] I, [2015-03-24T09:44:52.589658 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [] found vm object id [7], job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:54.027474 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2148],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [7], Instance id: [], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [399 bytes], Args: []
[----] I, [2015-03-24T09:44:54.027689 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(save_vmmetadata): vm [] data put on queue, job [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:54.028082 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) Completed: Sending vm summary to server.  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]  VM:[/rhev/data-center/00000002-0002-0002-0002-0000000002b7/mastersd/master/vms/6636bdb3-e1cf-4379-854b-0ed90b8bbf28/6636bdb3-e1cf-4379-854b-0ed90b8bbf28.ovf]
[----] I, [2015-03-24T09:44:54.028372 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(agent_job_state): jobid: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] starting
[----] I, [2015-03-24T09:44:54.038719 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.put)        Message id: [2149],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204694], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Synchronize", "Synchronization complete"]
[----] I, [2015-03-24T09:44:54.039260 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqServer.scan_sync_vm) Command [syncmetadata] completed successfully in [3.75997915] seconds.  TaskId:[bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:44:54.039934 #7000:f89ea4]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.delivered)  Message id: [2141], State: [ok], Delivered in [5.501728607] seconds
[----] I, [2015-03-24T09:44:54.635200 #6975:51deac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2146], MiqWorker id: [61], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204692], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Synchronize", "Synchronization in progress"], Dequeued in: [2.179346086] seconds
[----] I, [2015-03-24T09:44:54.637237 #6975:51deac]  INFO -- : Q-task_id([agent_job_state_1427204692]) JOB([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] Agent state update: state: [Synchronize], message: [Synchronization in progress]
[----] I, [2015-03-24T09:45:00.669124 #6975:51deac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2148], MiqWorker id: [61], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [7], Instance id: [], Task id: [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [399 bytes], Args: [], Dequeued in: [6.648729612] seconds
[----] I, [2015-03-24T09:45:00.669292 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.deliver)    Message id: [2148], Delivering...
[----] I, [2015-03-24T09:45:00.680486 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Vm-save_metadata) TaskId = [bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]
[----] I, [2015-03-24T09:45:00.700346 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: starting...
[----] I, [2015-03-24T09:45:00.720422 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Document=summary
[----] I, [2015-03-24T09:45:00.721252 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Summary XML [<vmmetadata created_on='1427204692' display_time='2015-03-24T13:44:52Z' from_time='' items_selected='0' items_total='0' original_filename='vmconfig' taskid='bf59ccfe-d22b-11e4-b42f-001a4a2dd77b' version='2.0'/>]
[----] I, [2015-03-24T09:45:00.721490 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Summary XML [<vmmetadata created_on='1427204692' display_time='2015-03-24T13:44:52Z' from_time='' items_selected='0' items_total='0' original_filename='accounts' taskid='bf59ccfe-d22b-11e4-b42f-001a4a2dd77b' version='2.0'/>]
[----] I, [2015-03-24T09:45:00.721725 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Summary XML [<vmmetadata created_on='1427204692' display_time='2015-03-24T13:44:52Z' from_time='' items_selected='0' items_total='0' original_filename='software' taskid='bf59ccfe-d22b-11e4-b42f-001a4a2dd77b' version='2.0'/>]
[----] I, [2015-03-24T09:45:00.721936 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Summary XML [<vmmetadata created_on='1427204692' display_time='2015-03-24T13:44:52Z' from_time='' items_selected='0' items_total='0' original_filename='services' taskid='bf59ccfe-d22b-11e4-b42f-001a4a2dd77b' version='2.0'/>]
[----] I, [2015-03-24T09:45:00.722197 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: Summary XML [<vmmetadata created_on='1427204692' display_time='2015-03-24T13:44:52Z' from_time='' items_selected='0' items_total='0' original_filename='system' taskid='bf59ccfe-d22b-11e4-b42f-001a4a2dd77b' version='2.0'/>]
[----] E, [2015-03-24T09:45:00.722379 #6975:51deac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-process_data: scan operation yielded no data. aborting
[----] I, [2015-03-24T09:45:00.744723 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Event.raise_evm_event): Event Raised [vm_scan_abort]
[----] I, [2015-03-24T09:45:00.851607 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Event.raise_evm_event): Alert for Event [vm_scan_abort]
[----] I, [2015-03-24T09:45:00.852010 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqAlert.evaluate_alerts) [vm_scan_abort] Target: VmRedhat Name: [s_appl_downstream-53z_150217_2vkQlgtG], Id: [7]
[----] E, [2015-03-24T09:45:00.895090 #6975:51deac] ERROR -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-abort: job aborting, scan operation yielded no data. aborting
[----] I, [2015-03-24T09:45:00.914102 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) action-finished: job finished, scan operation yielded no data. aborting
[----] I, [2015-03-24T09:45:00.932069 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) dispatch_finish: Dispatch Status is 'finished'
[----] I, [2015-03-24T09:45:00.947813 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(Vm-save_metadata) Summary XML received. [<summary created_on='1427204692' display_time='2015-03-24T13:44:52Z' scan_time='2015-03-24 13:44:52 U]
[----] I, [2015-03-24T09:45:00.948484 #6975:51deac]  INFO -- : Q-task_id([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b]) MIQ(MiqQueue.delivered)  Message id: [2148], State: [ok], Delivered in [0.279170217] seconds
[----] I, [2015-03-24T09:45:01.180106 #6975:51deac]  INFO -- : MIQ(MiqQueue.get_via_drb) Message id: [2149], MiqWorker id: [61], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [agent_job_state_1427204694], Command: [Job.agent_state_update_queue], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: ["bf59ccfe-d22b-11e4-b42f-001a4a2dd77b", "Synchronize", "Synchronization complete"], Dequeued in: [7.149137317] seconds
[----] I, [2015-03-24T09:45:01.182614 #6975:51deac]  INFO -- : Q-task_id([agent_job_state_1427204694]) JOB([bf59ccfe-d22b-11e4-b42f-001a4a2dd77b] Agent state update: state: [Synchronize], message: [Synchronization complete]

Comment 3 Rich Oliveri 2015-04-06 21:05:31 UTC

Given blocking issues I'm having with the RHEVM fleecing code, and issues I'm having in my dev/rest environment, I can't give an estimate on when this may be resolved.

Comment 5 CFME Bot 2015-04-22 00:48:01 UTC

New commit detected on ovirt/master:
https://github.com/ManageIQ/ovirt/commit/e3234ac513d3cc206cb2462a12df1c295935a783

commit e3234ac513d3cc206cb2462a12df1c295935a783
Author:     Richard Oliveri <roliveri>
AuthorDate: Tue Apr 21 17:50:09 2015 -0400
Commit:     Richard Oliveri <roliveri>
CommitDate: Tue Apr 21 17:50:09 2015 -0400

    Use explicit namespace when referencing File class.
    
    The ovirt gem defines a File class in the Ovirt namespace, so any
    reference to the standard Ruby File class must be fully qualified.
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1205247

 lib/ovirt/inventory.rb | 2 +-
 lib/ovirt/template.rb  | 2 +-
 2 files changed, 2 insertions(+), 2 deletions(-)

Comment 6 CFME Bot 2015-04-24 15:21:05 UTC

New commit detected on manageiq/master:
https://github.com/ManageIQ/manageiq/commit/9c12ada07243665a4d110252f29fab620eda1237

commit 9c12ada07243665a4d110252f29fab620eda1237
Author:     Richard Oliveri <roliveri>
AuthorDate: Wed Apr 22 11:27:11 2015 -0400
Commit:     Richard Oliveri <roliveri>
CommitDate: Wed Apr 22 11:27:11 2015 -0400

    Require ovirt gem instead of rhevm_inventory
    
    The functionality of rhevm_inventory has been moved into the ovirt gem,
    require the proper gem accordingly.
    
    https://bugzilla.redhat.com/show_bug.cgi?id=1205247

 lib/Gemfile                           | 2 +-
 lib/metadata/MIQExtract/MIQExtract.rb | 8 ++++----
 2 files changed, 5 insertions(+), 5 deletions(-)

Comment 7 Oleg Barenboim 2015-04-24 15:58:38 UTC

Can this be moved to POST or awaiting more fixes?

Comment 8 Dave Johnson 2015-04-30 20:10:06 UTC

John Prause, can you verify Oleg's comment?  Based on the commits, I want to believe this can be on_qa in .24, right?

Comment 9 John Prause 2015-04-30 20:36:08 UTC

Yes, the changes are found in the 5.4.0.0.24 build.
Moving this to Modified state, adding to the 5.4 advisory, then switch to ON_QA state.

Comment 11 John Prause 2015-05-01 12:33:08 UTC

BZ was added to advisory.

Comment 12 Thom Carlin 2015-05-06 12:02:56 UTC

Verified in 5.4.0.0.24.20150427192818_1fd9e49

Comment 14 errata-xmlrpc 2015-06-16 12:54:34 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://rhn.redhat.com/errata/RHBA-2015-1100.html

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