1375684 – error loading instance page

Bug 1375684 - error loading instance page

Summary: error loading instance page

Keywords:
Status:	CLOSED CURRENTRELEASE
Alias:	None
Product:	Red Hat CloudForms Management Engine
Classification:	Red Hat
Component:	UI - OPS
Sub Component:
Version:	5.7.0
Hardware:	Unspecified
OS:	Unspecified
Priority:	high
Severity:	high
Target Milestone:	GA
Target Release:	cfme-future
Assignee:	Tzu-Mainn Chen
QA Contact:	Ola Pavlenko
Docs Contact:
URL:
Whiteboard:	openstack
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2016-09-13 17:01 UTC by Ronnie Rasouli
Modified:	2018-02-12 08:41 UTC (History)
CC List:	10 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2016-11-17 09:03:07 UTC
Category:	---
Cloudforms Team:	Openstack
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
last 1000 lines of evm.log (217.84 KB, text/plain) 2016-09-29 07:17 UTC, Ronnie Rasouli	no flags	Details
View All

Links
System	ID	Private	Priority	Status	Summary	Last Updated
Red Hat Bugzilla	1391850	0	high	CLOSED	Compute-Clouds-Instances throwing unexpected error	2021-02-22 00:41:40 UTC

Internal Links: 1391850

Description Ronnie Rasouli 2016-09-13 17:01:35 UTC

Description of problem:

navigating to instance is broken.

1. in cloud -> provider -> instance -> clicking on quadicon result:  Unexpected error encountered  undefined local variable or method `null' for #<Class:0x00000009dbd040> [vm_cloud/explorer] 

2. In cloud -> instances clicking on quad icon -> page not open
Version-Release number of selected component (if applicable):
latest miq version

How reproducible:
100%

Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:
instance page appear

Additional info:

from reproducing issue 

[----] I, [2[----] I, [2016-09-13T19:58:21.993715 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:22.652478 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:23.241761 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 5.
[----] I, [2016-09-13T19:58:23.246248 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [297],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:23.250353 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [298],  id: [], Zone: [default], Role: [], Server: [], 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, [2016-09-13T19:58:23.255647 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [299],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:23.259802 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [300],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:30.935487 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 4 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:30.940823 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.002713918685913086, :worker_monitor=>2.9160728454589844, :worker_dequeue=>0.008043050765991211, :total_time=>2.9270119667053223}
[----] I, [2016-09-13T19:58:30.978943 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [297], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.73439351] seconds
[----] I, [2016-09-13T19:58:30.979003 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [297], Delivering...
[----] I, [2016-09-13T19:58:31.001840 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [297], State: [ok], Delivered in [0.022835806] seconds
[----] I, [2016-09-13T19:58:31.009685 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [300], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.751460626] seconds
[----] I, [2016-09-13T19:58:31.009737 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [300], Delivering...
[----] I, [2016-09-13T19:58:31.012918 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0016870498657226562, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0017049312591552734, :pending_vm_jobs=>0.0003387928009033203, :vm_jobs_to_dispatch_count=>0, :total_time=>0.003007650375366211}
[----] I, [2016-09-13T19:58:31.013013 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [300], State: [ok], Delivered in [0.003262508] seconds
[----] I, [2016-09-13T19:58:31.019278 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [298], MiqWorker id: [2], Zone: [default], Role: [], Server: [], 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: [7.770597955] seconds
[----] I, [2016-09-13T19:58:31.019329 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [298], Delivering...
[----] I, [2016-09-13T19:58:31.020681 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [298], State: [ok], Delivered in [0.001337918] seconds
[----] I, [2016-09-13T19:58:31.026172 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [299], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.772129958] seconds
[----] I, [2016-09-13T19:58:31.026235 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [299], Delivering...
[----] I, [2016-09-13T19:58:31.028267 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [299], State: [ok], Delivered in [0.002018204] seconds
[----] I, [2016-09-13T19:58:32.642389 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:33.964883 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:35.941116 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:58:35 UTC]...
[----] I, [2016-09-13T19:58:35.946868 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:58:35 UTC]...Complete
[----] I, [2016-09-13T19:58:37.018938 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:37.681604 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:38.265163 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:58:38.271796 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [301],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:40.963570 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:41.707657 #37694:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [301], MiqWorker id: [4], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.438014269] seconds
[----] I, [2016-09-13T19:58:41.707717 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [301], Delivering...
[----] I, [2016-09-13T19:58:41.710770 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015780925750732422, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015859603881835938, :pending_vm_jobs=>0.00031256675720214844, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0028972625732421875}
[----] I, [2016-09-13T19:58:41.710885 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [301], State: [ok], Delivered in [0.003157782] seconds
[----] I, [2016-09-13T19:58:47.655683 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:48.893347 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0020923614501953125, :worker_monitor=>2.9134676456451416, :worker_dequeue=>0.007663249969482422, :total_time=>2.923337459564209}
[----] I, [2016-09-13T19:58:48.977740 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:52.046709 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:52.708127 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:53.277702 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-09-13T19:58:53.282362 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [302],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:53.287372 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [303],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:53.898506 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:54.262151 #37685:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [303], MiqWorker id: [3], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [0.976705446] seconds
[----] I, [2016-09-13T19:58:54.262231 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [303], Delivering...
[----] I, [2016-09-13T19:58:54.265334 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015366077423095703, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015439987182617188, :pending_vm_jobs=>0.00031065940856933594, :vm_jobs_to_dispatch_count=>0, :total_time=>0.002919435501098633}
[----] I, [2016-09-13T19:58:54.265484 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [303], State: [ok], Delivered in [0.00321025] seconds
[----] I, [2016-09-13T19:58:54.271505 #37685:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [302], MiqWorker id: [3], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [0.990992129] seconds
[----] I, [2016-09-13T19:58:54.271563 #37685:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [302], Delivering...
[----] I, [2016-09-13T19:58:54.273653 #37685:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [302], State: [ok], Delivered in [0.002077018] seconds
[----] I, [2016-09-13T19:59:02.822653 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:04.096456 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:06.778566 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.002101421356201172, :worker_monitor=>2.8516955375671387, :worker_dequeue=>0.010739326477050781, :total_time=>2.864699602127075}
[----] I, [2016-09-13T19:59:07.074610 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:07.734151 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:08.292728 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:59:08.298841 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [304],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:11.778824 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:11 UTC]...
[----] I, [2016-09-13T19:59:11.784115 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:11 UTC]...Complete
[----] I, [2016-09-13T19:59:11.789648 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:11.804604 #37703:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [304], MiqWorker id: [5], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.507764101] seconds
[----] I, [2016-09-13T19:59:11.804664 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [304], Delivering...
[----] I, [2016-09-13T19:59:11.807429 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0013778209686279297, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0013968944549560547, :pending_vm_jobs=>0.0003082752227783203, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0026369094848632812}
[----] I, [2016-09-13T19:59:11.807561 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [304], State: [ok], Delivered in [0.002882894] seconds
[----] I, [2016-09-13T19:59:17.833225 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
Session:	 Hash of Size 17080, Elements 44
=================================
[----] I, [2016-09-13T19:59:19.107543 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:22.105450 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:22.761119 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:23.303905 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 5.
[----] I, [2016-09-13T19:59:23.308434 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [305],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:23.313048 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [306],  id: [], Zone: [default], Role: [], Server: [], 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, [2016-09-13T19:59:23.318696 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [307],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:23.323172 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [308],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:24.884863 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 4 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:24.889905 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0018219947814941406, :server_monitor=>0.05184292793273926, :worker_monitor=>3.0204946994781494, :worker_dequeue=>0.007463216781616211, :total_time=>3.081801414489746}
[----] I, [2016-09-13T19:59:25.082608 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [305], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.775972381] seconds
[----] I, [2016-09-13T19:59:25.082669 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [305], Delivering...
[----] I, [2016-09-13T19:59:25.106608 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [305], State: [ok], Delivered in [0.0239232] seconds
[----] I, [2016-09-13T19:59:25.113748 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [308], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.792223104] seconds
[----] I, [2016-09-13T19:59:25.113811 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [308], Delivering...
[----] I, [2016-09-13T19:59:25.117071 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.001468658447265625, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0014755725860595703, :pending_vm_jobs=>0.00031495094299316406, :vm_jobs_to_dispatch_count=>0, :total_time=>0.003118276596069336}
[----] I, [2016-09-13T19:59:25.117251 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [308], State: [ok], Delivered in [0.003412045] seconds
[----] I, [2016-09-13T19:59:25.123058 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [306], MiqWorker id: [2], Zone: [default], Role: [], Server: [], 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: [1.81163472] seconds
[----] I, [2016-09-13T19:59:25.123111 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [306], Delivering...
[----] I, [2016-09-13T19:59:25.124429 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [306], State: [ok], Delivered in [0.001308167] seconds
[----] I, [2016-09-13T19:59:25.130570 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [307], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.813435999] seconds
[----] I, [2016-09-13T19:59:25.130629 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [307], Delivering...
[----] I, [2016-09-13T19:59:25.132615 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [307], State: [ok], Delivered in [0.001978886] seconds
[----] I, [2016-09-13T19:59:32.844736 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:34.118629 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:37.132314 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:37.787658 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:38.329588 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:59:38.335064 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [309],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:42.915449 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:42.921743 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0022652149200439453, :worker_monitor=>2.9991815090179443, :worker_dequeue=>0.009279727935791016, :total_time=>3.0109071731567383}
[----] I, [2016-09-13T19:59:43.154995 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [309], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [4.821799219] seconds
[----] I, [2016-09-13T19:59:43.155065 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [309], Delivering...
[----] I, [2016-09-13T19:59:43.158041 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015058517456054688, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015134811401367188, :pending_vm_jobs=>0.0003044605255126953, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0028238296508789062}
[----] I, [2016-09-13T19:59:43.158167 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [309], State: [ok], Delivered in [0.003081275] seconds
[----] I, [2016-09-13T19:59:47.855680 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:47.921997 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:47 UTC]...
[----] I, [2016-09-13T19:59:47.931213 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:47 UTC]...Complete
[----] I, [2016-09-13T19:59:49.128716 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:52.165018 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:52.817520 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:53.340371 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-09-13T19:59:53.344713 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [310],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:53.349414 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [311],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T20:00:00.783830 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T20:00:00.789139 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0022377967834472656, :worker_monitor=>2.827193021774292, :worker_dequeue=>0.007815361022949219, :total_time=>2.8373773097991943}
[----] I, [2016-09-13T20:00:00.933485 #37694:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [311], MiqWorker id: [4], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.585729408] seconds
[----] I, [2016-09-13T20:00:00.933551 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [311], Delivering...
[----] I, [2016-09-13T20:00:00.936654 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0014472007751464844, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.001455545425415039, :pending_vm_jobs=>0.0003590583801269531, :vm_jobs_to_dispatch_count=>0, :total_time=>0.002959728240966797}
[----] I, [2016-09-13T20:00:00.936793 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [311], State: [ok], Delivered in [0.003239881] seconds
[----] I, [2016-09-13T20:00:01.181687 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [310], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.83872228] seconds
[----] I, [2016-09-13T20:00:01.181753 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [310], Delivering...
[----] I, [2016-09-13T20:00:01.184439 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [310], State: [ok], Delivered in [0.002672595] seconds
[----] I, [2016-09-13T20:00:02.866042 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:04.138690 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:07.190217 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:07.843648 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:08.354983 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 3.
[----] I, [2016-09-13T20:00:08.357167 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [8] [EVM: Recently Discovered Hosts] [MiqWidget] [generate_widget]
[----] I, [2016-09-13T20:00:08.360533 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [312],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [8], Task id: [], Command: [MiqSchedule.invoke_actions], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["action_generate_widget", 1473789600]
[----] I, [2016-09-13T20:00:08.360584 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [8] [EVM: Recently Discovered Hosts] [MiqWidget] [generate_widget]...complete
[----] I, [2016-09-13T20:00:08.361409 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [9] [EVM: Recently Discovered VMs] [MiqWidget] [generate_widget]
[----] I, [2016-09-13T20:00:08.364217 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [313],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [9], Task id: [], Command: [MiqSchedule.invoke_actions], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["action_generate_widget", 1473789600]
[----] I, [2016-09-13T20:00:08.364264 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [9] [EVM: Recently Discovered VMs] [MiqWidget] [generate_widget]...complete
[----] I, [2016-09-13T20:00:08.368933 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [314],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T20:00:10.804840 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 3 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T20:00:10.958333 #37703:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [314], MiqWorker id: [5], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [2.59097655] seconds
[----] I, [2016-09-13T20:00:10.958391 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [314], Delivering...
[----] I, [2016-09-13T20:00:10.961713 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0016560554504394531, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0016651153564453125, :pending_vm_jobs=>0.0005197525024414062, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0031485557556152344}
[----] I, [2016-09-13T20:00:10.961854 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [314], State: [ok], Delivered in [0.003450396] seconds
016-09-13T19:58:21.993715 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:22.652478 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:23.241761 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 5.
[----] I, [2016-09-13T19:58:23.246248 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [297],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:23.250353 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [298],  id: [], Zone: [default], Role: [], Server: [], 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, [2016-09-13T19:58:23.255647 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [299],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:23.259802 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [300],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:30.935487 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 4 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:30.940823 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.002713918685913086, :worker_monitor=>2.9160728454589844, :worker_dequeue=>0.008043050765991211, :total_time=>2.9270119667053223}
[----] I, [2016-09-13T19:58:30.978943 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [297], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.73439351] seconds
[----] I, [2016-09-13T19:58:30.979003 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [297], Delivering...
[----] I, [2016-09-13T19:58:31.001840 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [297], State: [ok], Delivered in [0.022835806] seconds
[----] I, [2016-09-13T19:58:31.009685 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [300], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.751460626] seconds
[----] I, [2016-09-13T19:58:31.009737 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [300], Delivering...
[----] I, [2016-09-13T19:58:31.012918 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0016870498657226562, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0017049312591552734, :pending_vm_jobs=>0.0003387928009033203, :vm_jobs_to_dispatch_count=>0, :total_time=>0.003007650375366211}
[----] I, [2016-09-13T19:58:31.013013 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [300], State: [ok], Delivered in [0.003262508] seconds
[----] I, [2016-09-13T19:58:31.019278 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [298], MiqWorker id: [2], Zone: [default], Role: [], Server: [], 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: [7.770597955] seconds
[----] I, [2016-09-13T19:58:31.019329 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [298], Delivering...
[----] I, [2016-09-13T19:58:31.020681 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [298], State: [ok], Delivered in [0.001337918] seconds
[----] I, [2016-09-13T19:58:31.026172 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [299], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.772129958] seconds
[----] I, [2016-09-13T19:58:31.026235 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [299], Delivering...
[----] I, [2016-09-13T19:58:31.028267 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [299], State: [ok], Delivered in [0.002018204] seconds
[----] I, [2016-09-13T19:58:32.642389 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:33.964883 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:35.941116 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:58:35 UTC]...
[----] I, [2016-09-13T19:58:35.946868 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:58:35 UTC]...Complete
[----] I, [2016-09-13T19:58:37.018938 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:37.681604 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:38.265163 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:58:38.271796 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [301],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:40.963570 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:41.707657 #37694:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [301], MiqWorker id: [4], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.438014269] seconds
[----] I, [2016-09-13T19:58:41.707717 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [301], Delivering...
[----] I, [2016-09-13T19:58:41.710770 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015780925750732422, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015859603881835938, :pending_vm_jobs=>0.00031256675720214844, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0028972625732421875}
[----] I, [2016-09-13T19:58:41.710885 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [301], State: [ok], Delivered in [0.003157782] seconds
[----] I, [2016-09-13T19:58:47.655683 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:48.893347 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0020923614501953125, :worker_monitor=>2.9134676456451416, :worker_dequeue=>0.007663249969482422, :total_time=>2.923337459564209}
[----] I, [2016-09-13T19:58:48.977740 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:52.046709 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:52.708127 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:58:53.277702 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-09-13T19:58:53.282362 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [302],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:53.287372 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [303],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:58:53.898506 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:58:54.262151 #37685:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [303], MiqWorker id: [3], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [0.976705446] seconds
[----] I, [2016-09-13T19:58:54.262231 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [303], Delivering...
[----] I, [2016-09-13T19:58:54.265334 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015366077423095703, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015439987182617188, :pending_vm_jobs=>0.00031065940856933594, :vm_jobs_to_dispatch_count=>0, :total_time=>0.002919435501098633}
[----] I, [2016-09-13T19:58:54.265484 #37685:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [303], State: [ok], Delivered in [0.00321025] seconds
[----] I, [2016-09-13T19:58:54.271505 #37685:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [302], MiqWorker id: [3], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [0.990992129] seconds
[----] I, [2016-09-13T19:58:54.271563 #37685:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [302], Delivering...
[----] I, [2016-09-13T19:58:54.273653 #37685:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [302], State: [ok], Delivered in [0.002077018] seconds
[----] I, [2016-09-13T19:59:02.822653 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:04.096456 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:06.778566 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.002101421356201172, :worker_monitor=>2.8516955375671387, :worker_dequeue=>0.010739326477050781, :total_time=>2.864699602127075}
[----] I, [2016-09-13T19:59:07.074610 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:07.734151 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:08.292728 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:59:08.298841 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [304],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:11.778824 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:11 UTC]...
[----] I, [2016-09-13T19:59:11.784115 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:11 UTC]...Complete
[----] I, [2016-09-13T19:59:11.789648 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:11.804604 #37703:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [304], MiqWorker id: [5], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.507764101] seconds
[----] I, [2016-09-13T19:59:11.804664 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [304], Delivering...
[----] I, [2016-09-13T19:59:11.807429 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0013778209686279297, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0013968944549560547, :pending_vm_jobs=>0.0003082752227783203, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0026369094848632812}
[----] I, [2016-09-13T19:59:11.807561 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [304], State: [ok], Delivered in [0.002882894] seconds
[----] I, [2016-09-13T19:59:17.833225 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
Session:	 Hash of Size 17080, Elements 44
=================================
[----] I, [2016-09-13T19:59:19.107543 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:22.105450 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:22.761119 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:23.303905 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 5.
[----] I, [2016-09-13T19:59:23.308434 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [305],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:23.313048 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [306],  id: [], Zone: [default], Role: [], Server: [], 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, [2016-09-13T19:59:23.318696 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [307],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:23.323172 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [308],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:24.884863 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 4 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:24.889905 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0018219947814941406, :server_monitor=>0.05184292793273926, :worker_monitor=>3.0204946994781494, :worker_dequeue=>0.007463216781616211, :total_time=>3.081801414489746}
[----] I, [2016-09-13T19:59:25.082608 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [305], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.775972381] seconds
[----] I, [2016-09-13T19:59:25.082669 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [305], Delivering...
[----] I, [2016-09-13T19:59:25.106608 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [305], State: [ok], Delivered in [0.0239232] seconds
[----] I, [2016-09-13T19:59:25.113748 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [308], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.792223104] seconds
[----] I, [2016-09-13T19:59:25.113811 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [308], Delivering...
[----] I, [2016-09-13T19:59:25.117071 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.001468658447265625, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0014755725860595703, :pending_vm_jobs=>0.00031495094299316406, :vm_jobs_to_dispatch_count=>0, :total_time=>0.003118276596069336}
[----] I, [2016-09-13T19:59:25.117251 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [308], State: [ok], Delivered in [0.003412045] seconds
[----] I, [2016-09-13T19:59:25.123058 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [306], MiqWorker id: [2], Zone: [default], Role: [], Server: [], 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: [1.81163472] seconds
[----] I, [2016-09-13T19:59:25.123111 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [306], Delivering...
[----] I, [2016-09-13T19:59:25.124429 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [306], State: [ok], Delivered in [0.001308167] seconds
[----] I, [2016-09-13T19:59:25.130570 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [307], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [1.813435999] seconds
[----] I, [2016-09-13T19:59:25.130629 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [307], Delivering...
[----] I, [2016-09-13T19:59:25.132615 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [307], State: [ok], Delivered in [0.001978886] seconds
[----] I, [2016-09-13T19:59:32.844736 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:34.118629 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:37.132314 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:37.787658 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:38.329588 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-09-13T19:59:38.335064 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [309],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:42.915449 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T19:59:42.921743 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0022652149200439453, :worker_monitor=>2.9991815090179443, :worker_dequeue=>0.009279727935791016, :total_time=>3.0109071731567383}
[----] I, [2016-09-13T19:59:43.154995 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [309], MiqWorker id: [2], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [4.821799219] seconds
[----] I, [2016-09-13T19:59:43.155065 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [309], Delivering...
[----] I, [2016-09-13T19:59:43.158041 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0015058517456054688, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0015134811401367188, :pending_vm_jobs=>0.0003044605255126953, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0028238296508789062}
[----] I, [2016-09-13T19:59:43.158167 #37676:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [309], State: [ok], Delivered in [0.003081275] seconds
[----] I, [2016-09-13T19:59:47.855680 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:47.921997 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:47 UTC]...
[----] I, [2016-09-13T19:59:47.931213 #35433:10c9990]  INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-09-13 16:59:47 UTC]...Complete
[----] I, [2016-09-13T19:59:49.128716 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:52.165018 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:52.817520 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T19:59:53.340371 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-09-13T19:59:53.344713 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [310],  id: [], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T19:59:53.349414 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [311],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T20:00:00.783830 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T20:00:00.789139 #35433:10c9990]  INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0022377967834472656, :worker_monitor=>2.827193021774292, :worker_dequeue=>0.007815361022949219, :total_time=>2.8373773097991943}
[----] I, [2016-09-13T20:00:00.933485 #37694:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [311], MiqWorker id: [4], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.585729408] seconds
[----] I, [2016-09-13T20:00:00.933551 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [311], Delivering...
[----] I, [2016-09-13T20:00:00.936654 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0014472007751464844, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.001455545425415039, :pending_vm_jobs=>0.0003590583801269531, :vm_jobs_to_dispatch_count=>0, :total_time=>0.002959728240966797}
[----] I, [2016-09-13T20:00:00.936793 #37694:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [311], State: [ok], Delivered in [0.003239881] seconds
[----] I, [2016-09-13T20:00:01.181687 #37676:10c9990]  INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [310], MiqWorker id: [2], Zone: [default], Role: [], Server: [d2340626-79cf-11e6-b62c-5254009650c8], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.83872228] seconds
[----] I, [2016-09-13T20:00:01.181753 #37676:10c9990]  INFO -- : MIQ(MiqQueue#deliver) Message id: [310], Delivering...
[----] I, [2016-09-13T20:00:01.184439 #37676:10c9990]  INFO -- : MIQ(MiqQueue#delivered) Message id: [310], State: [ok], Delivered in [0.002672595] seconds
[----] I, [2016-09-13T20:00:02.866042 #54754:1c471dc]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:04.138690 #54766:1c11d5c]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:07.190217 #50805:1c9f0e4]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:07.843648 #50816:1b7bf28]  INFO -- : Querying Openstack Ceilometer for events newer than ...
[----] I, [2016-09-13T20:00:08.354983 #37731:10c9990]  INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 3.
[----] I, [2016-09-13T20:00:08.357167 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [8] [EVM: Recently Discovered Hosts] [MiqWidget] [generate_widget]
[----] I, [2016-09-13T20:00:08.360533 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [312],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [8], Task id: [], Command: [MiqSchedule.invoke_actions], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["action_generate_widget", 1473789600]
[----] I, [2016-09-13T20:00:08.360584 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [8] [EVM: Recently Discovered Hosts] [MiqWidget] [generate_widget]...complete
[----] I, [2016-09-13T20:00:08.361409 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [9] [EVM: Recently Discovered VMs] [MiqWidget] [generate_widget]
[----] I, [2016-09-13T20:00:08.364217 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [313],  id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [9], Task id: [], Command: [MiqSchedule.invoke_actions], Timeout: [1200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["action_generate_widget", 1473789600]
[----] I, [2016-09-13T20:00:08.364264 #37731:10c9990]  INFO -- : MIQ(MiqSchedule.queue_scheduled_work) Queueing start of schedule id: [9] [EVM: Recently Discovered VMs] [MiqWidget] [generate_widget]...complete
[----] I, [2016-09-13T20:00:08.368933 #37731:10c9990]  INFO -- : MIQ(MiqQueue.put) Message id: [314],  id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-09-13T20:00:10.804840 #35433:10c9990]  INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 3 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-09-13T20:00:10.958333 #37703:10c9990]  INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [314], MiqWorker id: [5], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_dispatcher], Command: [JobProxyDispatcher.dispatch], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [2.59097655] seconds
[----] I, [2016-09-13T20:00:10.958391 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [314], Delivering...
[----] I, [2016-09-13T20:00:10.961713 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.0016560554504394531, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.0016651153564453125, :pending_vm_jobs=>0.0005197525024414062, :vm_jobs_to_dispatch_count=>0, :total_time=>0.0031485557556152344}
[----] I, [2016-09-13T20:00:10.961854 #37703:10c9990]  INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [314], State: [ok], Delivered in [0.003450396] seconds

Comment 2 Tzu-Mainn Chen 2016-09-13 17:08:57 UTC

Hm, I can't reproduce this.  Can you attach the full evm.log?  The bit pasted above doesn't show any errors.

Comment 4 Ronnie Rasouli 2016-09-29 07:17:42 UTC

Created attachment 1205858 [details]
last 1000 lines of evm.log

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