Bug 1601570 - [Regression] SSA on Datastore stuck with error in evm log
Summary: [Regression] SSA on Datastore stuck with error in evm log
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: Providers
Version: 5.10.0
Hardware: Unspecified
OS: Unspecified
high
high
Target Milestone: GA
: 5.10.0
Assignee: Adam Grare
QA Contact: Niyaz Akhtar Ansari
URL:
Whiteboard:
Depends On:
Blocks: 1533728
TreeView+ depends on / blocked
 
Reported: 2018-07-16 17:42 UTC by Niyaz Akhtar Ansari
Modified: 2019-02-11 14:07 UTC (History)
7 users (show)

Fixed In Version: 5.10.0.5
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-02-11 14:07:55 UTC
Category: ---
Cloudforms Team: ---
Target Upstream Version:
Embargoed:

Attachments (Terms of Use)
screenshot (214.56 KB, image/png)
2018-07-16 17:42 UTC, Niyaz Akhtar Ansari 		no flags Details
View All

Description Niyaz Akhtar Ansari 2018-07-16 17:42:13 UTC 
Created attachment 1459229 [details]
screenshot

Description of problem:


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

How reproducible:


Steps to Reproduce:
1.Add Vsphere Provider
2.Enable Smart proxy->Add host credentials 
3.Perform SSA on Datastores

Actual results:
The jobs seems to be stuck.
error in evm log"----] E, [2018-07-16T13:38:46.924869 #12009:6d4f84] ERROR -- : MIQ(MiqQueue#deliver) Message id: [10745], Message not processed.  Retrying at 2018-07-16 17:39:46 UTC"


Expected results:
It should work 

Additional info:
evm log
[----] I, [2018-07-16T13:37:40.722832 #12009:6d4f84]  INFO -- : MIQ(MiqQueue#unget) Message id: [10745],  id: [], Zone: [default], Role: [ems_operations], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [5], Task id: [], Command: [Storage.smartstate_analysis], Timeout: [1800], Priority: [100], State: [ready], Deliver On: [2018-07-16 17:38:40 UTC], Data: [], Args: [30], Requeued
[----] E, [2018-07-16T13:37:40.723006 #12009:6d4f84] ERROR -- : MIQ(MiqQueue#deliver) Message id: [10745], Message not processed.  Retrying at 2018-07-16 17:38:40 UTC
[----] I, [2018-07-16T13:37:45.491226 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004405]
[----] I, [2018-07-16T13:37:45.876455 #12060:6d4f84]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 4.
[----] I, [2018-07-16T13:37:45.889025 #12060:6d4f84]  INFO -- : MIQ(MiqQueue.put) Message id: [10846],  id: [], Zone: [default], Role: [], Server: [f6a0af01-52e0-4cce-8f83-808abd41760a], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2018-07-16T13:37:45.896359 #12060:6d4f84]  INFO -- : MIQ(MiqQueue.put) Message id: [10847],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Job.check_jobs_for_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2018-07-16T13:37:47.011525 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004406]
[----] I, [2018-07-16T13:37:47.012000 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004407]
[----] I, [2018-07-16T13:37:47.012090 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004408]
[----] I, [2018-07-16T13:37:47.012185 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004409]
[----] I, [2018-07-16T13:37:48.012624 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004410]
[----] I, [2018-07-16T13:37:49.013170 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004411]
[----] I, [2018-07-16T13:37:50.456527 #5885:6d4f84]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-07-16 17:37:50 UTC]...
[----] I, [2018-07-16T13:37:50.469150 #5885:6d4f84]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-07-16 17:37:50 UTC]...Complete
[----] I, [2018-07-16T13:37:51.614841 #5885:6d4f84]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2018-07-16T13:37:51.618914 #5885:6d4f84]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:heartbeat=>0.013160943984985352, :server_dequeue=>0.007483243942260742, :worker_monitor=>1.134361743927002, :worker_dequeue=>0.00719904899597168, :total_time=>1.1627147197723389}
[----] I, [2018-07-16T13:37:51.686270 #12035:6d4f84]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [10846], MiqWorker id: [16], Zone: [default], Role: [], Server: [f6a0af01-52e0-4cce-8f83-808abd41760a], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [5.801054023] seconds
[----] I, [2018-07-16T13:37:51.686953 #12035:6d4f84]  INFO -- : MIQ(MiqQueue#deliver) Message id: [10846], Delivering...
[----] I, [2018-07-16T13:37:51.767787 #12035:6d4f84]  INFO -- : MIQ(MiqQueue#delivered) Message id: [10846], State: [ok], Delivered in [0.080895242] seconds
[----] I, [2018-07-16T13:37:52.768283 #12009:6d4f84]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [10847], MiqWorker id: [13], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Job.check_jobs_for_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [6.874632905] seconds
[----] I, [2018-07-16T13:37:52.768472 #12009:6d4f84]  INFO -- : MIQ(MiqQueue#deliver) Message id: [10847], Delivering...
[----] I, [2018-07-16T13:37:52.771182 #12009:6d4f84]  INFO -- : MIQ(MiqQueue#delivered) Message id: [10847], State: [ok], Delivered in [0.002699856] seconds
[----] I, [2018-07-16T13:38:00.910952 #12060:6d4f84]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2018-07-16T13:38:03.023893 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004412]
[----] I, [2018-07-16T13:38:06.658676 #5885:6d4f84]  INFO -- : MiqServer: local=Y, master=Y, status= started, id=00001, pid=05885, guid=f6a0af01-52e0-4cce-8f83-808abd41760a, name=EVM, zone=default, hostname=dhcp-8-198-217.cfme2.lab.eng.rdu2.redhat.com, ipaddress=10.8.198.217, version=5.10.0.4, build=20180712211305_e6e4542, active roles=automate:database_operations:database_owner:ems_inventory:ems_operations:event:reporting:scheduler:smartproxy:smartstate:user_interface:web_services:websocket
[----] I, [2018-07-16T13:38:07.026203 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004413]
[----] I, [2018-07-16T13:38:07.696747 #5885:6d4f84]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2018-07-16T13:38:07.701051 #5885:6d4f84]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.005484580993652344, :log_active_servers=>0.008434295654296875, :worker_monitor=>1.0338923931121826, :worker_dequeue=>0.008000373840332031, :total_time=>1.0562546253204346}
[----] I, [2018-07-16T13:38:07.794023 #12017:6d4f84]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [10530], MiqWorker id: [14], Zone: [default], Role: [ems_operations], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [5], Task id: [], Command: [Storage.smartstate_analysis], Timeout: [1800], Priority: [100], State: [dequeue], Deliver On: [2018-07-16 17:38:04 UTC], Data: [], Args: [26], Dequeued in: [3829.959245567] seconds
[----] I, [2018-07-16T13:38:07.794423 #12017:6d4f84]  INFO -- : MIQ(MiqQueue#deliver) Message id: [10530], Delivering...
[----] I, [2018-07-16T13:38:07.800741 #12009:6d4f84]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [10844], MiqWorker id: [13], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Storage.scan_watchdog], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [2018-07-16 17:38:04 UTC], Data: [], Args: [26], Dequeued in: [63.163127697] seconds
[----] I, [2018-07-16T13:38:07.801064 #12009:6d4f84]  INFO -- : MIQ(MiqQueue#deliver) Message id: [10844], Delivering...
[----] I, [2018-07-16T13:38:07.816602 #12009:6d4f84]  INFO -- : MIQ(MiqQueue.put) Message id: [10848],  id: [], Zone: [default], Role: [], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Storage.scan_watchdog], Timeout: [600], Priority: [100], State: [ready], Deliver On: [2018-07-16 17:39:07 UTC], Data: [], Args: [26]
[----] I, [2018-07-16T13:38:07.817069 #12009:6d4f84]  INFO -- : MIQ(MiqQueue#delivered) Message id: [10844], State: [ok], Delivered in [0.015997425] seconds
[----] I, [2018-07-16T13:38:07.826968 #12017:6d4f84]  INFO -- : MIQ(MiqQueue#unget) Message id: [10530],  id: [], Zone: [default], Role: [ems_operations], Server: [], MiqTask id: [], Ident: [generic], Target id: [], Instance id: [5], Task id: [], Command: [Storage.smartstate_analysis], Timeout: [1800], Priority: [100], State: [ready], Deliver On: [2018-07-16 17:39:07 UTC], Data: [], Args: [26], Requeued
[----] E, [2018-07-16T13:38:07.827149 #12017:6d4f84] ERROR -- : MIQ(MiqQueue#deliver) Message id: [10530], Message not processed.  Retrying at 2018-07-16 17:39:07 UTC
[----] I, [2018-07-16T13:38:15.934067 #12060:6d4f84]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2018-07-16T13:38:19.032728 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004414]
[----] I, [2018-07-16T13:38:20.036958 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004415]
[----] I, [2018-07-16T13:38:20.037788 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004416]
[----] I, [2018-07-16T13:38:21.038408 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [2004417]
[----] I, [2018-07-16T13:38:21.039070 #58107:6d4f84]  INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [env-nvc60-vcsa.cfme2.lab.eng.rdu2.redhat.com] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [2004418]
[----] I, [2018-07-16T13:38:22.733875 #5885:6d4f84]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-07-16 17:38:22 UTC]...
[----] I, [2018-07-16T13:38:22.745066 #5885:6d4f84]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-07-16 17:38:22 UTC]...Complete
[----] I, [2018-07-16T13:38:23.907804 #5885:6d4f84]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:heartbeat=>0.01163482666015625, :server_dequeue=>0.006188154220581055, :worker_monitor=>1.1484427452087402, :worker_dequeue=>0.007666826248168945, :total_time=>1.1743347644805908}
Comment 4 CFME Bot 2018-07-17 17:35:48 UTC 
https://github.com/ManageIQ/manageiq/pull/17718
Comment 5 CFME Bot 2018-07-17 17:56:00 UTC 
New commit detected on ManageIQ/manageiq/master:

https://github.com/ManageIQ/manageiq/commit/b5b412aa3847719b3fe530f938ccebde86a4e09e
commit b5b412aa3847719b3fe530f938ccebde86a4e09e
Author:     Adam Grare <agrare>
AuthorDate: Tue Jul 17 13:23:02 2018 -0400
Commit:     Adam Grare <agrare>
CommitDate: Tue Jul 17 13:23:02 2018 -0400

    Fix detection of an EMS to use for Storage#scan

    Fix the detection of an EMS to use for storage smartstate scan.

    Fixes https://bugzilla.redhat.com/show_bug.cgi?id=1601570

 app/models/storage.rb | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)
Comment 6 Niyaz Akhtar Ansari 2018-07-30 08:29:04 UTC 
Verified in Version 5.10.0.6.20180725145922_d299ff5
Note You need to log in before you can comment on or make changes to this bug.