Fedora Account System
Red Hat Associate
Red Hat Customer
Description of problem: Enabling the backup service fails on UI with the error Unable to create backup for Cloud Volume "qqq": uninitialized Invalid backup: No backups available to do an incremental backup.\", \"code\": 400}}" Version-Release number of selected component (if applicable): 5.8.0.14 How reproducible: 100 % Steps to Reproduce: 1.create a cloud volume 2. enable for the first time the cinder backup service 3. navigate to created volume, click on configuration, backup this cloud volume... 4. fill the form of backup name 'qqq' volume. do not check the incremental backup Actual results: Expected results: Unable to create backup for Cloud Volume "qqq": uninitialized Additional info: ---] I, [2017-05-17T09:55:32.345321 #15269:1025138] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2017-05-17T09:55:32.363346 #15278:1025138] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 2. [----] I, [2017-05-17T09:55:32.372522 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System] [----] I, [2017-05-17T09:55:32.403241 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System] [----] I, [2017-05-17T09:55:32.424306 #15269:1025138] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}] [----] I, [2017-05-17T09:55:32.432311 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<MiqServer id: 45000000000001, guid: "ba34e092-38a4-11e7-84df-525400950748", status: "started", started_on: "2017-05-14 12:58:22", stopped_on: nil, pid: 12246, build: "20170509175238_5dbf87a", percent_memory: 4.02, percent_cpu: 1.29, cpu_time: 299259.0, name: "EVM", capabilities: {:vixDisk=>true, :concurrent_miqproxies=>2}, last_heartbeat: "2017-05-17 13:55:20", os_priority: 21, is_master: true, logo: nil, version: "5.8.0.14-rc3", zone_id: 45000000000001, upgrade_status: nil, upgrade_message: nil, memory_usage: 372686848, memory_size: 730771456, hostname: nil, ipaddress: "10.0.0.8", drb_uri: "druby://127.0.0.1:45809", mac_address: "52:54:00:95:07:48", vm_id: nil, has_active_userinterface: true, has_active_webservices: true, sql_spid: 12253, rh_registered: nil, rh_subscribed: nil, last_update_check: nil, updates_available: nil, rhn_mirror: false, log_file_depot_id: nil, proportional_set_size: 322826000, has_active_websocket: true, system_memory_free: 166711296, system_memory_used: 9093283840, system_swap_free: 5200330752, system_swap_used: 4996018176>] [----] I, [2017-05-17T09:55:32.432585 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [evm_worker_start] [----] I, [2017-05-17T09:55:32.448333 #15278:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088212], 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, [2017-05-17T09:55:32.471606 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [evm_worker_start] [----] I, [2017-05-17T09:55:32.471926 #15269:1025138] INFO -- : MIQ(MiqAlert.evaluate_alerts) [evm_worker_start] Target: MiqServer Name: [EVM], Id: [45000000000001] [----] I, [2017-05-17T09:55:32.472425 #15269:1025138] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2017-05-17T09:55:32.472922 #15269:1025138] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/evm_worker_start#create] [----] I, [2017-05-17T09:55:32.473648 #15269:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088205], State: [ok], Delivered in [0.519305264] seconds [----] I, [2017-05-17T09:55:32.504267 #15278:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088213], id: [], Zone: [default], Role: [], Server: [ba34e092-38a4-11e7-84df-525400950748], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [Session.check_session_timeout], Timeout: [600], Priority: [90], State: [ready], Deliver On: [], Data: [], Args: [] [----] I, [2017-05-17T09:55:33.567769 #14439:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager::EventCatcher::Runner#queue_event) EMS [10.0.0.101] as [admin] Caught event [compute.libvirt.error] [----] I, [2017-05-17T09:55:33.602064 #14439:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088214], id: [], Zone: [default], Role: [event], Server: [], Ident: [ems], Target id: [45000000000005], Instance id: [], Task id: [], Command: [EmsEvent.add], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [{:event_type=>"compute.libvirt.error", :source=>"OPENSTACK", :message=>nil, :timestamp=>"2017-05-17T13:55:09.169000", :username=>nil, :full_data=>{:content=>{"message_id"=>"5f5b277a-ed00-4131-b053-643419d2acf6", "event_type"=>"compute.libvirt.error", "timestamp"=>"2017-05-17T13:55:09.169000", "payload"=>{"service"=>"compute.compute-1.localdomain", "request_id"=>"req-a1b40da1-06e5-4711-a5be-621edaddc341"}}, :context=>{}, :user_id=>nil, :priority=>nil, :content_type=>nil}, :ems_id=>45000000000005}] [----] I, [2017-05-17T09:55:34.759569 #14463:1224a74] INFO -- : Querying OpenStack for events newer than 2017-05-17T13:55:18.562000... [----] I, [2017-05-17T09:55:36.157633 #14439:1223368] INFO -- : Querying OpenStack for events newer than 2017-05-17T13:55:19.793000... [fog][WARNING] Unrecognized arguments: provider [fog][WARNING] Unrecognized arguments: provider [----] I, [2017-05-17T09:55:41.772922 #14455:1225b7c] INFO -- : Querying OpenStack for events newer than 2017-05-16T13:54:12.757913... [fog][WARNING] Unrecognized arguments: provider [fog][WARNING] Unrecognized arguments: provider [----] I, [2017-05-17T09:55:44.670139 #12246:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher.sync_workers) Workers are being synchronized: Current: [], Desired: ["ems_45000000000003"] [----] I, [2017-05-17T09:55:44.740522 #15335:177891c] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088215], id: [], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [45000000000001], Task id: [], Command: [ManageIQ::Providers::Openstack::CloudManager::CloudVolume.backup_create], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [{:name=>"ttt", :incremental=>true, :task_id=>45000000001947}] [----] I, [2017-05-17T09:55:44.740692 #15335:177891c] INFO -- : MIQ(MiqTask.generic_action_with_callback) Task: [45000000001947] Queued the action: [creating Cloud Volume Backup for user admin] being run for user: [admin] [----] I, [2017-05-17T09:55:44.756092 #12246:1025138] INFO -- : :kill_algorithm: [----] I, [2017-05-17T09:55:44.756231 #12246:1025138] INFO -- : :name: :used_swap_percent_gt_value [----] I, [2017-05-17T09:55:44.756292 #12246:1025138] INFO -- : :value: 80 [----] I, [2017-05-17T09:55:44.756329 #12246:1025138] INFO -- : :miq_server_time_threshold: 120 [----] I, [2017-05-17T09:55:44.756420 #12246:1025138] INFO -- : :nice_delta: 1 [----] I, [2017-05-17T09:55:44.756578 #12246:1025138] INFO -- : :poll: 2 [----] I, [2017-05-17T09:55:44.756660 #12246:1025138] INFO -- : :start_algorithm: [----] I, [2017-05-17T09:55:44.756695 #12246:1025138] INFO -- : :name: :used_swap_percent_lt_value [----] I, [2017-05-17T09:55:44.756724 #12246:1025138] INFO -- : :value: 60 [----] I, [2017-05-17T09:55:44.756749 #12246:1025138] INFO -- : :sync_interval: 1800 [----] I, [2017-05-17T09:55:44.756775 #12246:1025138] INFO -- : :wait_for_started_timeout: 600 [----] I, [2017-05-17T09:55:45.031061 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher.close_pg_sockets_inherited_from_parent) Closing socket: 24 [----] I, [2017-05-17T09:55:45.142332 #12246:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088216], 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", 45000000000001], "evm_worker_start", {:event_details=>"Worker started: ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748]", :type=>"ManageIQ::Providers::StorageManager::CinderManager::EventCatcher"}] [----] I, [2017-05-17T09:55:45.142651 #12246:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher#start) Worker started: ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748] [----] I, [2017-05-17T09:55:45.664314 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#sync_config) ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748], Zone [default], Active Roles [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,reporting,scheduler,smartproxy,smartstate,user_interface,web_services,websocket], Assigned Roles [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,reporting,scheduler,smartproxy,smartstate,user_interface,web_services,websocket], Configuration: [----] I, [2017-05-17T09:55:45.665574 #24742:1025138] INFO -- : :count: 1 [----] I, [2017-05-17T09:55:45.665681 #24742:1025138] INFO -- : :gc_interval: 900 [----] I, [2017-05-17T09:55:45.665744 #24742:1025138] INFO -- : :heartbeat_freq: 10 [----] I, [2017-05-17T09:55:45.665806 #24742:1025138] INFO -- : :heartbeat_timeout: 120 [----] I, [2017-05-17T09:55:45.665863 #24742:1025138] INFO -- : :memory_threshold: 2147483648 [----] I, [2017-05-17T09:55:45.665923 #24742:1025138] INFO -- : :nice_delta: 1 [----] I, [2017-05-17T09:55:45.666013 #24742:1025138] INFO -- : :parent_time_threshold: 180 [----] I, [2017-05-17T09:55:45.666081 #24742:1025138] INFO -- : :poll: 10 [----] I, [2017-05-17T09:55:45.666145 #24742:1025138] INFO -- : :poll_escalate_max: 30 [----] I, [2017-05-17T09:55:45.666205 #24742:1025138] INFO -- : :poll_method: :normal [----] I, [2017-05-17T09:55:45.666267 #24742:1025138] INFO -- : :restart_interval: 0 [----] I, [2017-05-17T09:55:45.666326 #24742:1025138] INFO -- : :starting_timeout: 600 [----] I, [2017-05-17T09:55:45.666390 #24742:1025138] INFO -- : :stopping_timeout: 600 [----] I, [2017-05-17T09:55:45.666456 #24742:1025138] INFO -- : :flooding_events_per_minute: 30 [----] I, [2017-05-17T09:55:45.666521 #24742:1025138] INFO -- : :flooding_monitor_enabled: false [----] I, [2017-05-17T09:55:45.666581 #24742:1025138] INFO -- : :ems_event_page_size: 100 [----] I, [2017-05-17T09:55:45.666656 #24742:1025138] INFO -- : :ems_event_thread_shutdown_timeout: 10 [----] I, [2017-05-17T09:55:45.666710 #24742:1025138] INFO -- : --- [----] I, [2017-05-17T09:55:45.667285 #24742:1025138] INFO -- : :guid: 85bd16ca-3b08-11e7-a51d-525400950748 [----] I, [2017-05-17T09:55:45.667366 #24742:1025138] INFO -- : :ems_id: 45000000000003 [----] I, [2017-05-17T09:55:45.686082 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Openstack::CloudManager: [oc_ci] [----] I, [2017-05-17T09:55:47.344061 #12246:1025138] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 7 miq_queue rows for queue_name=generic, wcount=4, priority=200 [----] I, [2017-05-17T09:55:47.346481 #12246:1025138] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems, wcount=1, priority=200 [----] I, [2017-05-17T09:55:47.362935 #12246:1025138] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems_45000000000006, wcount=2, priority=200 [----] I, [2017-05-17T09:55:47.367069 #12246:1025138] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems_45000000000003, wcount=1, priority=200 [----] I, [2017-05-17T09:55:47.369304 #12246:1025138] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems_45000000000004, wcount=1, priority=200 [----] I, [2017-05-17T09:55:47.371152 #12246:1025138] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.0037550926208496094, :worker_monitor=>10.799628496170044, :worker_dequeue=>0.030600547790527344, :total_time=>10.834354639053345} [----] I, [2017-05-17T09:55:47.556075 #15278:1025138] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 4. [----] I, [2017-05-17T09:55:47.605277 #15278:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088217], id: [], Zone: [default], Role: [], Server: [ba34e092-38a4-11e7-84df-525400950748], Ident: [generic], Target id: [], Instance id: [], Task id: [], Command: [MiqServer.status_update], Timeout: [600], Priority: [20], State: [ready], Deliver On: [], Data: [], Args: [] [----] I, [2017-05-17T09:55:47.637635 #15278:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088218], 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, [2017-05-17T09:55:47.668144 #15269:1025138] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [45000000088210], MiqWorker id: [45000000000004], 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::Openstack::CloudManager", :object_id=>45000000000005, :attrs=>{:event_type=>"ems_auth_valid", "MiqEvent::miq_event"=>45000000018115, :miq_event_id=>45000000018115, "EventStream::event_stream"=>45000000018115, :event_stream_id=>45000000018115}, :instance_name=>"Event", :user_id=>45000000000001, :miq_group_id=>45000000000001, :tenant_id=>45000000000001, :automate_message=>nil}], Dequeued in: [15.539719082] seconds [----] I, [2017-05-17T09:55:47.668301 #15269:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088210], Delivering... [----] I, [2017-05-17T09:55:47.671177 #15269:1025138] INFO -- : MIQ(MiqAeEngine.deliver) Delivering {:event_type=>"ems_auth_valid", "MiqEvent::miq_event"=>45000000018115, :miq_event_id=>45000000018115, "EventStream::event_stream"=>45000000018115, :event_stream_id=>45000000018115} for object [ManageIQ::Providers::Openstack::CloudManager.45000000000005] with state [] to Automate [----] I, [2017-05-17T09:55:47.722118 #15269:1025138] INFO -- : <AutomationEngine> Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=45000000018115&ExtManagementSystem%3A%3Aext_management_system=45000000000005&MiqEvent%3A%3Amiq_event=45000000018115&MiqServer%3A%3Amiq_server=45000000000001&User%3A%3Auser=45000000000001&event_stream_id=45000000018115&event_type=ems_auth_valid&miq_event_id=45000000018115&object_name=Event&vmdb_object_type=ext_management_system] [----] I, [2017-05-17T09:55:47.824465 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=45000000018115&ExtManagementSystem%3A%3Aext_management_system=45000000000005&MiqEvent%3A%3Amiq_event=45000000018115&MiqServer%3A%3Amiq_server=45000000000001&User%3A%3Auser=45000000000001&event_stream_id=45000000018115&event_type=ems_auth_valid&miq_event_id=45000000018115&object_name=Event&vmdb_object_type=ext_management_system ManageIQ/System] [----] I, [2017-05-17T09:55:47.882493 #15259:1025138] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [45000000088212], MiqWorker id: [45000000000003], 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: [15.451796433] seconds [----] I, [2017-05-17T09:55:47.882786 #15259:1025138] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [45000000088212], Delivering... [----] I, [2017-05-17T09:55:47.945322 #24742:1025138] INFO -- : MIQ(AuthUseridPassword#validation_successful) [ExtManagementSystem] [45000000000005], previously valid/invalid on: [2017-05-17 13:55:16 UTC]/[], previous status: [Valid] [----] I, [2017-05-17T09:55:47.978609 #24742:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088219], 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::Openstack::CloudManager", 45000000000005], "ems_auth_valid", {}] [----] I, [2017-05-17T09:55:47.988572 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#after_initialize) EMS [10.0.0.101] as [admin] Event Catcher skipping the following events: [----] I, [2017-05-17T09:55:48.094058 #15269:1025138] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create] [----] I, [2017-05-17T09:55:48.273795 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create ManageIQ/System/Event/MiqEvent] [----] I, [2017-05-17T09:55:48.304732 #15269:1025138] INFO -- : <AutomationEngine> Instance [/ManageIQ/System/Event/MiqEvent/POLICY/ems_auth_valid] not found in MiqAeDatastore - trying [.missing] [----] I, [2017-05-17T09:55:48.327175 #15269:1025138] INFO -- : <AutomationEngine> Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2017-05-17T09:55:48.334290 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System] [----] I, [2017-05-17T09:55:48.337428 #15259:1025138] INFO -- : Q-task_id([job_dispatcher]) MIQ(JobProxyDispatcher#dispatch) Complete - Timings: {:pending_container_jobs=>0.2573580741882324, :container_jobs_to_dispatch_count=>0, :container_dispatching=>0.2717452049255371, :pending_vm_jobs=>0.12109732627868652, :vm_jobs_to_dispatch_count=>0, :total_time=>0.44910097122192383} [----] I, [2017-05-17T09:55:48.341563 #15259:1025138] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [45000000088212], State: [ok], Delivered in [0.457179832] seconds [----] I, [2017-05-17T09:55:48.358434 #15269:1025138] INFO -- : <AutomationEngine> Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System] [----] I, [2017-05-17T09:55:48.373274 #15269:1025138] INFO -- : <AutomationEngine> Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}] [----] I, [2017-05-17T09:55:48.384389 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) target = [#<ManageIQ::Providers::Openstack::CloudManager id: 45000000000005, name: "oc_ci", created_on: "2017-05-14 13:09:03", updated_on: "2017-05-17 13:55:32", guid: "809ca21e-38a6-11e7-a51d-525400950748", zone_id: 45000000000001, type: "ManageIQ::Providers::Openstack::CloudManager", api_version: "v2", uid_ems: nil, host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: "", last_refresh_error: nil, last_refresh_date: "2017-05-17 13:55:32", provider_id: 45000000000001, realm: nil, tenant_id: 45000000000001, project: nil, parent_ems_id: nil, subscription: nil, last_metrics_error: nil, last_metrics_update_date: nil, last_metrics_success_date: nil, tenant_mapping_enabled: true>] [----] I, [2017-05-17T09:55:48.384949 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) Event Raised [ems_auth_valid] [----] I, [2017-05-17T09:55:48.402611 #15269:1025138] INFO -- : MIQ(MiqEvent#process_evm_event) Alert for Event [ems_auth_valid] [----] I, [2017-05-17T09:55:48.402922 #15269:1025138] INFO -- : MIQ(MiqAlert.evaluate_alerts) [ems_auth_valid] Target: ManageIQ::Providers::Openstack::CloudManager Name: [oc_ci], Id: [45000000000005] [----] I, [2017-05-17T09:55:48.404270 #15269:1025138] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2017-05-17T09:55:48.405324 #15269:1025138] INFO -- : <AutomationEngine> Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/ems_auth_valid#create] [----] I, [2017-05-17T09:55:48.406294 #15269:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088210], State: [ok], Delivered in [0.737986927] seconds [----] I, [2017-05-17T09:55:48.611036 #24742:1025138] INFO -- : ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner started. ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748], Zone [default], Role [automate,database_operations,database_owner,ems_inventory,ems_metrics_collector,ems_metrics_coordinator,ems_metrics_processor,ems_operations,event,reporting,scheduler,smartproxy,smartstate,user_interface,web_services,websocket] [----] I, [2017-05-17T09:55:48.611192 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#do_wait_for_worker_monitor) EMS [10.0.0.101] as [admin] Checking that worker monitor has started before doing work [----] I, [2017-05-17T09:55:48.617363 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#do_wait_for_worker_monitor) EMS [10.0.0.101] as [admin] Starting work since worker monitor has started [----] I, [2017-05-17T09:55:48.617890 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#start_event_monitor) EMS [10.0.0.101] as [admin] Validating Connection/Credentials [----] I, [2017-05-17T09:55:48.618299 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Openstack::CloudManager: [oc_ci] [----] I, [2017-05-17T09:55:48.630505 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#start_event_monitor) EMS [10.0.0.101] as [admin] Starting Event Monitor Thread [----] I, [2017-05-17T09:55:48.633023 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#start_event_monitor) EMS [10.0.0.101] as [admin] Started Event Monitor Thread [----] I, [2017-05-17T09:55:48.637414 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#worker_monitor_drb) EMS [10.0.0.101] as [admin] Initializing DRb Connection to MiqServer with ID=[45000000000001], NAME=[EVM], PID=[12246], GUID=[ba34e092-38a4-11e7-84df-525400950748] DRb URI=[druby://127.0.0.1:45809] [----] I, [2017-05-17T09:55:48.643314 #24742:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::EventCatcher::Runner#do_work) EMS [10.0.0.101] as [admin] Waiting for the Monitor Thread to exit... [----] I, [2017-05-17T09:55:48.775334 #22195:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::RefreshWorker::Runner#get_message_via_drb) Message id: [45000000088208], MiqWorker id: [45000000007729], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_45000000000003], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::StorageManager::CinderManager", 45000000000003]]], Dequeued in: [16.776270104] seconds [----] I, [2017-05-17T09:55:48.777042 #22195:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088208], Delivering... [----] I, [2017-05-17T09:55:48.825609 #22195:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::Refresher#refresh) Refreshing all targets... [----] I, [2017-05-17T09:55:48.826629 #22195:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::Refresher#refresh) EMS: [oc_ci Cinder Manager], id: [45000000000003] Refreshing targets for EMS... [----] I, [2017-05-17T09:55:48.827231 #22195:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::Refresher#refresh) EMS: [oc_ci Cinder Manager], id: [45000000000003] ManageIQ::Providers::StorageManager::CinderManager [oc_ci Cinder Manager] id [45000000000003] [----] I, [2017-05-17T09:55:48.914212 #22195:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::CinderManager::Refresher#refresh_targets_for_ems) EMS: [oc_ci Cinder Manager], id: [45000000000003] Refreshing target ManageIQ::Providers::StorageManager::CinderManager [oc_ci Cinder Manager] id [45000000000003]... [----] I, [2017-05-17T09:55:49.027249 #15242:1025138] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [45000000088213], MiqWorker id: [45000000000001], Zone: [default], Role: [], Server: [ba34e092-38a4-11e7-84df-525400950748], 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: [16.54065749] seconds [----] I, [2017-05-17T09:55:49.027442 #15242:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088213], Delivering... [----] I, [2017-05-17T09:55:49.030424 #15242:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088213], State: [ok], Delivered in [0.00299053] seconds [----] I, [2017-05-17T09:55:49.044508 #15242:1025138] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [45000000087814], MiqWorker id: [45000000000001], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [45000000000010], Task id: [], Command: [ManageIQ::Providers::Openstack::CloudManager::Vm.raw_resize_finish], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [2017-05-17 13:55:40 UTC], Data: [], Args: [], Dequeued in: [908.073496041] seconds [----] I, [2017-05-17T09:55:49.044681 #15242:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000087814], Delivering... [----] I, [2017-05-17T09:55:49.075507 #15242:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088220], id: [], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_45000000000005], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::Openstack::CloudManager::Vm", 45000000000010]]] [----] I, [2017-05-17T09:55:49.084460 #15242:1025138] INFO -- : MIQ(MiqQueue#unget) Message id: [45000000087814], id: [], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [45000000000010], Task id: [], Command: [ManageIQ::Providers::Openstack::CloudManager::Vm.raw_resize_finish], Timeout: [600], Priority: [100], State: [ready], Deliver On: [2017-05-17 13:56:49 UTC], Data: [], Args: [], Requeued [----] E, [2017-05-17T09:55:49.084613 #15242:1025138] ERROR -- : MIQ(MiqQueue#deliver) Message id: [45000000087814], Message not processed. Retrying at 2017-05-17 13:56:49 UTC [----] I, [2017-05-17T09:55:49.095314 #15242:1025138] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [45000000088211], MiqWorker id: [45000000000001], Zone: [default], Role: [], Server: [], Ident: [generic], Target id: [], Instance id: [45000000000005], Task id: [], Command: [ManageIQ::Providers::Openstack::CloudManager.sync_cloud_tenants_with_tenants], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [], Dequeued in: [16.80608298] seconds [----] I, [2017-05-17T09:55:49.095480 #15242:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088211], Delivering... [----] I, [2017-05-17T09:55:49.110616 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) Syncing CloudTenant with Tenants... [----] I, [2017-05-17T09:55:49.116154 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant admin has tenant admin [----] I, [2017-05-17T09:55:49.116328 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) Updating Tenant admin with parameters: {:name=>"admin", :description=>"admin tenant"} [----] I, [2017-05-17T09:55:49.197438 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant admin saved [----] I, [2017-05-17T09:55:49.204032 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant my_osp_tenant has tenant my_osp_tenant [----] I, [2017-05-17T09:55:49.204225 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) Updating Tenant my_osp_tenant with parameters: {:name=>"my_osp_tenant", :description=>"A tenant created by OSP CLI"} [----] I, [2017-05-17T09:55:49.228152 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant my_osp_tenant saved [----] I, [2017-05-17T09:55:49.234407 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant sasasasas has tenant sasasasas [----] I, [2017-05-17T09:55:49.234537 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) Updating Tenant sasasasas with parameters: {:name=>"sasasasas", :description=>"sasasasas"} [----] I, [2017-05-17T09:55:49.244585 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant sasasasas saved [----] I, [2017-05-17T09:55:49.249864 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant גדשדג1שדגasdas has tenant גדשדג1שדגasdas [----] I, [2017-05-17T09:55:49.250019 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) Updating Tenant גדשדג1שדגasdas with parameters: {:name=>"גדשדג1שדגasdas", :description=>"גדשדג1שדגasdas"} [----] I, [2017-05-17T09:55:49.259213 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#sync_tenants) CloudTenant גדשדג1שדגasdas saved [----] I, [2017-05-17T09:55:49.275055 #15242:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088211], State: [ok], Delivered in [0.179539695] seconds [----] I, [2017-05-17T09:55:49.292603 #15242:1025138] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [45000000088215], MiqWorker id: [45000000000001], Zone: [default], Role: [ems_operations], Server: [], Ident: [generic], Target id: [], Instance id: [45000000000001], Task id: [], Command: [ManageIQ::Providers::Openstack::CloudManager::CloudVolume.backup_create], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [{:name=>"ttt", :incremental=>true, :task_id=>45000000001947}], Dequeued in: [4.564337246] seconds [----] I, [2017-05-17T09:55:49.292797 #15242:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088215], Delivering... [----] I, [2017-05-17T09:55:49.305056 #15242:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::CloudManager#with_provider_connection) Connecting through ManageIQ::Providers::Openstack::CloudManager: [oc_ci] [----] I, [2017-05-17T09:55:49.895512 #15298:1025138] INFO -- : MIQ(MiqEventHandler::Runner#get_message_via_drb) Message id: [45000000088214], MiqWorker id: [45000000000006], Zone: [default], Role: [event], Server: [], Ident: [ems], Target id: [45000000000005], Instance id: [], Task id: [], Command: [EmsEvent.add], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [{:event_type=>"compute.libvirt.error", :source=>"OPENSTACK", :message=>nil, :timestamp=>"2017-05-17T13:55:09.169000", :username=>nil, :full_data=>{:content=>{"message_id"=>"5f5b277a-ed00-4131-b053-643419d2acf6", "event_type"=>"compute.libvirt.error", "timestamp"=>"2017-05-17T13:55:09.169000", "payload"=>{"service"=>"compute.compute-1.localdomain", "request_id"=>"req-a1b40da1-06e5-4711-a5be-621edaddc341"}}, :context=>{}, :user_id=>nil, :priority=>nil, :content_type=>nil}, :ems_id=>45000000000005}], Dequeued in: [16.322796014] seconds [----] I, [2017-05-17T09:55:49.895704 #15298:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088214], Delivering... [----] I, [2017-05-17T09:55:49.952777 #15298:1025138] INFO -- : MIQ(EmsEventHelper#before_handle) Processing EMS event [compute.libvirt.error] chain_id [] on EMS [45000000000005]... [----] E, [2017-05-17T09:55:50.101319 #15242:1025138] ERROR -- : <Fog> excon.error #<Excon::Error::BadRequest: Expected([200, 202]) <=> Actual(400 Bad Request) excon.error.response :body => "{\"badRequest\": {\"message\": \"Invalid backup: No backups available to do an incremental backup.\", \"code\": 400}}" :cookies => [ ] :headers => { "Content-Length" => "109" "Content-Type" => "application/json; charset=UTF-8" "Date" => "Wed, 17 May 2017 13:55:50 GMT" "Openstack-Api-Version" => "2.0" "Vary" => "OpenStack-API-Version" "X-Compute-Request-Id" => "req-66f896e8-38c1-49be-aa17-9a2e6d231437" "X-Openstack-Request-Id" => "req-66f896e8-38c1-49be-aa17-9a2e6d231437" } :host => "10.0.0.101" :local_address => "10.0.0.8" :local_port => 49648 :path => "/v2/51143c4c52c14f25824b0d244def4e22/backups" :port => 8776 :reason_phrase => "Bad Request" :remote_ip => "10.0.0.101" :status => 400 :status_line => "HTTP/1.1 400 Bad Request\r\n" > [----] E, [2017-05-17T09:55:50.102533 #15242:1025138] ERROR -- : MIQ(ManageIQ::Providers::Openstack::CloudManager::CloudVolume#backup_create) backup=[qqq], error: Expected([200, 202]) <=> Actual(400 Bad Request) excon.error.response :body => "{\"badRequest\": {\"message\": \"Invalid backup: No backups available to do an incremental backup.\", \"code\": 400}}" :cookies => [ ] :headers => { "Content-Length" => "109" "Content-Type" => "application/json; charset=UTF-8" "Date" => "Wed, 17 May 2017 13:55:50 GMT" "Openstack-Api-Version" => "2.0" "Vary" => "OpenStack-API-Version" "X-Compute-Request-Id" => "req-66f896e8-38c1-49be-aa17-9a2e6d231437" "X-Openstack-Request-Id" => "req-66f896e8-38c1-49be-aa17-9a2e6d231437" } :host => "10.0.0.101" :local_address => "10.0.0.8" :local_port => 49648 :path => "/v2/51143c4c52c14f25824b0d244def4e22/backups" :port => 8776 :reason_phrase => "Bad Request" :remote_ip => "10.0.0.101" :status => 400 :status_line => "HTTP/1.1 400 Bad Request\r\n" [----] E, [2017-05-17T09:55:50.104681 #15242:1025138] ERROR -- : MIQ(MiqQueue#deliver) Message id: [45000000088215], Error: [uninitialized constant MiqException::MiqVolumeBackupCreateError] [----] E, [2017-05-17T09:55:50.104938 #15242:1025138] ERROR -- : [NameError]: uninitialized constant MiqException::MiqVolumeBackupCreateError Method:[rescue in deliver] [----] E, [2017-05-17T09:55:50.105061 #15242:1025138] ERROR -- : /var/www/miq/vmdb/app/models/manageiq/providers/openstack/cloud_manager/cloud_volume.rb:69:in `rescue in backup_create' /var/www/miq/vmdb/app/models/manageiq/providers/openstack/cloud_manager/cloud_volume.rb:62:in `backup_create' /var/www/miq/vmdb/app/models/miq_queue.rb:347:in `block in deliver' /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:91:in `block in timeout' /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `block in catch' /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch' /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch' /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:106:in `timeout' /var/www/miq/vmdb/app/models/miq_queue.rb:343:in `deliver' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:107:in `deliver_queue_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:135:in `deliver_message' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:153:in `block in do_work' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:147:in `loop' /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:147:in `do_work' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:336:in `block in do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:333:in `loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:333:in `do_work_loop' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:155:in `run' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:130:in `start' /var/www/miq/vmdb/app/models/miq_worker/runner.rb:21:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:339:in `block in start_runner' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' /var/www/miq/vmdb/app/models/miq_worker.rb:337:in `start_runner' /var/www/miq/vmdb/app/models/miq_worker.rb:348:in `start' /var/www/miq/vmdb/app/models/miq_worker.rb:266:in `start_worker' /var/www/miq/vmdb/app/models/miq_worker.rb:150:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_worker.rb:150:in `times' /var/www/miq/vmdb/app/models/miq_worker.rb:150:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:53:in `block in sync_workers' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each' /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers' /var/www/miq/vmdb/app/models/miq_server.rb:160:in `start' /var/www/miq/vmdb/app/models/miq_server.rb:251:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:65:in `start' /var/www/miq/vmdb/lib/workers/evm_server.rb:91:in `start' /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>' [----] I, [2017-05-17T09:55:50.105298 #15242:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088215], State: [error], Delivered in [0.812511037] seconds [----] I, [2017-05-17T09:55:50.107701 #15242:1025138] INFO -- : MIQ(MiqQueue#m_callback) Message id: [45000000088215], Invoking Callback with args: ["Finished", "error", "uninitialized constant MiqException::MiqVolumeBackupCreateError", "nil"] [----] I, [2017-05-17T09:55:50.107964 #15242:1025138] INFO -- : MIQ(MiqTask#update_status) Task: [45000000001947] [Finished] [Error] [uninitialized constant MiqException::MiqVolumeBackupCreateError] [----] I, [2017-05-17T09:55:50.137330 #15242:1025138] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [45000000088216], MiqWorker id: [45000000000001], 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", 45000000000001], "evm_worker_start", {:event_details=>"Worker started: ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748]", :type=>"ManageIQ::Providers::StorageManager::CinderManager::EventCatcher"}], Dequeued in: [5.019896746] seconds [----] I, [2017-05-17T09:55:50.138287 #15242:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088216], Delivering... [----] I, [2017-05-17T09:55:50.147508 #15242:1025138] INFO -- : <AutomationEngine> MiqAeEvent.build_evm_event >> event=<"evm_worker_start"> inputs=<{:event_details=>"Worker started: ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748]", :type=>"ManageIQ::Providers::StorageManager::CinderManager::EventCatcher", "MiqEvent::miq_event"=>45000000018117, :miq_event_id=>45000000018117, "EventStream::event_stream"=>45000000018117, :event_stream_id=>45000000018117}> /var/www/miq/vmdb/app/models/manageiq/providers/base_manager/event_catcher/runner.rb:122:in `monitor_events': must be implemented in subclass (NotImplementedError) from /var/www/miq/vmdb/app/models/manageiq/providers/base_manager/event_catcher/runner.rb:164:in `block in start_event_monitor' [----] I, [2017-05-17T09:55:50.152582 #15298:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088221], 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=>"EmsEvent", :object_id=>45000000018116, :attrs=>{:event_id=>45000000018116, :event_stream_id=>45000000018116, :event_type=>"compute.libvirt.error"}, :instance_name=>"Event", :user_id=>45000000000001, :miq_group_id=>45000000000001, :tenant_id=>45000000000001, :automate_message=>nil}] [----] I, [2017-05-17T09:55:50.153659 #15298:1025138] INFO -- : MIQ(EmsEventHelper#after_handle) Processing EMS event [compute.libvirt.error] chain_id [] on EMS [45000000000005]...Complete [----] I, [2017-05-17T09:55:50.154958 #15298:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088214], State: [ok], Delivered in [0.258490466] seconds [----] I, [2017-05-17T09:55:50.172234 #15242:1025138] INFO -- : MIQ(MiqQueue.put) Message id: [45000000088222], 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=>45000000000001, :attrs=>{:event_type=>"evm_worker_start", :event_details=>"Worker started: ID [45000000007791], PID [24742], GUID [85bd16ca-3b08-11e7-a51d-525400950748]", :type=>"ManageIQ::Providers::StorageManager::CinderManager::EventCatcher", "MiqEvent::miq_event"=>45000000018117, :miq_event_id=>45000000018117, "EventStream::event_stream"=>45000000018117, :event_stream_id=>45000000018117}, :instance_name=>"Event", :user_id=>45000000000001, :miq_group_id=>45000000000002, :tenant_id=>45000000000001, :automate_message=>nil}] [----] I, [2017-05-17T09:55:50.172464 #15242:1025138] INFO -- : MIQ(MiqQueue#delivered) Message id: [45000000088216], State: [ok], Delivered in [0.034973123] seconds [----] I, [2017-05-17T09:55:52.371687 #12246:1025138] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-05-17 13:55:52 UTC]... [----] I, [2017-05-17T09:55:52.381295 #12246:1025138] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2017-05-17 13:55:52 UTC]...Complete [----] I, [2017-05-17T09:55:52.623445 #14463:1224a74] INFO -- : Querying OpenStack for events newer than 2017-05-17T13:55:37.019000... [----] E, [2017-05-17T09:55:52.746164 #15335:1778bd8] ERROR -- : MIQ(cloud_volume_controller-wait_for_task): Unable to create backup for Cloud Volume "qqq": uninitialized constant MiqException::MiqVolumeBackupCreateError [----] I, [2017-05-17T09:55:53.873877 #22122:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::NetworkManager::RefreshWorker::Runner#get_message_via_drb) Message id: [45000000088207], MiqWorker id: [45000000007726], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_45000000000006], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::Openstack::NetworkManager", 45000000000006]]], Dequeued in: [21.914810124] seconds [----] I, [2017-05-17T09:55:53.875764 #22122:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088207], Delivering... [----] I, [2017-05-17T09:55:53.997197 #22122:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::NetworkManager::Refresher#refresh) Refreshing all targets... [----] I, [2017-05-17T09:55:54.002633 #22122:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::NetworkManager::Refresher#refresh) EMS: [oc_ci Network Manager], id: [45000000000006] Refreshing targets for EMS... [----] I, [2017-05-17T09:55:54.004306 #22122:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::NetworkManager::Refresher#refresh) EMS: [oc_ci Network Manager], id: [45000000000006] ManageIQ::Providers::Openstack::NetworkManager [oc_ci Network Manager] id [45000000000006] [----] I, [2017-05-17T09:55:54.102509 #22122:1025138] INFO -- : MIQ(ManageIQ::Providers::Openstack::NetworkManager::Refresher#refresh_targets_for_ems) EMS: [oc_ci Network Manager], id: [45000000000006] Refreshing target ManageIQ::Providers::Openstack::NetworkManager [oc_ci Network Manager] id [45000000000006]... [----] I, [2017-05-17T09:55:54.303686 #14439:1223368] INFO -- : Querying OpenStack for events newer than 2017-05-17T13:55:38.844000... [----] I, [2017-05-17T09:55:54.855892 #22203:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::SwiftManager::RefreshWorker::Runner#get_message_via_drb) Message id: [45000000088209], MiqWorker id: [45000000007730], Zone: [default], Role: [ems_inventory], Server: [], Ident: [ems_45000000000004], Target id: [], Instance id: [], Task id: [], Command: [EmsRefresh.refresh], Timeout: [7200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [[["ManageIQ::Providers::StorageManager::SwiftManager", 45000000000004]]], Dequeued in: [22.815572319] seconds [----] I, [2017-05-17T09:55:54.856195 #22203:1025138] INFO -- : MIQ(MiqQueue#deliver) Message id: [45000000088209], Delivering... [----] I, [2017-05-17T09:55:54.893319 #22203:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::SwiftManager::Refresher#refresh) Refreshing all targets... [----] I, [2017-05-17T09:55:54.893892 #22203:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::SwiftManager::Refresher#refresh) EMS: [oc_ci Swift Manager], id: [45000000000004] Refreshing targets for EMS... [----] I, [2017-05-17T09:55:54.895956 #22203:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::SwiftManager::Refresher#refresh) EMS: [oc_ci Swift Manager], id: [45000000000004] ManageIQ::Providers::StorageManager::SwiftManager [oc_ci Swift Manager] id [45000000000004] [----] I, [2017-05-17T09:55:54.909275 #22203:1025138] INFO -- : MIQ(ManageIQ::Providers::StorageManager::SwiftManager::Refresher#refresh_targets_for_ems) EMS: [oc_ci Swift Manager], id: [45000000000004] Refreshing target ManageIQ::Providers::StorageManager::SwiftManager [oc_ci Swift Manager] id [45000000000004]... [fog][WARNING] Unrecognized arguments: provider [fog][WARNING] Unrecognized arguments: provider :
https://github.com/ManageIQ/manageiq-ui-classic/pull/1373
Verified ======== 5.9.0.10