Skip to content

Instantly share code, notes, and snippets.

@vrutkovs

vrutkovs/gist:d4afec07cc46d9895cf5

Created February 29, 2016 12:42
Show Gist options

  • Select an option

    Learn more about clone URLs
  • Save vrutkovs/d4afec07cc46d9895cf5 to your computer and use it in GitHub Desktop.

Select an option

Learn more about clone URLs
Save vrutkovs/d4afec07cc46d9895cf5 to your computer and use it in GitHub Desktop.
Download ZIP
Raw
gistfile1.txt
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:21.692919 #1280:db351c] INFO -- : Started POST "/ems_container/form_field_changed/new?name=O" for 127.0.0.1 at 2016-02-29 12:39:21 +0000
[----] I, [2016-02-29T12:39:21.708718 #1280:db351c] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:21.708910 #1280:db351c] INFO -- : Parameters: {"name"=>"O", "id"=>"new"}
[----] I, [2016-02-29T12:39:22.105169 #1280:db351c] INFO -- : Completed 200 OK in 396ms (Views: 2.1ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:22.226130 #1280:bc2ab4] INFO -- : Started POST "/ems_container/form_field_changed/new?name=OSE" for 127.0.0.1 at 2016-02-29 12:39:22 +0000
[----] I, [2016-02-29T12:39:22.234299 #1280:bc2ab4] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:22.235361 #1280:bc2ab4] INFO -- : Parameters: {"name"=>"OSE", "id"=>"new"}
[----] I, [2016-02-29T12:39:22.402946 #1280:bc2ab4] INFO -- : Completed 200 OK in 167ms (Views: 2.2ms | ActiveRecord: 0.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:22.769007 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:39:22 UTC]...
[----] I, [2016-02-29T12:39:22.862371 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:39:22 UTC]...Complete
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:23.090453 #1280:db351c] INFO -- : Started POST "/ems_container/form_field_changed/new?name=OSE" for 127.0.0.1 at 2016-02-29 12:39:23 +0000
[----] I, [2016-02-29T12:39:23.098141 #1280:db351c] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:23.098347 #1280:db351c] INFO -- : Parameters: {"name"=>"OSE", "id"=>"new"}
[----] I, [2016-02-29T12:39:23.304527 #1280:db351c] INFO -- : Completed 200 OK in 206ms (Views: 6.4ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:24.251471 #1280:db351c] INFO -- : Started POST "/ems_container/form_field_changed/new?server_emstype=openshift_enterprise" for 127.0.0.1 at 2016-02-29 12:39:24 +0000
[----] I, [2016-02-29T12:39:24.258284 #1280:db351c] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:24.258471 #1280:db351c] INFO -- : Parameters: {"server_emstype"=>"openshift_enterprise", "id"=>"new"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:24.339876 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:24.449329 #1280:db351c] INFO -- : Rendered layouts/_flash_msg.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:24.453838 #1280:db351c] INFO -- : Rendered ems_container/_form_fields.html.haml (0.8ms)
[----] I, [2016-02-29T12:39:24.472123 #1280:db351c] INFO -- : Rendered layouts/_form_buttons_verify.html.haml (1.1ms)
[----] I, [2016-02-29T12:39:24.472443 #1280:db351c] INFO -- : Rendered layouts/_auth_bearer_token.html.haml (2.7ms)
[----] I, [2016-02-29T12:39:24.472738 #1280:db351c] INFO -- : Rendered layouts/_container_auth.html.haml (4.0ms)
[----] I, [2016-02-29T12:39:24.474789 #1280:db351c] INFO -- : Rendered shared/views/ems_common/_form.html.haml (26.6ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:24.477042 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [414], 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-02-29T12:39:24.517110 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [415], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:24.565641 #1280:db351c] INFO -- : Completed 200 OK in 307ms (Views: 76.2ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:26.288861 #1280:1227648] INFO -- : Started POST "/ems_container/form_field_changed/new?hostname=10.3.13.105" for 127.0.0.1 at 2016-02-29 12:39:26 +0000
[----] I, [2016-02-29T12:39:26.339491 #1280:1227648] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:26.339773 #1280:1227648] INFO -- : Parameters: {"hostname"=>"10.3.13.105", "id"=>"new"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:28.422764 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:28.445063 #1280:1227648] INFO -- : Completed 200 OK in 2105ms (Views: 1.9ms | ActiveRecord: 0.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:28.589777 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [414], 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: [4.160673029] seconds
[----] I, [2016-02-29T12:39:28.590254 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [414], Delivering...
[----] I, [2016-02-29T12:39:28.621157 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.0009951591491699219, :jobs_to_dispatch_count=>0, :total_time=>0.030393362045288086}
[----] I, [2016-02-29T12:39:28.626075 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [414], State: [ok], Delivered in [0.035854979] seconds
[----] I, [2016-02-29T12:39:30.627786 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [415], MiqWorker id: [2], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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: [6.12334549] seconds
[----] I, [2016-02-29T12:39:30.628167 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [415], Delivering...
[----] D, [2016-02-29T12:39:30.628964 #1242:87d994] DEBUG -- : Checking session data
[----] I, [2016-02-29T12:39:30.707377 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [415], State: [ok], Delivered in [0.079208328] seconds
[----] D, [2016-02-29T12:39:37.037523 #1280:93aa1c] DEBUG -- : MIQ(MiqUiWorker::Runner) Garbage collection took 0.7553862010245211 seconds
[----] D, [2016-02-29T12:39:37.508942 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:39:37.509236 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:39:37.516208 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:39:37.544346 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.005527973175048828, :worker_monitor=>4.082116365432739, :worker_dequeue=>0.02704310417175293, :total_time=>4.115138530731201}
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:38.084155 #1280:85d4b4] INFO -- : Started POST "/ems_container/form_field_changed/new?bearer_token=8_-tvIBrFF2NTjV1IE4aV1iCAu8crdFdlTa5q7mdf44" for 127.0.0.1 at 2016-02-29 12:39:38 +0000
[----] I, [2016-02-29T12:39:38.093976 #1280:85d4b4] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:38.094188 #1280:85d4b4] INFO -- : Parameters: {"bearer_token"=>"8_-tvIBrFF2NTjV1IE4aV1iCAu8crdFdlTa5q7mdf44", "id"=>"new"}
[----] I, [2016-02-29T12:39:38.153525 #1280:91d4bc] INFO -- : Started POST "/ems_container/form_field_changed/new?bearer_token=8_-tvIBrFF2NTjV1IE4aV1iCAu8crdFdlTa5q7mdf44" for 127.0.0.1 at 2016-02-29 12:39:38 +0000
[----] I, [2016-02-29T12:39:38.171077 #1280:91d4bc] INFO -- : Processing by EmsContainerController#form_field_changed as JS
[----] I, [2016-02-29T12:39:38.171304 #1280:91d4bc] INFO -- : Parameters: {"bearer_token"=>"8_-tvIBrFF2NTjV1IE4aV1iCAu8crdFdlTa5q7mdf44", "id"=>"new"}
[----] I, [2016-02-29T12:39:38.382388 #1280:85d4b4] INFO -- : Completed 200 OK in 288ms (Views: 1.4ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:38.420445 #1280:91d4bc] INFO -- : Completed 200 OK in 249ms (Views: 2.1ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:39.181988 #1280:91d4bc] INFO -- : Started POST "/ems_container/create/new?button=validate&type=bearer" for 127.0.0.1 at 2016-02-29 12:39:39 +0000
[----] I, [2016-02-29T12:39:39.186992 #1280:91d4bc] INFO -- : Processing by EmsContainerController#create as JS
[----] I, [2016-02-29T12:39:39.187334 #1280:91d4bc] INFO -- : Parameters: {"button"=>"validate", "type"=>"bearer", "id"=>"new"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:39.414850 #1280:91d4bc] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_new]
[----] I, [2016-02-29T12:39:39.435291 #1280:91d4bc] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::OpenshiftEnterprise::ContainerManager: [OSE]
[----] I, [2016-02-29T12:39:39.613239 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-02-29T12:39:39.639970 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [416], 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: []
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:40.406115 #1280:91d4bc] INFO -- : Rendered layouts/_flash_msg.html.haml (0.4ms)
[----] I, [2016-02-29T12:39:40.437228 #1280:91d4bc] INFO -- : Completed 200 OK in 1250ms (Views: 5.4ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:42.410916 #1280:ff7eb8] INFO -- : Started POST "/ems_container/create/new?button=add" for 127.0.0.1 at 2016-02-29 12:39:42 +0000
[----] I, [2016-02-29T12:39:42.415022 #1280:ff7eb8] INFO -- : Processing by EmsContainerController#create as JS
[----] I, [2016-02-29T12:39:42.415229 #1280:ff7eb8] INFO -- : Parameters: {"button"=>"add", "id"=>"new"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:42.590180 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] D, [2016-02-29T12:39:42.592944 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_new]
[----] I, [2016-02-29T12:39:42.650857 #1280:ff7eb8] INFO -- : MIQ(AuthToken#after_authentication_changed) [ExtManagementSystem] [5], previously valid on: []
[----] I, [2016-02-29T12:39:42.683574 #1280:ff7eb8] INFO -- : MIQ(MiqQueue.put) Message id: [417], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_changed", {}]
[----] I, [2016-02-29T12:39:42.707975 #1280:ff7eb8] INFO -- : MIQ(MiqQueue.put) Message id: [418], id: [], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [5], Task id: [], Command: [ExtManagementSystem.authentication_check_types], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[:bearer], {}]
[----] I, [2016-02-29T12:39:42.767060 #1280:ff7eb8] INFO -- : <AuditSuccess> MIQ(EmsCommon.create) userid: [admin] - [OSE] Record created (name:[OSE], provider_region:[], hostname:[10.3.13.105], emstype:[openshift_enterprise], port:[8443], api_version:[], provider_id:[], security_protocol:[kerberos], zone:[default], default_userid:[], default_password:[*], metrics_userid:[], metrics_password:[*], amqp_userid:[], amqp_password:[*], ssh_keypair_userid:[], ssh_keypair_password:[*], bearer_token:[8_-tvIBrFF2NTjV1IE4aV1iCAu8crdFdlTa5q7mdf44], ipaddress:[])
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:42.878708 #1280:ff7eb8] INFO -- : Completed 200 OK in 463ms (Views: 4.1ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:43.093047 #1280:ff7eb8] INFO -- : Started GET "/ems_container/show_list?flash_msg=Containers+Providers+%22OSE%22+was+saved" for 127.0.0.1 at 2016-02-29 12:39:43 +0000
[----] I, [2016-02-29T12:39:43.096683 #1280:ff7eb8] INFO -- : Processing by EmsContainerController#show_list as HTML
[----] I, [2016-02-29T12:39:43.096860 #1280:ff7eb8] INFO -- : Parameters: {"flash_msg"=>"Containers Providers \"OSE\" was saved"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:43.160053 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [416], 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: [3.532277524] seconds
[----] D, [2016-02-29T12:39:43.188968 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_show_list]
[----] I, [2016-02-29T12:39:43.189071 #1242:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [416], Delivering...
[----] I, [2016-02-29T12:39:43.211881 #1242:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.013427972793579102, :jobs_to_dispatch_count=>0, :total_time=>0.02098679542541504}
[----] I, [2016-02-29T12:39:43.213917 #1242:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [416], State: [ok], Delivered in [0.024876057] seconds
[----] D, [2016-02-29T12:39:43.218665 #1280:ff7eb8] DEBUG -- : MIQ(Rbac.search) Find options: {:conditions=>nil, :include=>{:hostname=>{}, :ipaddress=>{}, :emstype_description=>{}, :port=>{}, :zone=>{}, :tags=>{}}, :order=>"LOWER(ext_management_systems.name) asc", :limit=>20, :offset=>0}
[----] D, [2016-02-29T12:39:43.285996 #1280:ff7eb8] DEBUG -- : MIQ(MiqReport#paged_view_search) Attrs: {:user_filters=>{"managed"=>[], "belongsto"=>[]}, :apply_limit_in_sql=>true, :total_count=>1, :auth_count=>1, :targets_hash=>"...", :apply_sortby_in_search=>true}
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:43.299479 #1280:ff7eb8] INFO -- : Rendered layouts/_info_msg.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.300113 #1280:ff7eb8] INFO -- : Rendered layouts/_flash_msg.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:43.304667 #1280:ff7eb8] INFO -- : Rendered layouts/quadicon/_ext_management_system.html.haml (2.7ms)
[----] I, [2016-02-29T12:39:43.306616 #1280:ff7eb8] INFO -- : Rendered layouts/quadicon/_quadicon_text.html.haml (1.0ms)
[----] I, [2016-02-29T12:39:43.306802 #1280:ff7eb8] INFO -- : Rendered layouts/gtl/_grid.html.haml (6.4ms)
[----] I, [2016-02-29T12:39:43.306945 #1280:ff7eb8] INFO -- : Rendered layouts/_gtl.html.haml (7.8ms)
[----] I, [2016-02-29T12:39:43.307110 #1280:ff7eb8] INFO -- : Rendered ems_container/show_list.html.haml within layouts/application (8.2ms)
[----] I, [2016-02-29T12:39:43.307471 #1280:ff7eb8] INFO -- : Rendered layouts/_doctype.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.309385 #1280:ff7eb8] INFO -- : Rendered stylesheets/_template50.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:43.319768 #1280:ff7eb8] INFO -- : Rendered layouts/_i18n_js.html.haml (9.4ms)
[----] I, [2016-02-29T12:39:43.329863 #1280:ff7eb8] INFO -- : Rendered layouts/_user_options.html.haml (9.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:43.330948 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [vi]
[----] D, [2016-02-29T12:39:43.331742 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [dashboard_view]
[----] D, [2016-02-29T12:39:43.333098 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_report]
[----] D, [2016-02-29T12:39:43.333737 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [chargeback]
[----] D, [2016-02-29T12:39:43.334036 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [timeline]
[----] D, [2016-02-29T12:39:43.334303 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [rss]
[----] D, [2016-02-29T12:39:43.334605 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [svc]
[----] D, [2016-02-29T12:39:43.334990 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [service]
[----] D, [2016-02-29T12:39:43.335258 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [catalog]
[----] D, [2016-02-29T12:39:43.335597 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_explorer_accords]
[----] D, [2016-02-29T12:39:43.335922 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:43.336183 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [clo]
[----] D, [2016-02-29T12:39:43.336654 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_cloud_show_list]
[----] D, [2016-02-29T12:39:43.336982 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [availability_zone_show_list]
[----] D, [2016-02-29T12:39:43.337311 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [cloud_tenant_show_list]
[----] D, [2016-02-29T12:39:43.337675 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [cloud_volume_show_list]
[----] D, [2016-02-29T12:39:43.337991 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [flavor_show_list]
[----] D, [2016-02-29T12:39:43.338321 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [security_group_show_list]
[----] D, [2016-02-29T12:39:43.338665 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_cloud_explorer_accords]
[----] D, [2016-02-29T12:39:43.339017 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [orchestration_stack_show_list]
[----] D, [2016-02-29T12:39:43.339350 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [auth_key_pair_cloud_show_list]
[----] D, [2016-02-29T12:39:43.339661 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [inf]
[----] D, [2016-02-29T12:39:43.340080 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_infra_show_list]
[----] D, [2016-02-29T12:39:43.340390 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_cluster_show_list]
[----] D, [2016-02-29T12:39:43.344480 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [host_show_list]
[----] D, [2016-02-29T12:39:43.351916 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_infra_explorer_accords]
[----] D, [2016-02-29T12:39:43.352438 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [resource_pool_show_list]
[----] D, [2016-02-29T12:39:43.352797 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [storage_show_list]
[----] D, [2016-02-29T12:39:43.353464 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [repository_show_list]
[----] D, [2016-02-29T12:39:43.353775 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [pxe]
[----] D, [2016-02-29T12:39:43.354092 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:43.354362 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [provider_foreman_explorer]
[----] D, [2016-02-29T12:39:43.354680 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [cnt]
[----] D, [2016-02-29T12:39:43.355068 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_dashboard]
[----] D, [2016-02-29T12:39:43.355392 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_show_list]
[----] D, [2016-02-29T12:39:43.355725 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_project_show_list]
[----] D, [2016-02-29T12:39:43.356310 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_route_show_list]
[----] D, [2016-02-29T12:39:43.357048 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_service_show_list]
[----] D, [2016-02-29T12:39:43.357519 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_replicator_show_list]
[----] D, [2016-02-29T12:39:43.358198 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_group_show_list]
[----] D, [2016-02-29T12:39:43.358763 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [containers]
[----] D, [2016-02-29T12:39:43.359273 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_node_show_list]
[----] D, [2016-02-29T12:39:43.359690 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [persistent_volume_show_list]
[----] D, [2016-02-29T12:39:43.360018 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_registry_show_list]
[----] D, [2016-02-29T12:39:43.360704 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_show_list]
[----] D, [2016-02-29T12:39:43.361030 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_topology]
[----] D, [2016-02-29T12:39:43.361320 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [mdl]
[----] D, [2016-02-29T12:39:43.361802 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_middleware_show_list]
[----] D, [2016-02-29T12:39:43.362133 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_server_show_list]
[----] D, [2016-02-29T12:39:43.362773 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_deployment_show_list]
[----] D, [2016-02-29T12:39:43.363340 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_topology]
[----] D, [2016-02-29T12:39:43.363660 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [con]
[----] D, [2016-02-29T12:39:43.364095 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [control_explorer_view]
[----] D, [2016-02-29T12:39:43.364401 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_simulation]
[----] D, [2016-02-29T12:39:43.364877 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_import_export]
[----] D, [2016-02-29T12:39:43.365153 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_log]
[----] D, [2016-02-29T12:39:43.365425 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [aut]
[----] D, [2016-02-29T12:39:43.365863 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_domain_view]
[----] D, [2016-02-29T12:39:43.366112 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_simulation]
[----] D, [2016-02-29T12:39:43.366401 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_customization_explorer]
[----] D, [2016-02-29T12:39:43.366754 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_import_export]
[----] D, [2016-02-29T12:39:43.367068 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_log]
[----] D, [2016-02-29T12:39:43.367445 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:43.367767 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [opt]
[----] D, [2016-02-29T12:39:43.368147 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [utilization]
[----] D, [2016-02-29T12:39:43.368432 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [planning]
[----] D, [2016-02-29T12:39:43.368742 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [bottlenecks]
[----] D, [2016-02-29T12:39:43.369056 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], main tab [set]
[----] D, [2016-02-29T12:39:43.369501 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings]
[----] D, [2016-02-29T12:39:43.369862 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [tasks]
[----] D, [2016-02-29T12:39:43.370193 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ops_explorer]
[----] D, [2016-02-29T12:39:43.370664 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [about]
[----] D, [2016-02-29T12:39:43.374161 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:43.374475 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:43.374772 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_refresh]
[----] D, [2016-02-29T12:39:43.375075 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_refresh]
[----] D, [2016-02-29T12:39:43.376092 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:43.376477 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:43.376881 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_new]
[----] D, [2016-02-29T12:39:43.377288 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_new]
[----] D, [2016-02-29T12:39:43.378490 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:43.378832 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:43.379105 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_edit]
[----] D, [2016-02-29T12:39:43.379427 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_edit]
[----] D, [2016-02-29T12:39:43.380304 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:43.370956 #1280:ff7eb8] INFO -- : Rendered layouts/_page_header_navbar.html.haml (40.6ms)
[----] I, [2016-02-29T12:39:43.371522 #1280:ff7eb8] INFO -- : Rendered layouts/_spinner.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:43.371909 #1280:ff7eb8] INFO -- : Rendered layouts/_lightbox_panel.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.372112 #1280:ff7eb8] INFO -- : Rendered layouts/_header.html.haml (51.7ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:43.380749 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:43.381190 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_delete]
[----] D, [2016-02-29T12:39:43.381510 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_delete]
[----] D, [2016-02-29T12:39:43.383237 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:43.383535 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:43.383898 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_tag]
[----] D, [2016-02-29T12:39:43.384216 #1280:ff7eb8] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_tag]
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:43.393157 #1280:ff7eb8] INFO -- : Rendered layouts/_breadcrumbs.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.393537 #1280:ff7eb8] INFO -- : Rendered layouts/_tabs.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.395480 #1280:ff7eb8] INFO -- : Rendered layouts/_user_input_filter.html.haml (1.3ms)
[----] I, [2016-02-29T12:39:43.395643 #1280:ff7eb8] INFO -- : Rendered layouts/_quick_search.html.haml (1.6ms)
[----] I, [2016-02-29T12:39:43.396741 #1280:ff7eb8] INFO -- : Rendered layouts/_searchbar.html.haml (2.9ms)
[----] I, [2016-02-29T12:39:43.400910 #1280:ff7eb8] INFO -- : Rendered layouts/_pagingcontrols.html.haml (2.4ms)
[----] I, [2016-02-29T12:39:43.401818 #1280:ff7eb8] INFO -- : Rendered layouts/_info_msg.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:43.401955 #1280:ff7eb8] INFO -- : Rendered layouts/listnav/_show_list.html.haml (0.4ms)
[----] I, [2016-02-29T12:39:43.402066 #1280:ff7eb8] INFO -- : Rendered layouts/_listnav.html.haml (0.8ms)
[----] I, [2016-02-29T12:39:43.402227 #1280:ff7eb8] INFO -- : Rendered layouts/_content.html.haml (29.9ms)
[----] I, [2016-02-29T12:39:43.522465 #1280:ff7eb8] INFO -- : Rendered layouts/_flash_msg.html.haml (0.3ms)
[----] I, [2016-02-29T12:39:43.552847 #1280:ff7eb8] INFO -- : Rendered layouts/exp_atom/_editor.html.haml (2.3ms)
[----] I, [2016-02-29T12:39:43.553090 #1280:ff7eb8] INFO -- : Rendered layouts/_exp_editor.html.haml (30.2ms)
[----] I, [2016-02-29T12:39:43.553236 #1280:ff7eb8] INFO -- : Rendered layouts/_adv_search_body.html.haml (150.3ms)
[----] I, [2016-02-29T12:39:43.561397 #1280:ff7eb8] INFO -- : Rendered layouts/_adv_search_footer.html.haml (4.3ms)
[----] I, [2016-02-29T12:39:43.561644 #1280:ff7eb8] INFO -- : Rendered layouts/_adv_search.html.haml (159.0ms)
[----] I, [2016-02-29T12:39:43.561843 #1280:ff7eb8] INFO -- : Rendered layouts/_footer.html.haml (159.4ms)
[----] I, [2016-02-29T12:39:43.600868 #1280:ff7eb8] INFO -- : Completed 200 OK in 504ms (Views: 264.7ms | ActiveRecord: 0.0ms)
[----] I, [2016-02-29T12:39:46.116233 #1280:bdfe5c] INFO -- : Started GET "/ems_container/show/5" for 127.0.0.1 at 2016-02-29 12:39:46 +0000
[----] I, [2016-02-29T12:39:46.149095 #1280:bdfe5c] INFO -- : Processing by EmsContainerController#show as HTML
[----] I, [2016-02-29T12:39:46.149304 #1280:bdfe5c] INFO -- : Parameters: {"id"=>"5"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:46.261200 #1261:87d994] DEBUG -- : MIQ(MiqReportingWorker::Runner) Garbage collection took 0.5983024120214395 seconds
[----] D, [2016-02-29T12:39:46.376265 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_show]
[----] D, [2016-02-29T12:39:46.444814 #1280:bdfe5c] DEBUG -- : MIQ(Rbac.search) Find options: {:conditions=>"ext_management_systems.id = 5", :include=>{}, :order=>nil, :limit=>nil, :offset=>nil}
[----] D, [2016-02-29T12:39:46.531346 #1290:93b0d4] DEBUG -- : MIQ(MiqWebServiceWorker::Runner) Garbage collection took 0.7244057490024716 seconds
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:46.578245 #1280:bdfe5c] INFO -- : Rendered layouts/_flash_msg.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.620172 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual.html.haml (41.3ms)
[----] I, [2016-02-29T12:39:46.621688 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual_multivalue.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:46.621885 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual.html.haml (1.2ms)
[----] I, [2016-02-29T12:39:46.636350 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual_multilabel.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.733941 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual.html.haml (96.9ms)
[----] I, [2016-02-29T12:39:46.735291 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual.html.haml (0.3ms)
[----] I, [2016-02-29T12:39:46.741148 #1280:bdfe5c] INFO -- : Rendered shared/summary/_textual_tags.html.haml (5.5ms)
[----] I, [2016-02-29T12:39:46.742084 #1280:bdfe5c] INFO -- : Rendered ems_container/_main.html.haml (164.1ms)
[----] I, [2016-02-29T12:39:46.742267 #1280:bdfe5c] INFO -- : Rendered shared/views/ems_common/_show.html.haml (164.5ms)
[----] I, [2016-02-29T12:39:46.742846 #1280:bdfe5c] INFO -- : Rendered ems_container/show.html.haml within layouts/application (164.9ms)
[----] I, [2016-02-29T12:39:46.743596 #1280:bdfe5c] INFO -- : Rendered layouts/_doctype.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.746286 #1280:bdfe5c] INFO -- : Rendered stylesheets/_template50.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:46.765858 #1280:bdfe5c] INFO -- : Rendered layouts/_i18n_js.html.haml (17.4ms)
[----] I, [2016-02-29T12:39:46.781702 #1280:bdfe5c] INFO -- : Rendered layouts/_user_options.html.haml (14.5ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:46.782831 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [vi]
[----] D, [2016-02-29T12:39:46.783488 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [dashboard_view]
[----] D, [2016-02-29T12:39:46.783940 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_report]
[----] D, [2016-02-29T12:39:46.784248 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [chargeback]
[----] D, [2016-02-29T12:39:46.784529 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [timeline]
[----] D, [2016-02-29T12:39:46.784935 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [rss]
[----] D, [2016-02-29T12:39:46.785273 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [svc]
[----] D, [2016-02-29T12:39:46.785735 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [service]
[----] D, [2016-02-29T12:39:46.786111 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [catalog]
[----] D, [2016-02-29T12:39:46.786623 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_explorer_accords]
[----] D, [2016-02-29T12:39:46.786989 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:46.787292 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [clo]
[----] D, [2016-02-29T12:39:46.787784 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_cloud_show_list]
[----] D, [2016-02-29T12:39:46.788293 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [availability_zone_show_list]
[----] D, [2016-02-29T12:39:46.788741 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [cloud_tenant_show_list]
[----] D, [2016-02-29T12:39:46.789127 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [cloud_volume_show_list]
[----] D, [2016-02-29T12:39:46.789428 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [flavor_show_list]
[----] D, [2016-02-29T12:39:46.789740 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [security_group_show_list]
[----] D, [2016-02-29T12:39:46.790030 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_cloud_explorer_accords]
[----] D, [2016-02-29T12:39:46.790304 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [orchestration_stack_show_list]
[----] D, [2016-02-29T12:39:46.790621 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [auth_key_pair_cloud_show_list]
[----] D, [2016-02-29T12:39:46.790890 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [inf]
[----] D, [2016-02-29T12:39:46.791269 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_infra_show_list]
[----] D, [2016-02-29T12:39:46.791599 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_cluster_show_list]
[----] D, [2016-02-29T12:39:46.802337 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [host_show_list]
[----] D, [2016-02-29T12:39:46.807398 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [vm_infra_explorer_accords]
[----] D, [2016-02-29T12:39:46.808108 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [resource_pool_show_list]
[----] D, [2016-02-29T12:39:46.808528 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [storage_show_list]
[----] D, [2016-02-29T12:39:46.809200 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [repository_show_list]
[----] D, [2016-02-29T12:39:46.809494 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [pxe]
[----] D, [2016-02-29T12:39:46.809839 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:46.810085 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [provider_foreman_explorer]
[----] D, [2016-02-29T12:39:46.810335 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [cnt]
[----] D, [2016-02-29T12:39:46.810688 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_dashboard]
[----] D, [2016-02-29T12:39:46.810958 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_show_list]
[----] D, [2016-02-29T12:39:46.811262 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_project_show_list]
[----] D, [2016-02-29T12:39:46.811818 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_route_show_list]
[----] D, [2016-02-29T12:39:46.812362 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_service_show_list]
[----] D, [2016-02-29T12:39:46.812739 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_replicator_show_list]
[----] D, [2016-02-29T12:39:46.813375 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_group_show_list]
[----] D, [2016-02-29T12:39:46.813885 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [containers]
[----] D, [2016-02-29T12:39:46.814350 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_node_show_list]
[----] D, [2016-02-29T12:39:46.814703 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [persistent_volume_show_list]
[----] D, [2016-02-29T12:39:46.814982 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_registry_show_list]
[----] D, [2016-02-29T12:39:46.815593 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_show_list]
[----] D, [2016-02-29T12:39:46.815875 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_topology]
[----] D, [2016-02-29T12:39:46.816150 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [mdl]
[----] D, [2016-02-29T12:39:46.816529 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_middleware_show_list]
[----] D, [2016-02-29T12:39:46.816846 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_server_show_list]
[----] D, [2016-02-29T12:39:46.817336 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_deployment_show_list]
[----] D, [2016-02-29T12:39:46.817925 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [middleware_topology]
[----] D, [2016-02-29T12:39:46.818168 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [con]
[----] D, [2016-02-29T12:39:46.818495 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [control_explorer_view]
[----] D, [2016-02-29T12:39:46.818832 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_simulation]
[----] D, [2016-02-29T12:39:46.819078 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_import_export]
[----] D, [2016-02-29T12:39:46.819300 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [policy_log]
[----] D, [2016-02-29T12:39:46.819614 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [aut]
[----] D, [2016-02-29T12:39:46.820144 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_domain_view]
[----] D, [2016-02-29T12:39:46.820479 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_simulation]
[----] D, [2016-02-29T12:39:46.821867 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_customization_explorer]
[----] D, [2016-02-29T12:39:46.822777 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_import_export]
[----] D, [2016-02-29T12:39:46.823032 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_ae_class_log]
[----] D, [2016-02-29T12:39:46.823372 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_show_list]
[----] D, [2016-02-29T12:39:46.823770 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [opt]
[----] D, [2016-02-29T12:39:46.824148 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [utilization]
[----] D, [2016-02-29T12:39:46.824428 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [planning]
[----] D, [2016-02-29T12:39:46.824870 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [bottlenecks]
[----] D, [2016-02-29T12:39:46.825182 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], main tab [set]
[----] D, [2016-02-29T12:39:46.825577 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings]
[----] D, [2016-02-29T12:39:46.825853 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [tasks]
[----] D, [2016-02-29T12:39:46.826148 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ops_explorer]
[----] D, [2016-02-29T12:39:46.826482 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [about]
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:46.826839 #1280:bdfe5c] INFO -- : Rendered layouts/_page_header_navbar.html.haml (44.5ms)
[----] I, [2016-02-29T12:39:46.827418 #1280:bdfe5c] INFO -- : Rendered layouts/_spinner.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.829958 #1280:bdfe5c] INFO -- : Rendered layouts/_lightbox_panel.html.haml (0.8ms)
[----] I, [2016-02-29T12:39:46.830192 #1280:bdfe5c] INFO -- : Rendered layouts/_header.html.haml (63.6ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:46.831902 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.832247 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.832636 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [refresh_server_summary]
[----] D, [2016-02-29T12:39:46.835192 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.835529 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.835805 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_refresh]
[----] D, [2016-02-29T12:39:46.837258 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.837530 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.837796 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_edit]
[----] D, [2016-02-29T12:39:46.838898 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.839162 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.839389 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_delete]
[----] D, [2016-02-29T12:39:46.841424 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.841771 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.842050 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_perf]
[----] D, [2016-02-29T12:39:46.843158 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.843482 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.843827 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_timeline]
[----] D, [2016-02-29T12:39:46.846204 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [my_settings_time_profiles]
[----] D, [2016-02-29T12:39:46.846524 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [miq_request_approval]
[----] D, [2016-02-29T12:39:46.846842 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_tag]
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:46.853900 #1280:bdfe5c] INFO -- : Rendered layouts/_breadcrumbs.html.haml (0.2ms)
[----] I, [2016-02-29T12:39:46.854447 #1280:bdfe5c] INFO -- : Rendered layouts/_tabs.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.858109 #1280:bdfe5c] INFO -- : Rendered layouts/_searchbar.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.858539 #1280:bdfe5c] INFO -- : Rendered layouts/_pagingcontrols.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.877329 #1280:bdfe5c] INFO -- : Rendered layouts/quadicon/_ext_management_system.html.haml (3.3ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:46.899135 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_project_show_list]
[----] D, [2016-02-29T12:39:46.903183 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_route_show_list]
[----] D, [2016-02-29T12:39:46.908948 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_service_show_list]
[----] D, [2016-02-29T12:39:46.912237 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_replicator_show_list]
[----] D, [2016-02-29T12:39:46.914331 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_group_show_list]
[----] D, [2016-02-29T12:39:46.916655 #1280:bdfe5c] DEBUG -- : Role Authorization failed for: userid [admin], role id [1], feature identifier [,_show_list]
[----] D, [2016-02-29T12:39:46.917039 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_show_list]
[----] D, [2016-02-29T12:39:46.922469 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_node_show_list]
[----] D, [2016-02-29T12:39:46.923469 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_registry_show_list]
[----] D, [2016-02-29T12:39:46.926079 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [container_image_show_list]
[----] D, [2016-02-29T12:39:46.928726 #1280:bdfe5c] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [persistent_volume_show_list]
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:46.929976 #1280:bdfe5c] INFO -- : Rendered layouts/listnav/_ems_container.html.haml (64.5ms)
[----] I, [2016-02-29T12:39:46.930198 #1280:bdfe5c] INFO -- : Rendered layouts/_listnav.html.haml (65.7ms)
[----] I, [2016-02-29T12:39:46.930393 #1280:bdfe5c] INFO -- : Rendered layouts/_content.html.haml (99.9ms)
[----] I, [2016-02-29T12:39:46.933132 #1280:bdfe5c] INFO -- : Rendered layouts/_adv_search.html.haml (0.1ms)
[----] I, [2016-02-29T12:39:46.933345 #1280:bdfe5c] INFO -- : Rendered layouts/_footer.html.haml (1.8ms)
[----] I, [2016-02-29T12:39:46.955760 #1280:bdfe5c] INFO -- : Completed 200 OK in 806ms (Views: 360.9ms | ActiveRecord: 0.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:47.636981 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] D, [2016-02-29T12:39:48.128166 #1265:87d994] DEBUG -- : MIQ(MiqReportingWorker::Runner) Garbage collection took 0.8457603819842916 seconds
[----] I, [2016-02-29T12:39:49.355359 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [417], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_changed", {}], Dequeued in: [6.691978895] seconds
[----] I, [2016-02-29T12:39:49.355820 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [417], Delivering...
[----] I, [2016-02-29T12:39:49.453809 #1242:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"ems_auth_changed"> inputs=<{"MiqEvent::miq_event"=>78, :miq_event_id=>78, "EventStream::event_stream"=>78, :event_stream_id=>78}>
[----] I, [2016-02-29T12:39:49.499208 #1242:87d994] INFO -- : MIQ(User#current_group=) User: [admin] Assigning Role: [EvmRole-tenant_administrator] from Group: [Tenant My Company access]
[----] I, [2016-02-29T12:39:49.544317 #1242:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [419], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>78, :miq_event_id=>78, "EventStream::event_stream"=>78, :event_stream_id=>78}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:39:49.545708 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [417], State: [ok], Delivered in [0.189737823] seconds
[----] I, [2016-02-29T12:39:49.603283 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [418], MiqWorker id: [2], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [5], Task id: [], Command: [ExtManagementSystem.authentication_check_types], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[:bearer], {}], Dequeued in: [6.902100331] seconds
[----] I, [2016-02-29T12:39:49.603877 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [418], Delivering...
[----] I, [2016-02-29T12:39:49.651305 #1242:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager#with_provider_connection) Connecting through ManageIQ::Providers::OpenshiftEnterprise::ContainerManager: [OSE]
[----] I, [2016-02-29T12:39:49.983599 #1242:87d994] INFO -- : MIQ(AuthToken#validation_successful) [ExtManagementSystem] [5], previously valid/invalid on: []/[], previous status: []
[----] I, [2016-02-29T12:39:50.036877 #1242:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [420], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_valid", {}]
[----] I, [2016-02-29T12:39:50.037530 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [418], State: [ok], Delivered in [0.433948729] seconds
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:50.847872 #1280:280f7d0] INFO -- : Started POST "/ems_container/button/5?pressed=ems_container_refresh" for 127.0.0.1 at 2016-02-29 12:39:50 +0000
[----] I, [2016-02-29T12:39:51.028775 #1280:280f7d0] INFO -- : Processing by EmsContainerController#button as JS
[----] I, [2016-02-29T12:39:51.028974 #1280:280f7d0] INFO -- : Parameters: {"pressed"=>"ems_container_refresh", "id"=>"5"}
==> /var/www/miq/vmdb/log/evm.log <==
[----] D, [2016-02-29T12:39:51.563490 #1280:280f7d0] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_refresh]
[----] D, [2016-02-29T12:39:51.572137 #1280:280f7d0] DEBUG -- : Role Authorization successful for: userid [admin], role id [1], feature identifier [ems_container_refresh]
[----] I, [2016-02-29T12:39:51.731335 #1280:280f7d0] INFO -- : MIQ(MiqQueue.put) Message id: [421], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_5], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5]]]
[----] I, [2016-02-29T12:39:51.761761 #1280:280f7d0] INFO -- : <AuditSuccess> MIQ(EmsCommon.process_emss) userid: [admin] - 'refresh_ems' successfully initiated for 1 Containers Providers
[----] D, [2016-02-29T12:39:51.804481 #1280:280f7d0] DEBUG -- : MIQ(Rbac.search) Find options: {:conditions=>"ext_management_systems.id = 5", :include=>{}, :order=>nil, :limit=>nil, :offset=>nil}
[----] D, [2016-02-29T12:39:51.862737 #1280:280f7d0] DEBUG -- : MIQ(Rbac.search) Find options: {:conditions=>"ext_management_systems.id = 5", :include=>{}, :order=>nil, :limit=>nil, :offset=>nil}
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:39:51.902404 #1280:280f7d0] INFO -- : Rendered layouts/_flash_msg.html.haml (0.4ms)
[----] I, [2016-02-29T12:39:51.938717 #1280:280f7d0] INFO -- : Completed 200 OK in 909ms (Views: 3.9ms | ActiveRecord: 0.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:39:52.982610 #1112:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker.sync_workers) Workers are being synchronized: Current: [], Desired: ["ems_5"]
[----] I, [2016-02-29T12:39:54.693271 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 16.
[----] I, [2016-02-29T12:39:54.746463 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [422], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Service.retirement_check], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:54.812115 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [423], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Vm.retirement_check], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:54.887221 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [424], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [OrchestrationStack.retirement_check], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:54.993066 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [425], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.refresh_all_ems_timer], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:55.040106 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [426], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [log_status], Command: [MiqServer.log_status], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:55.075954 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [427], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [log_status], Command: [MiqWorker.log_status_all], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:55.120345 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [428], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:39:55.135975 #1112:87d994] INFO -- : :kill_algorithm:
[----] I, [2016-02-29T12:39:55.136221 #1112:87d994] INFO -- : :name: :used_swap_percent_gt_value
[----] I, [2016-02-29T12:39:55.136284 #1112:87d994] INFO -- : :value: 80
[----] I, [2016-02-29T12:39:55.136341 #1112:87d994] INFO -- : :miq_server_time_threshold: 120
[----] I, [2016-02-29T12:39:55.136395 #1112:87d994] INFO -- : :nice_delta: 1
[----] I, [2016-02-29T12:39:55.136450 #1112:87d994] INFO -- : :poll: 2
[----] I, [2016-02-29T12:39:55.136502 #1112:87d994] INFO -- : :start_algorithm:
[----] I, [2016-02-29T12:39:55.136594 #1112:87d994] INFO -- : :name: :used_swap_percent_lt_value
[----] I, [2016-02-29T12:39:55.136647 #1112:87d994] INFO -- : :value: 60
[----] I, [2016-02-29T12:39:55.136744 #1112:87d994] INFO -- : :sync_interval: 1800
[----] I, [2016-02-29T12:39:55.136794 #1112:87d994] INFO -- : :wait_for_started_timeout: 600
[----] D, [2016-02-29T12:39:55.137070 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:type=>:start, :worker_name=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker", :name=>:used_swap_percent_lt_value, :value=>60}]
[----] D, [2016-02-29T12:39:55.137261 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [start] algorithm: [used_swap_percent_lt_value]
[----] D, [2016-02-29T12:39:55.138180 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [start] algorithm: [used_swap_percent_lt_value] completed with result: [true]
[----] I, [2016-02-29T12:39:55.187173 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [429], 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-02-29T12:39:55.344075 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [430], 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-02-29T12:39:55.437618 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [431], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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-02-29T12:39:55.780671 #3093:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker.close_pg_sockets_inherited_from_parent) Closing socket: 20
[----] I, [2016-02-29T12:39:55.895966 #1112:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [432], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker"}]
[----] I, [2016-02-29T12:39:55.896379 #1112:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker#start) Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]
[----] I, [2016-02-29T12:39:56.109458 #3093:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker::Runner#sync_config) ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c], Zone [default], Active Roles [automate,database_operations,ems_inventory,ems_operations,event,reporting,scheduler,smartstate,user_interface,web_services], Assigned Roles [automate,database_operations,database_owner,ems_inventory,ems_operations,event,reporting,scheduler,smartstate,user_interface,web_services], Configuration:
[----] I, [2016-02-29T12:39:56.112356 #3093:87d994] INFO -- : :count: 1
[----] I, [2016-02-29T12:39:56.112498 #3093:87d994] INFO -- : :gc_interval: 900
[----] I, [2016-02-29T12:39:56.112612 #3093:87d994] INFO -- : :heartbeat_freq: 60
[----] I, [2016-02-29T12:39:56.112694 #3093:87d994] INFO -- : :heartbeat_timeout: 120
[----] I, [2016-02-29T12:39:56.112786 #3093:87d994] INFO -- : :memory_threshold: 2147483648
[----] I, [2016-02-29T12:39:56.112878 #3093:87d994] INFO -- : :nice_delta: 7
[----] I, [2016-02-29T12:39:56.112974 #3093:87d994] INFO -- : :parent_time_threshold: 180
[----] I, [2016-02-29T12:39:56.113049 #3093:87d994] INFO -- : :poll: 10
[----] I, [2016-02-29T12:39:56.113140 #3093:87d994] INFO -- : :poll_escalate_max: 30
[----] I, [2016-02-29T12:39:56.113224 #3093:87d994] INFO -- : :poll_method: :normal
[----] I, [2016-02-29T12:39:56.113306 #3093:87d994] INFO -- : :restart_interval: 7200
[----] I, [2016-02-29T12:39:56.113396 #3093:87d994] INFO -- : :starting_timeout: 600
[----] I, [2016-02-29T12:39:56.113495 #3093:87d994] INFO -- : :cpu_usage_threshold: 100
[----] I, [2016-02-29T12:39:56.113615 #3093:87d994] INFO -- : :dequeue_method: :drb
[----] I, [2016-02-29T12:39:56.113699 #3093:87d994] INFO -- : :queue_timeout: 7200
[----] I, [2016-02-29T12:39:56.113758 #3093:87d994] INFO -- : ---
[----] I, [2016-02-29T12:39:56.114940 #3093:87d994] INFO -- : :guid: 88f59666-dee1-11e5-ac53-02420a01024c
[----] I, [2016-02-29T12:39:56.115036 #3093:87d994] INFO -- : :ems_id: 5
[----] W, [2016-02-29T12:39:56.137899 #3093:87d994] WARN -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager#authentication_check_no_validation) type: [nil] for [5] [OSE] Validation failed: incomplete, Missing credentials
[----] W, [2016-02-29T12:39:56.139164 #3093:87d994] WARN -- : MIQ(AuthToken#validation_failed) [ExtManagementSystem] [5], previously valid on: 2016-02-29 12:39:49 UTC, previous status: [Valid]
[----] I, [2016-02-29T12:39:56.140510 #1112:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher.sync_workers) Workers are being synchronized: Current: [], Desired: ["ems_5"]
[----] D, [2016-02-29T12:39:56.141094 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:type=>:start, :worker_name=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher", :name=>:used_swap_percent_lt_value, :value=>60}]
[----] D, [2016-02-29T12:39:56.141277 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [start] algorithm: [used_swap_percent_lt_value]
[----] D, [2016-02-29T12:39:56.143089 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [start] algorithm: [used_swap_percent_lt_value] completed with result: [true]
[----] I, [2016-02-29T12:39:56.190184 #3097:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher.close_pg_sockets_inherited_from_parent) Closing socket: 20
[----] I, [2016-02-29T12:39:56.236036 #3093:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [433], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_incomplete", {}]
[----] I, [2016-02-29T12:39:56.317834 #1112:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [434], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher"}]
[----] I, [2016-02-29T12:39:56.318961 #1112:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher#start) Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]
[----] I, [2016-02-29T12:39:56.974339 #3097:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher::Runner#sync_config) ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c], Zone [default], Active Roles [automate,database_operations,ems_inventory,ems_operations,event,reporting,scheduler,smartstate,user_interface,web_services], Assigned Roles [automate,database_operations,database_owner,ems_inventory,ems_operations,event,reporting,scheduler,smartstate,user_interface,web_services], Configuration:
[----] I, [2016-02-29T12:39:56.978226 #3097:87d994] INFO -- : :count: 1
[----] I, [2016-02-29T12:39:56.978408 #3097:87d994] INFO -- : :gc_interval: 900
[----] I, [2016-02-29T12:39:56.978503 #3097:87d994] INFO -- : :heartbeat_freq: 60
[----] I, [2016-02-29T12:39:56.978635 #3097:87d994] INFO -- : :heartbeat_timeout: 120
[----] I, [2016-02-29T12:39:56.978708 #3097:87d994] INFO -- : :memory_threshold: 2147483648
[----] I, [2016-02-29T12:39:56.978787 #3097:87d994] INFO -- : :nice_delta: 1
[----] I, [2016-02-29T12:39:56.978860 #3097:87d994] INFO -- : :parent_time_threshold: 180
[----] I, [2016-02-29T12:39:56.978959 #3097:87d994] INFO -- : :poll: 1
[----] I, [2016-02-29T12:39:56.979044 #3097:87d994] INFO -- : :poll_escalate_max: 30
[----] I, [2016-02-29T12:39:56.979127 #3097:87d994] INFO -- : :poll_method: :normal
[----] I, [2016-02-29T12:39:56.979202 #3097:87d994] INFO -- : :restart_interval: 0
[----] I, [2016-02-29T12:39:56.979292 #3097:87d994] INFO -- : :starting_timeout: 600
[----] I, [2016-02-29T12:39:56.979380 #3097:87d994] INFO -- : :ems_event_page_size: 100
[----] I, [2016-02-29T12:39:56.979460 #3097:87d994] INFO -- : :ems_event_thread_shutdown_timeout: 10
[----] I, [2016-02-29T12:39:56.979533 #3097:87d994] INFO -- : ---
[----] I, [2016-02-29T12:39:56.980900 #3097:87d994] INFO -- : :guid: 898e624c-dee1-11e5-ac53-02420a01024c
[----] I, [2016-02-29T12:39:56.981016 #3097:87d994] INFO -- : :ems_id: 5
[----] I, [2016-02-29T12:39:56.986975 #3093:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker#log_status) [Refresh Worker for Cloud/Infrastructure Providers: OSE] Worker ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:55 UTC], Process Info: Memory Usage [297304064], Memory Size [561614848], Proportional Set Size: [140775000], Memory % [3.62], CPU Time [24.0], CPU % [0.0], Priority [20]
[----] E, [2016-02-29T12:39:57.005070 #3093:87d994] ERROR -- : EMS [10.3.13.105] as [] ID [23] PID [3093] GUID [88f59666-dee1-11e5-ac53-02420a01024c] EMS id [5] failed authentication check. Worker exiting.
[----] W, [2016-02-29T12:39:57.037259 #3097:87d994] WARN -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager#authentication_check_no_validation) type: [nil] for [5] [OSE] Validation failed: incomplete, Missing credentials
[----] W, [2016-02-29T12:39:57.038174 #3097:87d994] WARN -- : MIQ(AuthToken#validation_failed) [ExtManagementSystem] [5], previously valid on: 2016-02-29 12:39:49 UTC, previous status: [Incomplete]
[----] I, [2016-02-29T12:39:57.141501 #3097:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [435], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_incomplete", {}]
[----] I, [2016-02-29T12:39:57.160852 #3097:87d994] INFO -- : EMS [10.3.13.105] as [] ID [24] PID [3097] GUID [898e624c-dee1-11e5-ac53-02420a01024c] EMS ID [5] failed authentication check. Stopping Event Monitor Thread.
[----] I, [2016-02-29T12:39:57.463246 #3097:87d994] INFO -- : MIQ(ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher#log_status) [Event Monitor for Cloud/Infrastructure Providers: OSE] Worker ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:56 UTC], Process Info: Memory Usage [297295872], Memory Size [561614848], Proportional Set Size: [149560000], Memory % [3.62], CPU Time [32.0], CPU % [0.0], Priority [20]
[----] E, [2016-02-29T12:39:57.463793 #3097:87d994] ERROR -- : EMS [10.3.13.105] as [] ID [24] PID [3097] GUID [898e624c-dee1-11e5-ac53-02420a01024c] EMS ID [5] failed authentication check. Worker exiting.
[----] D, [2016-02-29T12:39:58.201479 #1246:87d994] DEBUG -- : MIQ(MiqGenericWorker::Runner) Garbage collection took 1.7463937190186698 seconds
[----] D, [2016-02-29T12:39:59.306364 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:39:59.306703 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:39:59.308681 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:39:59.324603 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 16 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:39:59.333792 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.009643793106079102, :worker_monitor=>6.631185054779053, :worker_dequeue=>0.02451491355895996, :total_time=>6.665737867355347}
[----] I, [2016-02-29T12:40:00.167110 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [419], MiqWorker id: [4], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>78, :miq_event_id=>78, "EventStream::event_stream"=>78, :event_stream_id=>78}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [10.654925934] seconds
[----] I, [2016-02-29T12:40:00.179916 #1252:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [419], Delivering...
[----] I, [2016-02-29T12:40:00.186135 #1252:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_changed", "MiqEvent::miq_event"=>78, :miq_event_id=>78, "EventStream::event_stream"=>78, :event_stream_id=>78} for object [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.5] with state [] to Automate
[----] I, [2016-02-29T12:40:00.208992 #1252:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=78&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=78&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=78&event_type=ems_auth_changed&miq_event_id=78&object_name=Event&vmdb_object_type=ext_management_system]
[----] I, [2016-02-29T12:40:00.366088 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=78&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=78&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=78&event_type=ems_auth_changed&miq_event_id=78&object_name=Event&vmdb_object_type=ext_management_system ManageIQ/System]
[----] I, [2016-02-29T12:40:00.369911 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [426], MiqWorker id: [5], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [log_status], Command: [MiqServer.log_status], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [5.345937248] seconds
[----] I, [2016-02-29T12:40:00.370192 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqQueue#deliver) Message id: [426], Delivering...
[----] I, [2016-02-29T12:40:00.372229 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] System Status:
[----] I, [2016-02-29T12:40:00.372477 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Active: 5795762176
[----] I, [2016-02-29T12:40:00.372750 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Active(anon): 5750370304
[----] I, [2016-02-29T12:40:00.373175 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Active(file): 45391872
[----] I, [2016-02-29T12:40:00.373320 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] AnonHugePages: 301989888
[----] I, [2016-02-29T12:40:00.373764 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] AnonPages: 5547003904
[----] I, [2016-02-29T12:40:00.374016 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Bounce: 0
[----] I, [2016-02-29T12:40:00.375142 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Buffers: 0
[----] I, [2016-02-29T12:40:00.375313 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Cached: 560742400
[----] I, [2016-02-29T12:40:00.375651 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] CommitLimit: 4101603328
[----] I, [2016-02-29T12:40:00.375886 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Committed_AS: 10380906496
[----] I, [2016-02-29T12:40:00.376372 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] DirectMap1G: 6442450944
[----] I, [2016-02-29T12:40:00.443799 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] DirectMap2M: 2053111808
[----] I, [2016-02-29T12:40:00.443917 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] DirectMap4k: 94359552
[----] I, [2016-02-29T12:40:00.444003 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Dirty: 208896
[----] I, [2016-02-29T12:40:00.444099 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] HardwareCorrupted: 0
[----] I, [2016-02-29T12:40:00.444179 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] HugePages_Free: 0
[----] I, [2016-02-29T12:40:00.444254 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] HugePages_Rsvd: 0
[----] I, [2016-02-29T12:40:00.444343 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] HugePages_Surp: 0
[----] I, [2016-02-29T12:40:00.444440 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] HugePages_Total: 0
[----] I, [2016-02-29T12:40:00.444535 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Hugepagesize: 2097152
[----] I, [2016-02-29T12:40:00.444683 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Inactive: 238837760
[----] I, [2016-02-29T12:40:00.444792 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Inactive(anon): 123637760
[----] I, [2016-02-29T12:40:00.444869 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Inactive(file): 115200000
[----] I, [2016-02-29T12:40:00.444936 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] KernelStack: 7110656
[----] I, [2016-02-29T12:40:00.445000 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Mapped: 56479744
[----] I, [2016-02-29T12:40:00.445066 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] MemAvailable: 1874403328
[----] I, [2016-02-29T12:40:00.445129 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] MemFree: 1856987136
[----] I, [2016-02-29T12:40:00.445191 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] MemTotal: 8203210752
[----] I, [2016-02-29T12:40:00.445254 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Mlocked: 73334784
[----] I, [2016-02-29T12:40:00.445329 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] NFS_Unstable: 0
[----] I, [2016-02-29T12:40:00.445397 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] PageTables: 39620608
[----] I, [2016-02-29T12:40:00.445474 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] SReclaimable: 47222784
[----] I, [2016-02-29T12:40:00.445581 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] SUnreclaim: 60682240
[----] I, [2016-02-29T12:40:00.445656 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Shmem: 386383872
[----] I, [2016-02-29T12:40:00.445735 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Slab: 107905024
[----] I, [2016-02-29T12:40:00.445814 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] SwapCached: 0
[----] I, [2016-02-29T12:40:00.445884 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] SwapFree: 0
[----] I, [2016-02-29T12:40:00.445949 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] SwapTotal: 0
[----] I, [2016-02-29T12:40:00.446014 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Unevictable: 73334784
[----] I, [2016-02-29T12:40:00.446176 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] VmallocChunk: 35184293445632
[----] I, [2016-02-29T12:40:00.446249 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] VmallocTotal: 35184372087808
[----] I, [2016-02-29T12:40:00.446362 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] VmallocUsed: 28127232
[----] I, [2016-02-29T12:40:00.446462 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Writeback: 0
[----] I, [2016-02-29T12:40:00.446589 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] WritebackTmp: 0
[----] I, [2016-02-29T12:40:00.678131 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Disk Usage:
[----] I, [2016-02-29T12:40:00.678425 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] Filesystem Type Total Used Available %Used iTotal iUsed iFree %iUsed Mounted on
[----] I, [2016-02-29T12:40:00.688295 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] rootfs rootfs 99.9 GB 1.2 GB 98.7 GB 2% 104849408 87479 104761929 1% /
[----] I, [2016-02-29T12:40:00.695795 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] tmpfs tmpfs 3.8 GB 0 Bytes 3.8 GB 0% 1001368 3 1001365 1% /dev
[----] I, [2016-02-29T12:40:00.701756 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] shm tmpfs 64 MB 0 Bytes 64 MB 0% 1001368 1 1001367 1% /dev/shm
[----] I, [2016-02-29T12:40:00.716698 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] /dev/vda1 xfs 20 GB 4 GB 16 GB 21% 20970112 49182 20920930 1% /etc/hosts
[----] I, [2016-02-29T12:40:00.752994 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] MiqQueue count for state=["dequeue"] by zone and role: {"default"=>{"automate"=>1, nil=>1}}
[----] I, [2016-02-29T12:40:00.753271 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_system_status) [EVM Server (1112)] MiqQueue count for state=["ready"] by zone and role: {"default"=>{"ems_inventory"=>11, nil=>13, "smartstate"=>1}}
[----] I, [2016-02-29T12:40:00.776801 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqServer.log_status) [EVM Server (1112)] Process info: Memory Usage [297492480], Memory Size [526876672], Proportional Set Size: [255412000], Memory % [3.63], CPU Time [2453.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.777662 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqQueue#delivered) Message id: [426], State: [ok], Delivered in [0.407474452] seconds
[----] I, [2016-02-29T12:40:00.920834 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [427], MiqWorker id: [5], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [log_status], Command: [MiqWorker.log_status_all], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [5.858676316] seconds
[----] I, [2016-02-29T12:40:00.921197 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqQueue#deliver) Message id: [427], Delivering...
[----] I, [2016-02-29T12:40:00.940145 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqScheduleWorker#log_status) [Schedule Worker] Worker ID [8], PID [1270], GUID [36975110-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:08 UTC], Process Info: Memory Usage [292179968], Memory Size [533192704], Proportional Set Size: [233725000], Memory % [3.56], CPU Time [1928.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.959082 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqUiWorker#log_status) [User Interface Worker] Worker ID [9], PID [1280], GUID [3ce4b814-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:36 UTC], Process Info: Memory Usage [333221888], Memory Size [548368384], Proportional Set Size: [303802000], Memory % [4.06], CPU Time [6948.0], CPU % [0.04], Priority [20]
[----] I, [2016-02-29T12:40:00.960592 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqEventHandler#log_status) [Event Handler] Worker ID [1], PID [1238], GUID [2baca958-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:57 UTC], Process Info: Memory Usage [311382016], Memory Size [523718656], Proportional Set Size: [268886000], Memory % [3.8], CPU Time [1214.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.961518 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqGenericWorker#log_status) [Generic Worker] Worker ID [3], PID [1246], GUID [2fa4ca36-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:56 UTC], Process Info: Memory Usage [302592000], Memory Size [523718656], Proportional Set Size: [263400000], Memory % [3.69], CPU Time [2121.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.962635 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqGenericWorker#log_status) [Generic Worker] Worker ID [2], PID [1242], GUID [2f65cc82-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:59 UTC], Process Info: Memory Usage [323567616], Memory Size [526352384], Proportional Set Size: [287284000], Memory % [3.94], CPU Time [2820.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.963795 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqPriorityWorker#log_status) [Priority Worker] Worker ID [4], PID [1252], GUID [30b0f490-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:59 UTC], Process Info: Memory Usage [297496576], Memory Size [526876672], Proportional Set Size: [255115000], Memory % [3.63], CPU Time [2541.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.964611 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqWebServiceWorker#log_status) [Web Services Worker] Worker ID [10], PID [1290], GUID [48d0ab7e-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:45 UTC], Process Info: Memory Usage [300756992], Memory Size [540561408], Proportional Set Size: [235069000], Memory % [3.67], CPU Time [318.0], CPU % [0.0], Priority [20]
[----] I, [2016-02-29T12:40:00.965480 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqPriorityWorker#log_status) [Priority Worker] Worker ID [5], PID [1257], GUID [33a03bf2-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:58 UTC], Process Info: Memory Usage [324567040], Memory Size [528982016], Proportional Set Size: [288754000], Memory % [3.96], CPU Time [2792.0], CPU % [0.01], Priority [20]
[----] I, [2016-02-29T12:40:00.966262 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqReportingWorker#log_status) [Reporting Worker] Worker ID [7], PID [1265], GUID [350dddf0-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:57 UTC], Process Info: Memory Usage [292573184], Memory Size [531087360], Proportional Set Size: [195131000], Memory % [3.57], CPU Time [442.0], CPU % [0.0], Priority [20]
[----] I, [2016-02-29T12:40:00.966898 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqReportingWorker#log_status) [Reporting Worker] Worker ID [6], PID [1261], GUID [34b29f80-dedd-11e5-ac53-02420a01024c], Last Heartbeat [2016-02-29 12:39:58 UTC], Process Info: Memory Usage [292560896], Memory Size [530034688], Proportional Set Size: [195127000], Memory % [3.57], CPU Time [473.0], CPU % [0.0], Priority [20]
[----] I, [2016-02-29T12:40:00.967273 #1257:87d994] INFO -- : Q-task_id([log_status]) MIQ(MiqQueue#delivered) Message id: [427], State: [ok], Delivered in [0.046144835] seconds
[----] I, [2016-02-29T12:40:00.970191 #1252:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_changed#create]
[----] I, [2016-02-29T12:40:01.016824 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [428], MiqWorker id: [5], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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.929700475] seconds
[----] I, [2016-02-29T12:40:01.017139 #1257:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [428], Delivering...
[----] I, [2016-02-29T12:40:01.044588 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_changed#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:01.247237 #1257:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [428], State: [ok], Delivered in [0.230088341] seconds
[----] I, [2016-02-29T12:40:01.595613 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [430], 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: [6.300863147] seconds
[----] I, [2016-02-29T12:40:01.596152 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [430], Delivering...
[----] I, [2016-02-29T12:40:01.622973 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.001184701919555664, :jobs_to_dispatch_count=>0, :total_time=>0.014760971069335938}
[----] I, [2016-02-29T12:40:01.627510 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [430], State: [ok], Delivered in [0.031374159] seconds
[----] I, [2016-02-29T12:40:01.749292 #1252:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/ems_auth_changed] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:01.836202 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [422], MiqWorker id: [3], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Service.retirement_check], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.10827458] seconds
[----] I, [2016-02-29T12:40:01.836721 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [422], Delivering...
[----] I, [2016-02-29T12:40:02.076396 #1252:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:02.089192 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:02.190273 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [423], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Vm.retirement_check], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.398579072] seconds
[----] I, [2016-02-29T12:40:02.199316 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [423], Delivering...
[----] I, [2016-02-29T12:40:02.184259 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:02.249766 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [423], State: [ok], Delivered in [0.050598768] seconds
[----] I, [2016-02-29T12:40:02.291882 #1252:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:02.301981 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::OpenshiftEnterprise::ContainerManager id: 5, name: "OSE", created_on: "2016-02-29 12:39:42", updated_on: "2016-02-29 12:39:42", guid: "817db7f6-dee1-11e5-ac53-02420a01024c", zone_id: 1, type: "ManageIQ::Providers::OpenshiftEnterprise::Containe...", api_version: nil, uid_ems: nil, host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: nil, last_refresh_error: nil, last_refresh_date: nil, provider_id: nil, security_protocol: nil, realm: nil, tenant_id: 1, project: nil>]
[----] I, [2016-02-29T12:40:02.303465 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [424], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [OrchestrationStack.retirement_check], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.457378812] seconds
[----] I, [2016-02-29T12:40:02.303839 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [424], Delivering...
[----] I, [2016-02-29T12:40:02.307995 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_changed]
[----] I, [2016-02-29T12:40:02.319235 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [424], State: [ok], Delivered in [0.015405248] seconds
[----] I, [2016-02-29T12:40:02.365024 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [422], State: [ok], Delivered in [0.52836325] seconds
[----] I, [2016-02-29T12:40:02.381034 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_changed]
[----] I, [2016-02-29T12:40:02.381363 #1252:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_changed] Target: ManageIQ::Providers::OpenshiftEnterprise::ContainerManager Name: [OSE], Id: [5]
[----] I, [2016-02-29T12:40:02.389453 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [425], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.refresh_all_ems_timer], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [7.40952713] seconds
[----] I, [2016-02-29T12:40:02.389794 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [425], Delivering...
[----] I, [2016-02-29T12:40:02.402926 #1252:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:02.403952 #1252:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_changed#create]
[----] I, [2016-02-29T12:40:02.406873 #1252:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [419], State: [ok], Delivered in [2.239424752] seconds
[----] I, [2016-02-29T12:40:02.410244 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [429], MiqWorker id: [3], 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.245122659] seconds
[----] I, [2016-02-29T12:40:02.410863 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [429], Delivering...
[----] D, [2016-02-29T12:40:02.411199 #1246:87d994] DEBUG -- : Checking for timed out jobs
[----] I, [2016-02-29T12:40:02.440803 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [429], State: [ok], Delivered in [0.030086932] seconds
[----] I, [2016-02-29T12:40:02.521096 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [431], MiqWorker id: [3], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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.125839714] seconds
[----] I, [2016-02-29T12:40:02.521488 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [431], Delivering...
[----] D, [2016-02-29T12:40:02.521872 #1246:87d994] DEBUG -- : Checking session data
[----] I, [2016-02-29T12:40:02.522351 #1242:87d994] INFO -- : MIQ(MiqQueue.put_or_update) Message id: [421] updated with following: {:queue_name=>"ems_5", :state=>"ready", :zone=>"default", :class_name=>"EmsRefresh", :method_name=>"refresh", :role=>"ems_inventory", :args=>[[["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5]]], :msg_timeout=>7200, :task_id=>nil}
[----] I, [2016-02-29T12:40:02.530006 #1242:87d994] INFO -- : MIQ(MiqQueue.put_or_update) Message id: [421], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_5], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5]]], Requeued
[----] I, [2016-02-29T12:40:02.530481 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [425], State: [ok], Delivered in [0.140707847] seconds
[----] I, [2016-02-29T12:40:02.540405 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [431], State: [ok], Delivered in [0.018947404] seconds
[----] I, [2016-02-29T12:40:02.606865 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [420], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_valid", {}], Dequeued in: [12.582742831] seconds
[----] I, [2016-02-29T12:40:02.607205 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [420], Delivering...
[----] I, [2016-02-29T12:40:02.610402 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [432], MiqWorker id: [3], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker"}], Dequeued in: [6.755349902] seconds
[----] I, [2016-02-29T12:40:02.610818 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [432], Delivering...
[----] I, [2016-02-29T12:40:02.635721 #1242:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"ems_auth_valid"> inputs=<{"MiqEvent::miq_event"=>79, :miq_event_id=>79, "EventStream::event_stream"=>79, :event_stream_id=>79}>
[----] I, [2016-02-29T12:40:02.648961 #1246:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_start"> inputs=<{:event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker", "MiqEvent::miq_event"=>80, :miq_event_id=>80, "EventStream::event_stream"=>80, :event_stream_id=>80}>
[----] I, [2016-02-29T12:40:02.674162 #1242:87d994] INFO -- : MIQ(User#current_group=) User: [admin] Assigning Role: [EvmRole-tenant_administrator] from Group: [Tenant My Company access]
[----] I, [2016-02-29T12:40:02.768717 #1242:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [436], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_valid", "MiqEvent::miq_event"=>79, :miq_event_id=>79, "EventStream::event_stream"=>79, :event_stream_id=>79}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:40:02.775808 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [420], State: [ok], Delivered in [0.168606236] seconds
[----] I, [2016-02-29T12:40:02.801415 #1246:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [437], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker", "MiqEvent::miq_event"=>80, :miq_event_id=>80, "EventStream::event_stream"=>80, :event_stream_id=>80}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:40:02.813976 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [432], State: [ok], Delivered in [0.202709412] seconds
[----] I, [2016-02-29T12:40:02.861924 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [433], MiqWorker id: [2], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_incomplete", {}], Dequeued in: [6.661021726] seconds
[----] I, [2016-02-29T12:40:02.862249 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [433], Delivering...
[----] I, [2016-02-29T12:40:02.895845 #1242:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"ems_auth_incomplete"> inputs=<{"MiqEvent::miq_event"=>81, :miq_event_id=>81, "EventStream::event_stream"=>81, :event_stream_id=>81}>
[----] I, [2016-02-29T12:40:02.899462 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [434], MiqWorker id: [3], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["MiqServer", 1], "evm_worker_start", {:event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher"}], Dequeued in: [6.640374402] seconds
[----] I, [2016-02-29T12:40:02.899742 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [434], Delivering...
[----] I, [2016-02-29T12:40:02.927877 #1246:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_start"> inputs=<{:event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher", "MiqEvent::miq_event"=>82, :miq_event_id=>82, "EventStream::event_stream"=>82, :event_stream_id=>82}>
[----] I, [2016-02-29T12:40:02.931376 #1242:87d994] INFO -- : MIQ(User#current_group=) User: [admin] Assigning Role: [EvmRole-tenant_administrator] from Group: [Tenant My Company access]
[----] I, [2016-02-29T12:40:02.991117 #1242:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [438], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>81, :miq_event_id=>81, "EventStream::event_stream"=>81, :event_stream_id=>81}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:40:02.996691 #1246:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [439], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher", "MiqEvent::miq_event"=>82, :miq_event_id=>82, "EventStream::event_stream"=>82, :event_stream_id=>82}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:40:02.997223 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [434], State: [ok], Delivered in [0.097483515] seconds
[----] I, [2016-02-29T12:40:02.998400 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [433], State: [ok], Delivered in [0.136063016] seconds
[----] I, [2016-02-29T12:40:03.147410 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [435], MiqWorker id: [3], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqEvent.raise_evm_event], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [["ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", 5], "ems_auth_incomplete", {}], Dequeued in: [6.056434465] seconds
[----] I, [2016-02-29T12:40:03.147848 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [435], Delivering...
[----] I, [2016-02-29T12:40:03.187129 #1246:87d994] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"ems_auth_incomplete"> inputs=<{"MiqEvent::miq_event"=>83, :miq_event_id=>83, "EventStream::event_stream"=>83, :event_stream_id=>83}>
[----] I, [2016-02-29T12:40:03.239363 #1246:87d994] INFO -- : MIQ(User#current_group=) User: [admin] Assigning Role: [EvmRole-tenant_administrator] from Group: [Tenant My Company access]
[----] I, [2016-02-29T12:40:03.310514 #1246:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [440], id: [], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>83, :miq_event_id=>83, "EventStream::event_stream"=>83, :event_stream_id=>83}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}]
[----] I, [2016-02-29T12:40:03.311158 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [435], State: [ok], Delivered in [0.163353797] seconds
[----] I, [2016-02-29T12:40:04.337437 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:40:04 UTC]...
[----] I, [2016-02-29T12:40:04.403064 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:40:04 UTC]...Complete
[----] D, [2016-02-29T12:40:04.447758 #1112:87d994] DEBUG -- : MIQ(MiqServer#monitor_servers_as_master) Checking other servers as master server
[----] D, [2016-02-29T12:40:04.470890 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Acquiring lock on MiqRegion::1...
[----] D, [2016-02-29T12:40:04.474134 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Acquired lock
[----] D, [2016-02-29T12:40:04.824463 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Releasing lock
[----] I, [2016-02-29T12:40:04.876883 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 5 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:40:05.115377 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [436], MiqWorker id: [5], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_valid", "MiqEvent::miq_event"=>79, :miq_event_id=>79, "EventStream::event_stream"=>79, :event_stream_id=>79}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [2.420598471] seconds
[----] I, [2016-02-29T12:40:05.115997 #1257:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [436], Delivering...
[----] I, [2016-02-29T12:40:05.127335 #1257:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_valid", "MiqEvent::miq_event"=>79, :miq_event_id=>79, "EventStream::event_stream"=>79, :event_stream_id=>79} for object [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.5] with state [] to Automate
[----] I, [2016-02-29T12:40:05.564919 #1257:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=79&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=79&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=79&event_type=ems_auth_valid&miq_event_id=79&object_name=Event&vmdb_object_type=ext_management_system]
[----] I, [2016-02-29T12:40:05.632796 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [437], MiqWorker id: [4], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker", "MiqEvent::miq_event"=>80, :miq_event_id=>80, "EventStream::event_stream"=>80, :event_stream_id=>80}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [2.904370844] seconds
[----] I, [2016-02-29T12:40:05.633193 #1252:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [437], Delivering...
[----] I, [2016-02-29T12:40:05.643885 #1252:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [23], PID [3093], GUID [88f59666-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker", "MiqEvent::miq_event"=>80, :miq_event_id=>80, "EventStream::event_stream"=>80, :event_stream_id=>80} for object [MiqServer.1] with state [] to Automate
[----] I, [2016-02-29T12:40:05.699220 #1252:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=80&MiqEvent%3A%3Amiq_event=80&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_details=Worker%20started%3A%20ID%20%5B23%5D%2C%20PID%20%5B3093%5D%2C%20GUID%20%5B88f59666-dee1-11e5-ac53-02420a01024c%5D&event_stream_id=80&event_type=evm_worker_start&miq_event_id=80&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AOpenshiftEnterprise%3A%3AContainerManager%3A%3ARefreshWorker&vmdb_object_type=miq_server]
[----] I, [2016-02-29T12:40:05.776504 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=79&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=79&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=79&event_type=ems_auth_valid&miq_event_id=79&object_name=Event&vmdb_object_type=ext_management_system ManageIQ/System]
[----] I, [2016-02-29T12:40:05.977914 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=80&MiqEvent%3A%3Amiq_event=80&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_details=Worker%20started%3A%20ID%20%5B23%5D%2C%20PID%20%5B3093%5D%2C%20GUID%20%5B88f59666-dee1-11e5-ac53-02420a01024c%5D&event_stream_id=80&event_type=evm_worker_start&miq_event_id=80&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AOpenshiftEnterprise%3A%3AContainerManager%3A%3ARefreshWorker&vmdb_object_type=miq_server ManageIQ/System]
[----] I, [2016-02-29T12:40:06.142752 #1242:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [438], MiqWorker id: [2], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>81, :miq_event_id=>81, "EventStream::event_stream"=>81, :event_stream_id=>81}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [3.194717045] seconds
[----] I, [2016-02-29T12:40:06.143099 #1242:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [438], Delivering...
[----] I, [2016-02-29T12:40:06.160126 #1242:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>81, :miq_event_id=>81, "EventStream::event_stream"=>81, :event_stream_id=>81} for object [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.5] with state [] to Automate
[----] I, [2016-02-29T12:40:06.176722 #1242:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=81&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=81&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=81&event_type=ems_auth_incomplete&miq_event_id=81&object_name=Event&vmdb_object_type=ext_management_system]
[----] I, [2016-02-29T12:40:06.300643 #1242:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=81&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=81&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=81&event_type=ems_auth_incomplete&miq_event_id=81&object_name=Event&vmdb_object_type=ext_management_system ManageIQ/System]
[----] I, [2016-02-29T12:40:06.308690 #1252:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create]
[----] I, [2016-02-29T12:40:06.325728 #1257:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create]
[----] I, [2016-02-29T12:40:06.438191 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:06.442694 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [439], MiqWorker id: [3], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"MiqServer", :object_id=>1, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher", "MiqEvent::miq_event"=>82, :miq_event_id=>82, "EventStream::event_stream"=>82, :event_stream_id=>82}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [3.466212771] seconds
[----] I, [2016-02-29T12:40:06.443068 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [439], Delivering...
[----] I, [2016-02-29T12:40:06.464277 #1246:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [24], PID [3097], GUID [898e624c-dee1-11e5-ac53-02420a01024c]", :type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher", "MiqEvent::miq_event"=>82, :miq_event_id=>82, "EventStream::event_stream"=>82, :event_stream_id=>82} for object [MiqServer.1] with state [] to Automate
[----] I, [2016-02-29T12:40:06.473496 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:06.501521 #1246:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=82&MiqEvent%3A%3Amiq_event=82&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_details=Worker%20started%3A%20ID%20%5B24%5D%2C%20PID%20%5B3097%5D%2C%20GUID%20%5B898e624c-dee1-11e5-ac53-02420a01024c%5D&event_stream_id=82&event_type=evm_worker_start&miq_event_id=82&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AOpenshiftEnterprise%3A%3AContainerManager%3A%3AEventCatcher&vmdb_object_type=miq_server]
[----] I, [2016-02-29T12:40:06.624182 #1257:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/ems_auth_valid] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:06.656637 #1252:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/evm_worker_start] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:06.721207 #1246:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=82&MiqEvent%3A%3Amiq_event=82&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_details=Worker%20started%3A%20ID%20%5B24%5D%2C%20PID%20%5B3097%5D%2C%20GUID%20%5B898e624c-dee1-11e5-ac53-02420a01024c%5D&event_stream_id=82&event_type=evm_worker_start&miq_event_id=82&object_name=Event&type=ManageIQ%3A%3AProviders%3A%3AOpenshiftEnterprise%3A%3AContainerManager%3A%3AEventCatcher&vmdb_object_type=miq_server ManageIQ/System]
[----] I, [2016-02-29T12:40:06.748442 #1257:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:06.777162 #1252:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:06.827512 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:06.863342 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:06.912358 #1242:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create]
[----] I, [2016-02-29T12:40:06.928757 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:06.966888 #1252:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:06.989482 #1257:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:07.010034 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::OpenshiftEnterprise::ContainerManager id: 5, name: "OSE", created_on: "2016-02-29 12:39:42", updated_on: "2016-02-29 12:39:42", guid: "817db7f6-dee1-11e5-ac53-02420a01024c", zone_id: 1, type: "ManageIQ::Providers::OpenshiftEnterprise::Containe...", api_version: nil, uid_ems: nil, host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: nil, last_refresh_error: nil, last_refresh_date: nil, provider_id: nil, security_protocol: nil, realm: nil, tenant_id: 1, project: nil>]
[----] I, [2016-02-29T12:40:07.010647 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_valid]
[----] I, [2016-02-29T12:40:07.024437 #1252:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:07.042171 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<MiqServer id: 1, guid: "8cb17a78-dedb-11e5-91d4-02420a01024c", status: "started", started_on: "2016-02-29 12:08:25", stopped_on: nil, pid: 1112, build: "20160229120718_", percent_memory: 3.96, percent_cpu: 0.01, cpu_time: 2812.0, name: "EVM", capabilities: {:vixDisk=>true, :concurrent_miqproxies=>0}, last_heartbeat: "2016-02-29 12:40:04", os_priority: 20, is_master: true, logo: nil, version: "master", zone_id: 1, upgrade_status: nil, upgrade_message: nil, memory_usage: 324567040, memory_size: 528982016, hostname: "manageiq-deploy-1-3cyz4", ipaddress: "10.1.2.76", drb_uri: "druby://127.0.0.1:42948", mac_address: "02:42:0a:01:02:4c", vm_id: nil, has_active_userinterface: true, has_active_webservices: true, sql_spid: 207, rh_registered: nil, rh_subscribed: nil, last_update_check: nil, updates_available: nil, rhn_mirror: false, log_file_depot_id: nil, proportional_set_size: 288754000>]
[----] I, [2016-02-29T12:40:07.042510 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [evm_worker_start]
[----] I, [2016-02-29T12:40:07.048316 #1242:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:07.086509 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_valid]
[----] I, [2016-02-29T12:40:07.087118 #1257:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_valid] Target: ManageIQ::Providers::OpenshiftEnterprise::ContainerManager Name: [OSE], Id: [5]
[----] I, [2016-02-29T12:40:07.107896 #1257:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.108874 #1257:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create]
[----] I, [2016-02-29T12:40:07.111278 #1257:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [436], State: [ok], Delivered in [1.995280701] seconds
[----] I, [2016-02-29T12:40:07.111498 #1252:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [evm_worker_start]
[----] I, [2016-02-29T12:40:07.111907 #1252:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [evm_worker_start] Target: MiqServer Name: [EVM], Id: [1]
[----] I, [2016-02-29T12:40:07.115069 #1246:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create]
[----] I, [2016-02-29T12:40:07.126825 #1252:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.127817 #1252:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create]
[----] I, [2016-02-29T12:40:07.128953 #1252:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [437], State: [ok], Delivered in [1.495791303] seconds
[----] I, [2016-02-29T12:40:07.135235 #1242:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/ems_auth_incomplete] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:07.172595 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [440], MiqWorker id: [5], Zone: [default], Role: [automate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqAeEngine.deliver], Timeout: [3600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [{:object_type=>"ManageIQ::Providers::OpenshiftEnterprise::ContainerManager", :object_id=>5, :attrs=>{:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>83, :miq_event_id=>83, "EventStream::event_stream"=>83, :event_stream_id=>83}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>1, :tenant_id=>1, :automate_message=>nil}], Dequeued in: [3.910958628] seconds
[----] I, [2016-02-29T12:40:07.173172 #1242:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.173365 #1257:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [440], Delivering...
[----] I, [2016-02-29T12:40:07.183377 #1257:87d994] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_incomplete", "MiqEvent::miq_event"=>83, :miq_event_id=>83, "EventStream::event_stream"=>83, :event_stream_id=>83} for object [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager.5] with state [] to Automate
[----] I, [2016-02-29T12:40:07.188897 #1246:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:07.194756 #1257:87d994] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=83&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=83&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=83&event_type=ems_auth_incomplete&miq_event_id=83&object_name=Event&vmdb_object_type=ext_management_system]
[----] I, [2016-02-29T12:40:07.203499 #1242:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:07.254972 #1242:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:07.266163 #1246:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/evm_worker_start] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:07.280174 #1242:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:07.287182 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=83&ExtManagementSystem%3A%3Aext_management_system=5&MiqEvent%3A%3Amiq_event=83&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&event_stream_id=83&event_type=ems_auth_incomplete&miq_event_id=83&object_name=Event&vmdb_object_type=ext_management_system ManageIQ/System]
[----] I, [2016-02-29T12:40:07.290217 #1242:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::OpenshiftEnterprise::ContainerManager id: 5, name: "OSE", created_on: "2016-02-29 12:39:42", updated_on: "2016-02-29 12:39:42", guid: "817db7f6-dee1-11e5-ac53-02420a01024c", zone_id: 1, type: "ManageIQ::Providers::OpenshiftEnterprise::Containe...", api_version: nil, uid_ems: nil, host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: nil, last_refresh_error: nil, last_refresh_date: nil, provider_id: nil, security_protocol: nil, realm: nil, tenant_id: 1, project: nil>]
[----] I, [2016-02-29T12:40:07.290726 #1242:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_incomplete]
[----] I, [2016-02-29T12:40:07.368537 #1246:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.381281 #1242:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_incomplete]
[----] I, [2016-02-29T12:40:07.384317 #1242:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_incomplete] Target: ManageIQ::Providers::OpenshiftEnterprise::ContainerManager Name: [OSE], Id: [5]
[----] D, [2016-02-29T12:40:07.384404 #1238:87d994] DEBUG -- : MIQ(MiqEventHandler::Runner) Garbage collection took 0.4577778819948435 seconds
[----] I, [2016-02-29T12:40:07.407105 #1246:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:07.408315 #1242:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.409687 #1242:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create]
[----] I, [2016-02-29T12:40:07.410815 #1242:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [438], State: [ok], Delivered in [1.2677526] seconds
[----] I, [2016-02-29T12:40:07.463928 #1246:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:07.501059 #1246:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:07.510697 #1246:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<MiqServer id: 1, guid: "8cb17a78-dedb-11e5-91d4-02420a01024c", status: "started", started_on: "2016-02-29 12:08:25", stopped_on: nil, pid: 1112, build: "20160229120718_", percent_memory: 3.96, percent_cpu: 0.01, cpu_time: 2812.0, name: "EVM", capabilities: {:vixDisk=>true, :concurrent_miqproxies=>0}, last_heartbeat: "2016-02-29 12:40:04", os_priority: 20, is_master: true, logo: nil, version: "master", zone_id: 1, upgrade_status: nil, upgrade_message: nil, memory_usage: 324567040, memory_size: 528982016, hostname: "manageiq-deploy-1-3cyz4", ipaddress: "10.1.2.76", drb_uri: "druby://127.0.0.1:42948", mac_address: "02:42:0a:01:02:4c", vm_id: nil, has_active_userinterface: true, has_active_webservices: true, sql_spid: 207, rh_registered: nil, rh_subscribed: nil, last_update_check: nil, updates_available: nil, rhn_mirror: false, log_file_depot_id: nil, proportional_set_size: 288754000>]
[----] I, [2016-02-29T12:40:07.511103 #1246:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [evm_worker_start]
[----] I, [2016-02-29T12:40:07.553226 #1246:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [evm_worker_start]
[----] I, [2016-02-29T12:40:07.553678 #1246:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [evm_worker_start] Target: MiqServer Name: [EVM], Id: [1]
[----] I, [2016-02-29T12:40:07.554305 #1246:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.555106 #1246:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create]
[----] I, [2016-02-29T12:40:07.556941 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [439], State: [ok], Delivered in [1.113874659] seconds
[----] I, [2016-02-29T12:40:07.559885 #1257:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create]
[----] I, [2016-02-29T12:40:07.625949 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create ManageIQ/System/Event/MiqEvent]
[----] I, [2016-02-29T12:40:07.701527 #1257:87d994] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/ems_auth_incomplete] not found in MiqAeDatastore - trying [.missing]
[----] I, [2016-02-29T12:40:07.782767 #1257:87d994] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.798001 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System]
[----] I, [2016-02-29T12:40:07.874319 #1257:87d994] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System]
[----] I, [2016-02-29T12:40:07.892082 #1257:87d994] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}]
[----] I, [2016-02-29T12:40:07.900048 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::OpenshiftEnterprise::ContainerManager id: 5, name: "OSE", created_on: "2016-02-29 12:39:42", updated_on: "2016-02-29 12:39:42", guid: "817db7f6-dee1-11e5-ac53-02420a01024c", zone_id: 1, type: "ManageIQ::Providers::OpenshiftEnterprise::Containe...", api_version: nil, uid_ems: nil, host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: nil, last_refresh_error: nil, last_refresh_date: nil, provider_id: nil, security_protocol: nil, realm: nil, tenant_id: 1, project: nil>]
[----] I, [2016-02-29T12:40:07.900726 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_incomplete]
[----] I, [2016-02-29T12:40:07.938472 #1257:87d994] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_incomplete]
[----] I, [2016-02-29T12:40:07.938941 #1257:87d994] INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_incomplete] Target: ManageIQ::Providers::OpenshiftEnterprise::ContainerManager Name: [OSE], Id: [5]
[----] I, [2016-02-29T12:40:07.960000 #1257:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create]
[----] I, [2016-02-29T12:40:07.960846 #1257:87d994] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_incomplete#create]
[----] I, [2016-02-29T12:40:07.967071 #1257:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [440], State: [ok], Delivered in [0.793770687] seconds
[----] D, [2016-02-29T12:40:08.126893 #1242:87d994] DEBUG -- : MIQ(MiqGenericWorker::Runner) Garbage collection took 0.6938302549824584 seconds
[----] I, [2016-02-29T12:40:10.515062 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-02-29T12:40:10.554050 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [441], 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: []
[----] D, [2016-02-29T12:40:12.330623 #1270:87d994] DEBUG -- : MIQ(MiqScheduleWorker::Runner) Garbage collection took 1.75458932298352 seconds
[----] I, [2016-02-29T12:40:13.930002 #1112:87d994] INFO -- : MIQ(MiqServer#clean_worker_records) SQL Record for Worker [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::RefreshWorker] with ID: [23], PID: [3093], GUID: [88f59666-dee1-11e5-ac53-02420a01024c], Status: [aborted] is being deleted
[----] I, [2016-02-29T12:40:13.985731 #1112:87d994] INFO -- : MIQ(MiqServer#clean_worker_records) SQL Record for Worker [ManageIQ::Providers::OpenshiftEnterprise::ContainerManager::EventCatcher] with ID: [24], PID: [3097], GUID: [898e624c-dee1-11e5-ac53-02420a01024c], Status: [aborted] is being deleted
[----] D, [2016-02-29T12:40:14.423377 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:40:14.423876 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:40:14.424886 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:40:14.444304 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:40:14.453612 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.04883122444152832, :worker_monitor=>4.44820237159729, :worker_dequeue=>0.028381824493408203, :total_time=>4.525853872299194}
[----] I, [2016-02-29T12:40:14.549067 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [441], 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: [4.010979163] seconds
[----] I, [2016-02-29T12:40:14.549794 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [441], Delivering...
[----] I, [2016-02-29T12:40:14.558377 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.001333475112915039, :jobs_to_dispatch_count=>0, :total_time=>0.008115530014038086}
[----] I, [2016-02-29T12:40:14.558964 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [441], State: [ok], Delivered in [0.009566948] seconds
[----] I, [2016-02-29T12:40:27.333015 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-02-29T12:40:27.548677 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [442], 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-02-29T12:40:27.599584 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [443], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] D, [2016-02-29T12:40:38.295090 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:40:38.295467 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:40:38.296731 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:40:38.307204 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:40:38.310990 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.027560710906982422, :worker_monitor=>8.712215900421143, :worker_dequeue=>0.01397252082824707, :total_time=>8.754135131835938}
[----] I, [2016-02-29T12:40:39.105446 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [442], 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: [11.599522065] seconds
[----] I, [2016-02-29T12:40:39.111220 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [442], Delivering...
[----] I, [2016-02-29T12:40:39.122490 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.0038771629333496094, :jobs_to_dispatch_count=>0, :total_time=>0.010689496994018555}
[----] I, [2016-02-29T12:40:39.125985 #1246:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [442], State: [ok], Delivered in [0.01482247] seconds
[----] I, [2016-02-29T12:40:39.185633 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [443], MiqWorker id: [3], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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: [11.613217023] seconds
[----] I, [2016-02-29T12:40:39.185982 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [443], Delivering...
[----] D, [2016-02-29T12:40:39.186488 #1246:87d994] DEBUG -- : Checking session data
[----] I, [2016-02-29T12:40:39.204878 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [443], State: [ok], Delivered in [0.018895028] seconds
[----] I, [2016-02-29T12:40:42.621725 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-02-29T12:40:42.672433 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [444], 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-02-29T12:40:43.313414 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:40:43 UTC]...
[----] I, [2016-02-29T12:40:43.351294 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:40:43 UTC]...Complete
[----] I, [2016-02-29T12:40:43.419970 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:40:43.470033 #1257:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [444], 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: [0.817474915] seconds
[----] I, [2016-02-29T12:40:43.470347 #1257:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [444], Delivering...
[----] I, [2016-02-29T12:40:43.486834 #1257:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.0016527175903320312, :jobs_to_dispatch_count=>0, :total_time=>0.015924453735351562}
[----] I, [2016-02-29T12:40:43.490228 #1257:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [444], State: [ok], Delivered in [0.019862615] seconds
==> /var/www/miq/vmdb/log/production.log <==
[----] I, [2016-02-29T12:40:48.017151 #1280:2a8a938] INFO -- : Started GET "/api" for 127.0.0.1 at 2016-02-29 12:40:48 +0000
[----] I, [2016-02-29T12:40:48.073519 #1280:2a8a938] INFO -- : Processing by ApiController#show as JSON
[----] I, [2016-02-29T12:40:48.151632 #1280:2a8a938] INFO -- : Completed 200 OK in 78ms (Views: 1.2ms | ActiveRecord: 0.0ms)
==> /var/www/miq/vmdb/log/evm.log <==
[----] I, [2016-02-29T12:40:48.462892 #1112:87d994] INFO -- : MiqServer: local=Y, master=Y, status= started, id=00001, pid=01112, guid=8cb17a78-dedb-11e5-91d4-02420a01024c, name=EVM, zone=default, hostname=manageiq-deploy-1-3cyz4, ipaddress=10.1.2.76, version=master, build=20160229120718_, active roles=automate:database_operations:ems_inventory:ems_operations:event:reporting:scheduler:smartstate:user_interface:web_services
[----] D, [2016-02-29T12:40:50.862616 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:40:50.862948 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:40:50.863728 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:40:50.892501 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.01002192497253418, :log_active_servers=>0.02233409881591797, :worker_monitor=>2.4006271362304688, :worker_dequeue=>0.028486251831054688, :total_time=>2.4619710445404053}
[----] I, [2016-02-29T12:40:57.698809 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 6.
[----] I, [2016-02-29T12:40:57.786907 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [445], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqDbConfig.log_statistics], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:40:57.867466 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [446], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: []
[----] I, [2016-02-29T12:40:57.898696 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [447], 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-02-29T12:40:57.988949 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [448], 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-02-29T12:40:58.004997 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [449], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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-02-29T12:41:01.090248 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 5 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:41:01.182223 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [446], MiqWorker id: [3], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [3.34312788] seconds
[----] I, [2016-02-29T12:41:01.183507 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [446], Delivering...
[----] I, [2016-02-29T12:41:01.344333 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [448], 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.368924765] seconds
[----] I, [2016-02-29T12:41:01.344930 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [448], Delivering...
[----] I, [2016-02-29T12:41:01.777583 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [446], State: [ok], Delivered in [0.594967477] seconds
[----] I, [2016-02-29T12:41:01.824864 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.007203817367553711, :jobs_to_dispatch_count=>0, :total_time=>0.47952985763549805}
[----] I, [2016-02-29T12:41:01.875080 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [448], State: [ok], Delivered in [0.530145575] seconds
[----] I, [2016-02-29T12:41:01.963184 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [445], MiqWorker id: [3], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqDbConfig.log_statistics], Timeout: [600], Priority: [90], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [4.205821573] seconds
[----] I, [2016-02-29T12:41:01.968092 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [445], Delivering...
[----] I, [2016-02-29T12:41:02.237975 #1246:87d994] INFO -- : MIQ(DbConfig.log_activity_statistics) <<-ACTIVITY_STATS_CSV
session_id,xact_start,last_request_start_time,command,task_state,login,application,request_id,net_address,host_name,client_port,wait_time_ms,blocked_by
207,,2016-02-29 12:41:02 UTC,"SELECT id, lock_version, priority, role FROM ""miq_queue"" WHERE ( state = 'ready'
AND (zone IS NULL OR zone = 'default')
AND queue_name = 'reporting'
AND (role IS NULL OR role IN ('automate','database_operations','ems_inventory','ems_operations','event','reporting','scheduler','smartstate','user_interface','web_services'))
AND (server_guid IS NULL OR server_guid = '8cb17a78-dedb-11e5-91d4-02420a01024c')
AND (deliver_on IS NULL OR deliver_on <= '2016-02-29 12:41:01.090801')
AND (priority <= 200)
) ORDER BY ""miq_queue"".""priority"" ASC, ""miq_queue"".""id"" ASC LIMIT $1",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55678,0,
216,,2016-02-29 12:41:01 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55686,0,
217,,2016-02-29 12:41:00 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55687,1,
218,2016-02-29 12:41:03 UTC,2016-02-29 12:41:03 UTC,"SELECT ""pg_stat_activity"".* FROM ""pg_stat_activity"" WHERE ""pg_stat_activity"".""datname"" = $1",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55688,0,
219,,2016-02-29 12:41:02 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55692,0,
220,,2016-02-29 12:41:01 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55693,0,
221,,2016-02-29 12:41:01 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55694,0,
222,,2016-02-29 12:41:00 UTC,SELECT pg_backend_pid(),false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55695,1,
223,,2016-02-29 12:40:59 UTC,"SELECT ""miq_schedules"".* FROM ""miq_schedules"" WHERE (updated_at > '2016-02-29 12:40:42.687042')",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55698,3,
225,,2016-02-29 12:39:44 UTC,"SELECT ""miq_reports"".""id"", ""miq_reports"".""name"", ""miq_reports"".""conditions"" FROM ""miq_reports"" WHERE ""miq_reports"".""db"" = $1 AND ""miq_reports"".""template_type"" = $2 AND (""miq_reports"".""conditions"" IS NOT NULL)",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55702,77,
226,,2016-02-29 12:37:46 UTC,"SELECT ""server_roles"".* FROM ""server_roles"" INNER JOIN ""assigned_server_roles"" ON ""server_roles"".""id"" = ""assigned_server_roles"".""server_role_id"" WHERE ""assigned_server_roles"".""miq_server_id"" = $1",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55704,195,
239,,2016-02-29 12:39:47 UTC,"SELECT 1 AS one FROM ""policy_events"" WHERE (policy_events.ems_id = 5) LIMIT $1",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55715,74,
248,,2016-02-29 12:39:52 UTC,"SELECT 1 AS one FROM ""ext_management_systems"" WHERE ""ext_management_systems"".""type"" IN ('ManageIQ::Providers::ContainerManager', 'ManageIQ::Providers::Atomic::ContainerManager', 'ManageIQ::Providers::AtomicEnterprise::ContainerManager', 'ManageIQ::Providers::Kubernetes::ContainerManager', 'ManageIQ::Providers::Openshift::ContainerManager', 'ManageIQ::Providers::OpenshiftEnterprise::ContainerManager') AND ""ext_management_systems"".""id"" = $1 LIMIT $2",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55745,69,
255,,2016-02-29 12:39:43 UTC,"SELECT ""configurations"".""updated_on"" FROM ""configurations"" WHERE ""configurations"".""miq_server_id"" = $1 AND ""configurations"".""typ"" = $2 ORDER BY ""configurations"".""id"" ASC LIMIT $3",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55766,78,
256,,2016-02-29 12:40:49 UTC,"SELECT ""miq_groups"".""description"" FROM ""miq_groups"" INNER JOIN ""miq_groups_users"" ON ""miq_groups"".""id"" = ""miq_groups_users"".""miq_group_id"" WHERE ""miq_groups_users"".""user_id"" = $1",false,postgres,/var/www/miq/vmdb/lib/workers/bin/evm_server.rb,10,10.1.2.1,,55768,13,
ACTIVITY_STATS_CSV
[----] I, [2016-02-29T12:41:02.239472 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [445], State: [ok], Delivered in [0.275930861] seconds
[----] I, [2016-02-29T12:41:02.283998 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [447], MiqWorker id: [3], 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: [4.394663154] seconds
[----] I, [2016-02-29T12:41:02.284296 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [447], Delivering...
[----] D, [2016-02-29T12:41:02.287322 #1246:87d994] DEBUG -- : Checking for timed out jobs
[----] I, [2016-02-29T12:41:02.309699 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [447], State: [ok], Delivered in [0.025399138] seconds
[----] I, [2016-02-29T12:41:02.373372 #1246:87d994] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [449], MiqWorker id: [3], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], 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: [4.375792909] seconds
[----] I, [2016-02-29T12:41:02.373747 #1246:87d994] INFO -- : MIQ(MiqQueue#deliver) Message id: [449], Delivering...
[----] D, [2016-02-29T12:41:02.374135 #1246:87d994] DEBUG -- : Checking session data
[----] I, [2016-02-29T12:41:02.464730 #1246:87d994] INFO -- : MIQ(MiqQueue#delivered) Message id: [449], State: [ok], Delivered in [0.090967396] seconds
[----] D, [2016-02-29T12:41:06.138156 #1112:87d994] DEBUG -- : MIQ(MiqServer#monitor_servers_as_master) Checking other servers as master server
[----] D, [2016-02-29T12:41:06.152316 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Acquiring lock on MiqRegion::1...
[----] D, [2016-02-29T12:41:06.156588 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Acquired lock
[----] D, [2016-02-29T12:41:06.423652 #1112:87d994] DEBUG -- : MIQ(MiqRegion#lock) Releasing lock
[----] D, [2016-02-29T12:41:08.697211 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:41:08.697456 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:41:08.698270 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:41:08.732162 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.006671905517578125, :server_monitor=>0.3001441955566406, :worker_monitor=>2.2703208923339844, :worker_dequeue=>0.0335996150970459, :total_time=>2.6112804412841797}
[----] I, [2016-02-29T12:41:13.053857 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1.
[----] I, [2016-02-29T12:41:13.080404 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [450], 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-02-29T12:41:13.732955 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:41:13 UTC]...
[----] I, [2016-02-29T12:41:13.826271 #1112:87d994] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2016-02-29 12:41:13 UTC]...Complete
[----] I, [2016-02-29T12:41:13.856802 #1112:87d994] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200
[----] I, [2016-02-29T12:41:14.198975 #1252:87d994] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [450], 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: [1.128452986] seconds
[----] I, [2016-02-29T12:41:14.199314 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [450], Delivering...
[----] I, [2016-02-29T12:41:14.207202 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_jobs=>0.0016591548919677734, :jobs_to_dispatch_count=>0, :total_time=>0.007410764694213867}
[----] I, [2016-02-29T12:41:14.207943 #1252:87d994] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [450], State: [ok], Delivered in [0.008638262] seconds
[----] D, [2016-02-29T12:41:26.368113 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Invoke algorithm started with options: [{:name=>:used_swap_percent_gt_value, :value=>80, :type=>:kill}]
[----] D, [2016-02-29T12:41:26.374275 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value]
[----] D, [2016-02-29T12:41:26.375296 #1112:87d994] DEBUG -- : MIQ(MiqServer#invoke_algorithm) Executing [kill] algorithm: [used_swap_percent_gt_value] completed with result: [false]
[----] I, [2016-02-29T12:41:26.405734 #1112:87d994] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.009991884231567383, :worker_monitor=>2.4450061321258545, :worker_dequeue=>0.030101537704467773, :total_time=>2.485441207885742}
[----] I, [2016-02-29T12:41:28.106771 #1270:87d994] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2.
[----] I, [2016-02-29T12:41:28.134294 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [451], 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-02-29T12:41:28.152221 #1270:87d994] INFO -- : MIQ(MiqQueue.put) Message id: [452], id: [], Zone: [default], Role: [], Server: [8cb17a78-dedb-11e5-91d4-02420a01024c], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: []
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment