Bug 1651702
| Summary: | SmartState Analysis fails on VMware Vsphere 6.7 | |||
|---|---|---|---|---|
| Product: | Red Hat CloudForms Management Engine | Reporter: | Phil Avery <pavery> | |
| Component: | SmartState Analysis | Assignee: | Jerry Keselman <jkeselma> | |
| Status: | CLOSED CURRENTRELEASE | QA Contact: | Satyajit Bulage <sbulage> | |
| Severity: | high | Docs Contact: | Red Hat CloudForms Documentation <cloudforms-docs> | |
| Priority: | high | |||
| Version: | 5.9.7 | CC: | dmetzger, jdupuy, jkeselma, mfeifer, obarenbo, roliveri, simaishi | |
| Target Milestone: | GA | Keywords: | Reopened, TestOnly, ZStream | |
| Target Release: | 5.11.0 | |||
| Hardware: | x86_64 | |||
| OS: | Linux | |||
| Whiteboard: | ||||
| Fixed In Version: | 5.11.0.1 | Doc Type: | If docs needed, set a value | |
| Doc Text: | Story Points: | --- | ||
| Clone Of: | ||||
| : | 1669626 1669627 (view as bug list) | Environment: | ||
| Last Closed: | 2019-12-13 15:09:16 UTC | Type: | Bug | |
| Regression: | --- | Mount Type: | --- | |
| Documentation: | --- | CRM: | ||
| Verified Versions: | Category: | Bug | ||
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | ||
| Cloudforms Team: | CFME Core | Target Upstream Version: | ||
| Embargoed: | ||||
| Bug Depends On: | ||||
| Bug Blocks: | 1669626, 1669627 | |||
Hello John, Can you please point me to reproducer environment .? I have tested SSA on nvc-6 provider and it is working without any error. Thanks, Satyajit Bulage. This just may be due to the fact that it's a new, unknown, version of the VDDK. Jerry will know. Assigning to him. Jerry, do you think that might be the cause? I believe the issue is due to 6.7 having some changes and the previous VDDK from 6.5 also fails so its not 100% backwards compatible, It certainly does show from VMWare on 6.7 that a snapshot completes, but then fails to mount it to read. From previous version updates we have seen issues and the gem "ffi-vix_disk_lib" has needed to be updated which is located here "https://github.com/ManageIQ/ffi-vix_disk_lib". Rich, correct, at least partially. The work has not been done to enable VDDK 6.7.0. However 6.5.0 has been enabled. It is unclear whether the log output that is pasted into the comment above is from version 6.5.0 or 6.7.0. I would expect them to be different. Can someone provide access to the appliance in question so I can debug the VDDK 6.5.0 issue further? Thanks. Jerry, The ESXi and VSphere are all on latest 6.7 now and using the respected vddk 6.7, I did and can downgrade the vddk to the 6.5 version that always worked on my VSphere 6.5 environment. Note we do get an error message at the same location just worded slightly different. This is the Error in Cloudforms when using vddk 6.7 on VSphere 6.7 Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] And this is the error when using vddk 6.5 on VSphere 6.7 Message Unable to mount filesystem. Reason:[FFI::VixDiskLib::ApiWrapper#open (errcode=3 - VIX_E_INVALID_ARG): One of the parameters was invalid. If you want me to install the 6.5 vddk and generate logs I am happy to do that. Phil, VDDK 6.7 *will not work* until we make the change to include it in ffi-vix_disk_lib, as you have already surmised. The VDDK 6.5 error is an entirely different issue specific to your environment. I would need access to the appliance with its VMware environment in order to debug. I do not have access to an environment with VSphere 6.7 installed. Phil, I can set up my own appliance to work with your VMware environment, if you can simply provide access to the ESX and Vcenter servers (IPs, user/passwords). Thanks. https://github.com/ManageIQ/ffi-vix_disk_lib/pull/13 and https://github.com/ManageIQ/vmware_web_service/pull/46 resolve this issue. We saw some strange behaviour where the ssa would error with a timeout in tasks and then the error would disappear and show it was successful, however when we click on the vm and go to the scan results we see the timeout error. Noticed the old gems were still present and we removed them which failed Cloudforms from starting. To be sure it wasn't my environment we built up a new 6.7 environment and latest appliances. I can grant you access to my lab if needed. Pavery Able to perform SSA on vSphere 6.7 using VDDK 6.7 Verified Version: 5.11.0.3.20190507174347_a77bd90 |
Description of problem: When running Smart State Analysis against VSphere 6.7 I get failures only on vm guests, ( Hosts and Datastores work 100% ) Latest version of the vddk give the following error Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] Previous VDDK would give this error Message Unable to mount filesystem. Reason:[FFI::VixDiskLib::ApiWrapper#open (errcode=3 - VIX_E_INVALID_ARG): One of the parameters was invalid. Version-Release number of selected component (if applicable): CloudForms Version 5.9.5.3.20181023135339_256263f Also tried with latest ManageIQ Version gaprindashvili-6.20181101094941_460a0a8 I upgraded to latest VSphere 6.7 ( VMware ESXi, 6.7.0, 10764712 ) with the latest vddk ( VMware-vix-disklib-6.7.0-8535999.x86_64.tar.gz ) I have tried this with an earlier version of 6.7 and the previous version of the vddk VMware-vix-disklib-6.7.0-8173251.x86_64.tar.gz as well as the 6.5 vddk VMware-vix-disklib-6.5.0-5136645.x86_64.tar.gz How reproducible: 100% Steps to Reproduce: 1. Upgrade Vsphere to 6.7 2. Perform Smartstate with either existing 6.5 version of vddk or upgrade vddk Actual results: Snapshot completes but then aborts when running the scan and then deletes the snapshot immedietly. Fail to scan with one of 2 errors depending on vddk version Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] Message Unable to mount filesystem. Reason:[FFI::VixDiskLib::ApiWrapper#open (errcode=3 - VIX_E_INVALID_ARG): One of the parameters was invalid. Expected results: Scan to pass Additional info: automation.log [----] I, [2018-11-20T14:38:59.136840 #6772:1021114] INFO -- : MiqAeEvent.build_evm_event >> event=<:request_vm_scan> inputs=<{:vm=>#<ManageIQ::Providers::Vmware::InfraManager::Vm id: 174, vendor: "vmware", format: nil, version: nil, name: "haproxy", description: nil, location: "haproxy/haproxy.vmx", config_xml: nil, autostart: nil, host_id: 14, last_sync_on: nil, created_on: "2018-09-19 00:36:19", updated_on: "2018-11-20 00:55:48", storage_id: 17, guid: "50c00c95-f701-457a-b9a7-54ac3a516d67", ems_id: 6, last_scan_on: "2018-11-20 04:54:17", last_scan_attempt_on: "2018-11-20 04:53:55", uid_ems: "4233d112-6e77-cf90-3885-4d19b2d1912b", retires_on: nil, retired: nil, boot_time: nil, tools_status: "toolsNotRunning", standby_action: "checkpoint", power_state: "off", state_changed_on: "2018-11-20 02:33:56", previous_state: "poweredOn", connection_state: "connected", last_perf_capture_on: "2018-11-19 21:46:00", registered: nil, busy: nil, smart: nil, memory_reserve: 0, memory_reserve_expand: false, memory_limit: -1, memory_shares: 20480, memory_shares_level: "normal", cpu_reserve: 0, cpu_reserve_expand: false, cpu_limit: -1, cpu_shares: 2000, cpu_shares_level: "normal", cpu_affinity: nil, ems_created_on: nil, template: false, evm_owner_id: 1, ems_ref_obj: "--- !ruby/string:VimString\nstr: vm-107\nxsiType: :M...", miq_group_id: 2, linked_clone: true, fault_tolerance: false, type: "ManageIQ::Providers::Vmware::InfraManager::Vm", ems_ref: "vm-107", ems_cluster_id: 5, retirement_warn: nil, retirement_last_warn: nil, vnc_port: nil, flavor_id: nil, availability_zone_id: nil, cloud: false, retirement_state: nil, cloud_network_id: nil, cloud_subnet_id: nil, cloud_tenant_id: nil, raw_power_state: "poweredOff", publicly_available: nil, orchestration_stack_id: nil, retirement_requester: nil, tenant_id: 1, resource_group_id: nil, deprecated: nil, storage_profile_id: nil, cpu_hot_add_enabled: false, cpu_hot_remove_enabled: false, memory_hot_add_enabled: false, memory_hot_add_limit: nil, memory_hot_add_increment: nil>, :host=>#<ManageIQ::Providers::Vmware::InfraManager::HostEsx id: 14, name: "esxi1.lab.int", hostname: "esxi1.lab.int", ipaddress: "192.168.0.11", vmm_vendor: "vmware", vmm_version: "6.7.0", vmm_product: "ESXi", vmm_buildnumber: "10764712", created_on: "2018-09-11 15:07:01", updated_on: "2018-11-20 15:29:08", guid: "aac931b6-1bb1-487d-a061-e271b3b2f0a1", ems_id: 6, user_assigned_os: nil, power_state: "on", smart: 1, settings: {}, last_perf_capture_on: "2018-11-20 15:29:00", uid_ems: "esxi1.lab.int", connection_state: "connected", ssh_permit_root_login: nil, ems_ref_obj: "--- !ruby/string:VimString\nstr: host-10\nxsiType: :...", admin_disabled: false, service_tag: "FN3V1P1", asset_tag: nil, ipmi_address: "", mac_address: "", type: "ManageIQ::Providers::Vmware::InfraManager::HostEsx", failover: nil, ems_ref: "host-10", hyperthreading: true, ems_cluster_id: 5, next_available_vnc_port: nil, hypervisor_hostname: nil, availability_zone_id: nil, maintenance: false, maintenance_reason: nil, physical_server_id: nil>, :ext_management_system=>#<ManageIQ::Providers::Vmware::InfraManager id: 6, name: "VCenter", created_on: "2018-09-11 15:06:32", updated_on: "2018-11-20 15:22:16", guid: "877a96a3-23c4-4433-8e0b-aeeddcf8f0c9", zone_id: 1, type: "ManageIQ::Providers::Vmware::InfraManager", api_version: "6.7", uid_ems: "20de47c4-e659-485c-8fa8-2c96d24b0f4e", host_default_vnc_port_start: nil, host_default_vnc_port_end: nil, provider_region: nil, last_refresh_error: nil, last_refresh_date: "2018-11-20 15:22:16", provider_id: nil, realm: nil, tenant_id: 1, 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: nil, enabled: true, options: {}>, "MiqEvent::miq_event"=>41581, :miq_event_id=>41581, "EventStream::event_stream"=>41581, :event_stream_id=>41581}> [----] I, [2018-11-20T14:39:20.238487 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) User [admin] with current group ID [2] name [EvmGroup-super_administrator] [----] I, [2018-11-20T14:39:20.247970 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=41582&Host%3A%3Ahost=14&MiqEvent%3A%3Amiq_event=41582&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&event_stream_id=41582&event_type=vm_scan_start&host_id=14&miq_event_id=41582&object_name=Event&vm_id=174&vmdb_object_type=vm] [----] I, [2018-11-20T14:39:20.405991 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=41582&Host%3A%3Ahost=14&MiqEvent%3A%3Amiq_event=41582&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&event_stream_id=41582&event_type=vm_scan_start&host_id=14&miq_event_id=41582&object_name=Event&vm_id=174&vmdb_object_type=vm ManageIQ/System] [----] I, [2018-11-20T14:39:20.571367 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_start#create] [----] I, [2018-11-20T14:39:20.688723 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_start#create ManageIQ/System/Event/MiqEvent] [----] I, [2018-11-20T14:39:20.707272 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Instance [/ManageIQ/System/Event/MiqEvent/POLICY/vm_scan_start] not found in MiqAeDatastore - trying [.missing] [----] I, [2018-11-20T14:39:20.729408 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2018-11-20T14:39:20.752704 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System] [----] I, [2018-11-20T14:39:20.785182 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System] [----] I, [2018-11-20T14:39:20.793530 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}] [----] I, [2018-11-20T14:39:20.895001 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2018-11-20T14:39:20.895833 #6772:1021114] INFO -- : Q-task_id([job_dispatcher]) Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_start#create] [----] I, [2018-11-20T14:39:36.024975 #6772:1021114] INFO -- : User [admin] with current group ID [2] name [EvmGroup-super_administrator] [----] I, [2018-11-20T14:39:36.028743 #6772:1021114] INFO -- : Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=41583&ExtManagementSystem%3A%3Aems=6&Host%3A%3Ahost=14&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&ems_id=6&event_id=41583&event_stream_id=41583&event_type=GeneralUserEvent&host_id=14&object_name=Event&vm_id=174&vmdb_object_type=event_stream] [----] I, [2018-11-20T14:39:36.128160 #6772:1021114] INFO -- : Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=41583&ExtManagementSystem%3A%3Aems=6&Host%3A%3Ahost=14&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&ems_id=6&event_id=41583&event_stream_id=41583&event_type=GeneralUserEvent&host_id=14&object_name=Event&vm_id=174&vmdb_object_type=event_stream ManageIQ/System] [----] I, [2018-11-20T14:39:36.245852 #6772:1021114] INFO -- : Following Relationship [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create] [----] I, [2018-11-20T14:39:36.407508 #6772:1021114] INFO -- : Updated namespace [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create ManageIQ/System/Event/EmsEvent] [----] I, [2018-11-20T14:39:36.480185 #6772:1021114] INFO -- : Instance [/ManageIQ/System/Event/EmsEvent/VC/GeneralUserEvent] not found in MiqAeDatastore - trying [.missing] [----] I, [2018-11-20T14:39:36.494907 #6772:1021114] INFO -- : Followed Relationship [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create] [----] I, [2018-11-20T14:39:46.341407 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) User [admin] with current group ID [2] name [EvmGroup-super_administrator] [----] I, [2018-11-20T14:39:46.351220 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=41584&Host%3A%3Ahost=14&MiqEvent%3A%3Amiq_event=41584&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&event_stream_id=41584&event_type=vm_scan_abort&host_id=14&miq_event_id=41584&object_name=Event&vm_id=174&vmdb_object_type=vm] [----] I, [2018-11-20T14:39:46.505748 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=41584&Host%3A%3Ahost=14&MiqEvent%3A%3Amiq_event=41584&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&event_stream_id=41584&event_type=vm_scan_abort&host_id=14&miq_event_id=41584&object_name=Event&vm_id=174&vmdb_object_type=vm ManageIQ/System] [----] I, [2018-11-20T14:39:46.670241 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Following Relationship [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_abort#create] [----] I, [2018-11-20T14:39:46.779113 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_abort#create ManageIQ/System/Event/MiqEvent] [----] I, [2018-11-20T14:39:46.796555 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Instance [/ManageIQ/System/Event/MiqEvent/POLICY/vm_scan_abort] not found in MiqAeDatastore - trying [.missing] [----] I, [2018-11-20T14:39:46.814383 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Following Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2018-11-20T14:39:46.835609 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [miqaedb:/System/event_handlers/event_enforce_policy#create ManageIQ/System] [----] I, [2018-11-20T14:39:46.864523 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Updated namespace [System/event_handlers/event_enforce_policy ManageIQ/System] [----] I, [2018-11-20T14:39:46.872145 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Invoking [builtin] method [/ManageIQ/System/event_handlers/event_enforce_policy] with inputs [{}] [----] I, [2018-11-20T14:39:46.970904 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Followed Relationship [miqaedb:/System/event_handlers/event_enforce_policy#create] [----] I, [2018-11-20T14:39:46.971586 #6796:1021114] INFO -- : Q-task_id([job_dispatcher]) Followed Relationship [miqaedb:/System/Event/MiqEvent/POLICY/vm_scan_abort#create] [----] I, [2018-11-20T14:39:52.003110 #6788:1021114] INFO -- : User [admin] with current group ID [2] name [EvmGroup-super_administrator] [----] I, [2018-11-20T14:39:52.008903 #6788:1021114] INFO -- : Instantiating [/System/Process/Event?EventStream%3A%3Aevent_stream=41585&ExtManagementSystem%3A%3Aems=6&Host%3A%3Ahost=14&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&ems_id=6&event_id=41585&event_stream_id=41585&event_type=GeneralUserEvent&host_id=14&object_name=Event&vm_id=174&vmdb_object_type=event_stream] [----] I, [2018-11-20T14:39:52.161305 #6788:1021114] INFO -- : Updated namespace [/System/Process/Event?EventStream%3A%3Aevent_stream=41585&ExtManagementSystem%3A%3Aems=6&Host%3A%3Ahost=14&MiqServer%3A%3Amiq_server=1&User%3A%3Auser=1&VmOrTemplate%3A%3Avm=174&ems_id=6&event_id=41585&event_stream_id=41585&event_type=GeneralUserEvent&host_id=14&object_name=Event&vm_id=174&vmdb_object_type=event_stream ManageIQ/System] [----] I, [2018-11-20T14:39:52.317973 #6788:1021114] INFO -- : Following Relationship [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create] [----] I, [2018-11-20T14:39:52.484635 #6788:1021114] INFO -- : Updated namespace [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create ManageIQ/System/Event/EmsEvent] [----] I, [2018-11-20T14:39:52.559502 #6788:1021114] INFO -- : Instance [/ManageIQ/System/Event/EmsEvent/VC/GeneralUserEvent] not found in MiqAeDatastore - trying [.missing] [----] I, [2018-11-20T14:39:52.574647 #6788:1021114] INFO -- : Followed Relationship [miqaedb:/System/Event/EmsEvent/VC/GeneralUserEvent#create] evm.log [----] I, [2018-11-20T10:40:58.488748 #6807:af5118] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=ems, wcount=1, priority=200 [----] I, [2018-11-20T10:40:58.490984 #6807:af5118] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 2 miq_queue rows for queue_name=generic, wcount=4, priority=200 [----] I, [2018-11-20T10:40:58.496517 #6807:af5118] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=smartproxy, wcount=2, priority=200 [----] I, [2018-11-20T10:40:58.496694 #6807:af5118] INFO -- : MIQ(MiqServer#monitor_loop) Server Monitoring Complete - Timings: {:server_dequeue=>0.004281520843505859, :worker_monitor=>2.264038324356079, :worker_dequeue=>0.016274452209472656, :total_time=>2.284942150115967} [----] I, [2018-11-20T10:40:58.683877 #10270:af5118] INFO -- : MIQ(MiqEventHandler::Runner#get_message_via_drb) Message id: [1030433], MiqWorker id: [5697], Zone: [default], Role: [event], Server: [], Ident: [ems], Target id: [6], Instance id: [], Task id: [], Command: [EmsEvent.add], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [{:event_type=>"GeneralUserEvent", :chain_id=>"180960", :is_task=>false, :source=>"VC", :message=>"User logged event: EVM SmartState Analysis Initiated for VM [haproxy]", :timestamp=>"2018-11-20T15:40:51.745523Z", :full_data=>{"key"=>"180960", "chainId"=>"180960", "createdTime"=>"2018-11-20T15:40:51.745523Z", "userName"=>"VSPHERE.LOCAL\\Administrator", "datacenter"=>{"name"=>"Datacenter", "datacenter"=>"datacenter-2"}, "computeResource"=>{"name"=>"Internal", "computeResource"=>"domain-c7"}, "host"=>{"name"=>"esxi1.lab.int", "host"=>"host-10"}, "vm"=>{"name"=>"haproxy", "vm"=>"vm-107", "path"=>"[ESXi1-DS] haproxy/haproxy.vmx", "uuid"=>"4233d112-6e77-cf90-3885-4d19b2d1912b"}, "fullFormattedMessage"=>"User logged event: EVM SmartState Analysis Initiated for VM [haproxy]", "changeTag"=>"", "message"=>"EVM SmartState Analysis Initiated for VM [haproxy]", "eventType"=>"GeneralUserEvent"}, :ems_id=>6, :username=>"VSPHERE.LOCAL\\Administrator", :vm_ems_ref=>"vm-107", :vm_name=>"haproxy", :vm_location=>"[ESXi1-DS] haproxy/haproxy.vmx", :vm_uid_ems=>"4233d112-6e77-cf90-3885-4d19b2d1912b", :host_name=>"esxi1.lab.int", :host_ems_ref=>"host-10"}], Dequeued in: [5.816960864] seconds [----] I, [2018-11-20T10:40:58.684078 #10270:af5118] INFO -- : MIQ(MiqQueue#deliver) Message id: [1030433], Delivering... [----] I, [2018-11-20T10:40:58.713071 #10270:af5118] INFO -- : MIQ(EmsEventHelper#before_handle) Processing EMS event [GeneralUserEvent] chain_id [180960] on EMS [6]... [----] I, [2018-11-20T10:40:58.742559 #10270:af5118] INFO -- : MIQ(MiqQueue.put) Message id: [1030436], 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=>41583, :attrs=>{:event_id=>41583, :event_stream_id=>41583, :event_type=>"GeneralUserEvent", "ExtManagementSystem::ems"=>6, :ems_id=>6, "VmOrTemplate::vm"=>174, :vm_id=>174, "Host::host"=>14, :host_id=>14}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}] [----] I, [2018-11-20T10:40:58.742724 #10270:af5118] INFO -- : MIQ(EmsEventHelper#after_handle) Processing EMS event [GeneralUserEvent] chain_id [180960] on EMS [6]...Complete [----] I, [2018-11-20T10:40:58.743081 #10270:af5118] INFO -- : MIQ(MiqQueue#delivered) Message id: [1030433], State: [ok], Delivered in [0.059001149] seconds [----] I, [2018-11-20T10:40:59.172485 #1652:af5118] INFO -- : MIQ(MiqSmartProxyWorker::Runner#get_message_via_drb) Message id: [1030432], MiqWorker id: [5745], Zone: [default], Role: [smartproxy], Server: [f5eb7d8f-f4d7-4d8d-af14-33371d378831], Ident: [smartproxy], Target id: [], Instance id: [2], Task id: [], Command: [MiqServer.scan_metadata], Timeout: [1200], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: [#<OpenStruct args=["[ESXi1-DS] haproxy/haproxy.vmx", "---\nems:\n ems:\n :hostname: vcenter.lab.int\n :ipaddress: \n :username: administrator\n :password: ********\n :class_name: ManageIQ::Providers::Vmware::InfraManager\n host:\n :hostname: esxi1.lab.int\n :ipaddress: 192.168.0.11\n :username: root\n :password: ********\n :class_name: ManageIQ::Providers::Vmware::InfraManager::HostEsx\n connect_to: host\nsnapshot:\n use_existing: false\n description: 'Snapshot for scan job: de21c3f5-8882-48bc-a71f-64fa8acff44b, EVM Server\n build: 20181023135339_256263f (embedded) Server Time: 2018-11-20T15:40:51Z'\n create_free_percent: 100\n remove_free_percent: 100\n name: 'Snapshot for scan job: de21c3f5-8882-48bc-a71f-64fa8acff44b, EVM Server build:\n 20181023135339_256263f (embedded) Server Time: 2018-11-20T15:40:51Z'\nvmScanProfiles: []\n"], method_name="scan_metadata", vm_guid="50c00c95-f701-457a-b9a7-54ac3a516d67", category="vmconfig,accounts,software,services,system", taskid="de21c3f5-8882-48bc-a71f-64fa8acff44b", target_id=174, target_type="VmOrTemplate">], Dequeued in: [7.431028677] seconds [----] I, [2018-11-20T10:40:59.172843 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [1030432], Delivering... [----] I, [2018-11-20T10:40:59.236575 #10278:af5118] INFO -- : MIQ(MiqPriorityWorker::Runner#get_message_via_drb) Message id: [1030434], MiqWorker id: [5698], Zone: [default], Role: [], Server: [f5eb7d8f-f4d7-4d8d-af14-33371d378831], 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.728092306] seconds [----] I, [2018-11-20T10:40:59.236874 #10278:af5118] INFO -- : MIQ(MiqQueue#deliver) Message id: [1030434], Delivering... [----] I, [2018-11-20T10:40:59.337438 #10278:af5118] INFO -- : MIQ(MiqQueue#delivered) Message id: [1030434], State: [ok], Delivered in [0.100572571] seconds [----] I, [2018-11-20T10:41:00.207561 #15253:af5118] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1030435], MiqWorker id: [5753], 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.682711512] seconds [----] I, [2018-11-20T10:41:00.207823 #15253:af5118] INFO -- : MIQ(MiqQueue#deliver) Message id: [1030435], Delivering... [----] I, [2018-11-20T10:41:00.434621 #15253:af5118] INFO -- : MIQ(MiqQueue#delivered) Message id: [1030435], State: [ok], Delivered in [0.226757194] seconds [----] I, [2018-11-20T10:41:02.997555 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) Connecting to [host(directly):] for VM:[] [----] I, [2018-11-20T10:41:03.001985 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [esxi1.lab.int] Connecting with address: [esxi1.lab.int], userid: [root]... [----] I, [2018-11-20T10:41:03.081370 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [esxi1.lab.int] esxi1.lab.int is ESX, API version: 6.7.1 [----] I, [2018-11-20T10:41:03.081463 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [esxi1.lab.int] Connected [----] I, [2018-11-20T10:41:03.081589 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) Connection to [host(directly):] completed for VM:[] in [0.084048122] seconds Cookie#domain returns dot-less domain name now. Use Cookie#dot_domain if you need "." at the beginning. [----] I, [2018-11-20T10:41:03.497166 #6807:af5118] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-11-20 15:41:03 UTC]... [----] I, [2018-11-20T10:41:03.506505 #6807:af5118] INFO -- : MIQ(MiqServer#heartbeat) Heartbeat [2018-11-20 15:41:03 UTC]...Complete [----] I, [2018-11-20T10:41:03.521239 #6807:af5118] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 1 miq_queue rows for queue_name=generic, wcount=4, priority=200 [----] I, [2018-11-20T10:41:03.981679 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue.put) Message id: [1030437], id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_message_1542728463], Command: [Job.update_message], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["de21c3f5-8882-48bc-a71f-64fa8acff44b", "Initializing scan"] [----] I, [2018-11-20T10:41:03.990887 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQExtract using config file: [[ESXi1-DS] haproxy/haproxy.vmx] settings: [{"ems"=>{"ems"=>{:hostname=>"vcenter.lab.int", :ipaddress=>nil, :username=>"administrator", :password=>"********", :class_name=>"ManageIQ::Providers::Vmware::InfraManager"}, "host"=>{:hostname=>"esxi1.lab.int", :ipaddress=>"192.168.0.11", :username=>"root", :password=>"********", :class_name=>"ManageIQ::Providers::Vmware::InfraManager::HostEsx", :use_vim_broker=>false}, "connect_to"=>"host", :use_vim_broker=>false}, "snapshot"=>{"use_existing"=>false, "description"=>"Snapshot for scan job: de21c3f5-8882-48bc-a71f-64fa8acff44b, EVM Server build: 20181023135339_256263f (embedded) Server Time: 2018-11-20T15:40:51Z", "create_free_percent"=>100, "remove_free_percent"=>100, "name"=>"Snapshot for scan job: de21c3f5-8882-48bc-a71f-64fa8acff44b, EVM Server build: 20181023135339_256263f (embedded) Server Time: 2018-11-20T15:40:51Z"}, "vmScanProfiles"=>[]}] [----] I, [2018-11-20T10:41:03.990981 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) Loading disk files for VM [[ESXi1-DS] haproxy/haproxy.vmx] [----] I, [2018-11-20T10:41:04.073571 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) Snapshot create pre-check skipped for Datastore <ESXi1-DS> due to Percentage:<>. Space Free:<399146745856> Disk size:<42949672960> [----] I, [2018-11-20T10:41:05.101893 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) VolMgrPlatformSupportLinux.preMount: VM snapshot [36-snapshot-13] created in [1.106860915] seconds [----] I, [2018-11-20T10:41:05.102253 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MiqVimVdlVcConnectionMod.vdlVcConnection: server - esxi1.lab.int [----] I, [2018-11-20T10:41:05.102352 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) ThumbPrint.initialize(esxi1.lab.int) [----] I, [2018-11-20T10:41:05.136620 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) ThumbPrint.to_sha1 for host esxi1.lab.int [----] I, [2018-11-20T10:41:05.137125 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) ThumbPrint.to_sha1 for host esxi1.lab.int is 50:A8:7A:D3:2A:4C:9E:BE:05:98:5D:7D:4A:2A:92:41:5B:52:83:DB [----] E, [2018-11-20T10:41:05.323613 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] for VM [[ESXi1-DS] haproxy/haproxy.vmx] [----] E, [2018-11-20T10:41:05.324336 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/vmware_web_service-0.3.0/lib/VMwareWebService/VixDiskLib/VixDiskLib.rb:140:in `get_uri' [----] E, [2018-11-20T10:41:05.324443 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/vmware_web_service-0.3.0/lib/VMwareWebService/VixDiskLib/VixDiskLib.rb:124:in `start_service' [----] E, [2018-11-20T10:41:05.324536 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/vmware_web_service-0.3.0/lib/VMwareWebService/VixDiskLib/VixDiskLib.rb:39:in `block in connect' [----] E, [2018-11-20T10:41:05.326701 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/sync.rb:234:in `block in sync_synchronize' [----] E, [2018-11-20T10:41:05.326801 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/sync.rb:231:in `handle_interrupt' [----] E, [2018-11-20T10:41:05.326888 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/sync.rb:231:in `sync_synchronize' [----] E, [2018-11-20T10:41:05.326986 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/vmware_web_service-0.3.0/lib/VMwareWebService/VixDiskLib/VixDiskLib.rb:36:in `connect' [----] E, [2018-11-20T10:41:05.327094 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/vmware_web_service-0.3.0/lib/VMwareWebService/MiqVimVdlMod.rb:46:in `vdlVcConnection' [----] E, [2018-11-20T10:41:05.327189 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:87:in `block in openDisks' [----] E, [2018-11-20T10:41:05.327278 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:79:in `each' [----] E, [2018-11-20T10:41:05.327368 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:79:in `openDisks' [----] E, [2018-11-20T10:41:05.327458 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:67:in `vmDisks' [----] E, [2018-11-20T10:41:05.327547 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:165:in `volumeManager' [----] E, [2018-11-20T10:41:05.327655 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/MiqVm/MiqVm.rb:159:in `rootTrees' [----] E, [2018-11-20T10:41:05.327742 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/manageiq-smartstate-0.2.13/lib/metadata/MIQExtract/MIQExtract.rb:57:in `initialize' [----] E, [2018-11-20T10:41:05.327828 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/mixins/scanning_mixin.rb:234:in `new' [----] E, [2018-11-20T10:41:05.327914 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/mixins/scanning_mixin.rb:234:in `scan_via_miq_vm' [----] E, [2018-11-20T10:41:05.328005 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/bundler/gems/cfme-providers-vmware-24941e32bad2/app/models/manageiq/providers/vmware/infra_manager/vm_or_template_shared/scanning.rb:29:in `perform_metadata_scan' [----] E, [2018-11-20T10:41:05.328129 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server/server_smart_proxy.rb:125:in `scan_metadata' [----] E, [2018-11-20T10:41:05.328216 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue.rb:451:in `block in dispatch_method' [----] E, [2018-11-20T10:41:05.328302 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:91:in `block in timeout' [----] E, [2018-11-20T10:41:05.328388 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `block in catch' [----] E, [2018-11-20T10:41:05.329953 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch' [----] E, [2018-11-20T10:41:05.330058 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:33:in `catch' [----] E, [2018-11-20T10:41:05.330144 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/rh-ruby23/root/usr/share/ruby/timeout.rb:106:in `timeout' [----] E, [2018-11-20T10:41:05.330225 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue.rb:450:in `dispatch_method' [----] E, [2018-11-20T10:41:05.330314 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue.rb:427:in `block in deliver' [----] E, [2018-11-20T10:41:05.330403 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/user.rb:261:in `with_user_group' [----] E, [2018-11-20T10:41:05.330492 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue.rb:427:in `deliver' [----] E, [2018-11-20T10:41:05.330582 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:104:in `deliver_queue_message' [----] E, [2018-11-20T10:41:05.330671 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:134:in `deliver_message' [----] E, [2018-11-20T10:41:05.330760 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:152:in `block in do_work' [----] E, [2018-11-20T10:41:05.330855 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `loop' [----] E, [2018-11-20T10:41:05.330945 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_queue_worker_base/runner.rb:146:in `do_work' [----] E, [2018-11-20T10:41:05.331032 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_smart_proxy_worker/runner.rb:71:in `do_work' [----] E, [2018-11-20T10:41:05.331145 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:329:in `block in do_work_loop' [----] E, [2018-11-20T10:41:05.331232 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:326:in `loop' [----] E, [2018-11-20T10:41:05.331319 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:326:in `do_work_loop' [----] E, [2018-11-20T10:41:05.331407 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:153:in `run' [----] E, [2018-11-20T10:41:05.331495 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:127:in `start' [----] E, [2018-11-20T10:41:05.331581 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker/runner.rb:22:in `start_worker' [----] E, [2018-11-20T10:41:05.331671 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:376:in `block in start_runner_via_fork' [----] E, [2018-11-20T10:41:05.331759 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' [----] E, [2018-11-20T10:41:05.333026 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/gems/nakayoshi_fork-0.0.3/lib/nakayoshi_fork.rb:24:in `fork' [----] E, [2018-11-20T10:41:05.333133 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:374:in `start_runner_via_fork' [----] E, [2018-11-20T10:41:05.333223 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:368:in `start_runner' [----] E, [2018-11-20T10:41:05.333313 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:415:in `start' [----] E, [2018-11-20T10:41:05.333397 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:266:in `start_worker' [----] E, [2018-11-20T10:41:05.333486 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:153:in `block in sync_workers' [----] E, [2018-11-20T10:41:05.333570 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:153:in `times' [----] E, [2018-11-20T10:41:05.333664 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_worker.rb:153:in `sync_workers' [----] E, [2018-11-20T10:41:05.333754 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:53:in `block in sync_workers' [----] E, [2018-11-20T10:41:05.333856 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `each' [----] E, [2018-11-20T10:41:05.333946 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:50:in `sync_workers' [----] E, [2018-11-20T10:41:05.334034 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server/worker_management/monitor.rb:22:in `monitor_workers' [----] E, [2018-11-20T10:41:05.334137 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:343:in `block in monitor' [----] E, [2018-11-20T10:41:05.334225 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-3707a9a85a9b/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' [----] E, [2018-11-20T10:41:05.334312 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-3707a9a85a9b/lib/gems/pending/util/extensions/miq-benchmark.rb:28:in `realtime_block' [----] E, [2018-11-20T10:41:05.334404 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:343:in `monitor' [----] E, [2018-11-20T10:41:05.334490 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block (2 levels) in monitor_loop' [----] E, [2018-11-20T10:41:05.334578 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-3707a9a85a9b/lib/gems/pending/util/extensions/miq-benchmark.rb:11:in `realtime_store' [----] E, [2018-11-20T10:41:05.334663 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /opt/rh/cfme-gemset/bundler/gems/cfme-gems-pending-3707a9a85a9b/lib/gems/pending/util/extensions/miq-benchmark.rb:35:in `realtime_block' [----] E, [2018-11-20T10:41:05.336123 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:382:in `block in monitor_loop' [----] E, [2018-11-20T10:41:05.336207 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:381:in `loop' [----] E, [2018-11-20T10:41:05.336296 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:381:in `monitor_loop' [----] E, [2018-11-20T10:41:05.336377 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/app/models/miq_server.rb:244:in `start' [----] E, [2018-11-20T10:41:05.336466 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/lib/workers/evm_server.rb:27:in `start' [----] E, [2018-11-20T10:41:05.336552 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/lib/workers/evm_server.rb:48:in `start' [----] E, [2018-11-20T10:41:05.336639 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQExtract.new /var/www/miq/vmdb/lib/workers/bin/evm_server.rb:4:in `<main>' [----] I, [2018-11-20T10:41:05.372519 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue.put) Message id: [1030438], id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_message_1542728465], Command: [Job.update_message], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: ["de21c3f5-8882-48bc-a71f-64fa8acff44b", "Scanning completed."] [----] I, [2018-11-20T10:41:05.373730 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#scan_via_miq_vm) Starting: Sending scan summary to server. TaskId:[de21c3f5-8882-48bc-a71f-64fa8acff44b] VM:[haproxy] [----] E, [2018-11-20T10:41:05.373853 #1652:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#scan_via_miq_vm) ScanMetadata error status:[16]: message:[Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.]] [----] I, [2018-11-20T10:41:05.382590 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#save_metadata_op) target [50c00c95-f701-457a-b9a7-54ac3a516d67], job [de21c3f5-8882-48bc-a71f-64fa8acff44b] enter [----] I, [2018-11-20T10:41:05.382793 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#save_metadata_op) target [50c00c95-f701-457a-b9a7-54ac3a516d67] found target object id [174], job [de21c3f5-8882-48bc-a71f-64fa8acff44b] [----] I, [2018-11-20T10:41:05.410460 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue.put) Message id: [1030439], id: [], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [174], Instance id: [], Task id: [de21c3f5-8882-48bc-a71f-64fa8acff44b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [387 bytes], Args: [] [----] I, [2018-11-20T10:41:05.410585 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#save_metadata_op) target [50c00c95-f701-457a-b9a7-54ac3a516d67] data put on queue, job [de21c3f5-8882-48bc-a71f-64fa8acff44b] [----] I, [2018-11-20T10:41:05.410854 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager::Vm#scan_via_miq_vm) Completed: Sending scan summary to server. TaskId:[de21c3f5-8882-48bc-a71f-64fa8acff44b] target:[haproxy] [----] I, [2018-11-20T10:41:05.410959 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MiqVm.unmount called. [----] I, [2018-11-20T10:41:05.456481 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) Snapshot remove pre-check skipped for Datastore <ESXi1-DS> due to Percentage:<>. Space Free:<399146745856> Disk size:<42949672960> [----] I, [2018-11-20T10:41:06.479647 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) VolMgrPlatformSupportLinux.postMount: VM snapshot [36-snapshot-13] removed [----] I, [2018-11-20T10:41:06.480320 #1652:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [1030432], State: [ok], Delivered in [7.307484622] seconds [----] I, [2018-11-20T10:41:08.542018 #6807:af5118] INFO -- : MIQ(MiqServer#populate_queue_messages) Fetched 3 miq_queue rows for queue_name=generic, wcount=4, priority=200 [----] I, [2018-11-20T10:41:09.469901 #15253:af5118] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1030438], MiqWorker id: [5753], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [], Instance id: [], Task id: [job_message_1542728465], Command: [Job.update_message], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [], Args: ["de21c3f5-8882-48bc-a71f-64fa8acff44b", "Scanning completed."], Dequeued in: [4.105071635] seconds [----] I, [2018-11-20T10:41:09.470186 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [1030438], Delivering... [----] I, [2018-11-20T10:41:09.473397 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) JOB([de21c3f5-8882-48bc-a71f-64fa8acff44b] Message update: [Scanning completed.] [----] I, [2018-11-20T10:41:09.501831 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [1030438], State: [ok], Delivered in [0.031656655] seconds [----] I, [2018-11-20T10:41:09.516368 #15253:af5118] INFO -- : MIQ(MiqGenericWorker::Runner#get_message_via_drb) Message id: [1030439], MiqWorker id: [5753], Zone: [default], Role: [smartstate], Server: [], Ident: [generic], Target id: [174], Instance id: [], Task id: [de21c3f5-8882-48bc-a71f-64fa8acff44b], Command: [VmOrTemplate.save_metadata], Timeout: [600], Priority: [100], State: [dequeue], Deliver On: [], Data: [387 bytes], Args: [], Dequeued in: [4.109992146] seconds [----] I, [2018-11-20T10:41:09.516543 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#deliver) Message id: [1030439], Delivering... [----] I, [2018-11-20T10:41:09.526899 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmOrTemplate.save_metadata) TaskId = [de21c3f5-8882-48bc-a71f-64fa8acff44b] [----] I, [2018-11-20T10:41:09.542402 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#process_data) starting... [----] I, [2018-11-20T10:41:09.562459 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#process_data) Document=summary [----] I, [2018-11-20T10:41:09.563325 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#process_data) sending :synchronize [----] I, [2018-11-20T10:41:09.643814 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#scanning) . [----] I, [2018-11-20T10:41:09.680697 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(ManageIQ::Providers::Vmware::InfraManager#with_provider_connection) Connecting through ManageIQ::Providers::Vmware::InfraManager: [VCenter] [----] I, [2018-11-20T10:41:09.710803 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [VCenter] [Broker] Connecting with address: [vcenter.lab.int], userid: [administrator]... [----] I, [2018-11-20T10:41:09.737757 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [VCenter] [Broker] vcenter.lab.int is VC, API version: 6.7 [----] I, [2018-11-20T10:41:09.737861 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqFaultTolerantVim._connect) EMS: [VCenter] [Broker] Connected Cookie#domain returns dot-less domain name now. Use Cookie#dot_domain if you need "." at the beginning. [----] I, [2018-11-20T10:41:10.557669 #9802:af5118] INFO -- : MIQ(MiqScheduleWorker::Runner#do_work) Number of scheduled items to be processed: 1. [----] I, [2018-11-20T10:41:10.570930 #9802:af5118] INFO -- : MIQ(MiqScheduleWorker::Runner#reload_schedules) Reloading schedule: [rss_newest_vms] with id: [20] [----] I, [2018-11-20T10:41:10.571109 #9802:af5118] INFO -- : MIQ(MiqScheduleWorker::Runner#rufus_remove_schedules_by_tag) Unscheduling 1 jobs with tag: miq_schedules_20 [----] I, [2018-11-20T10:41:10.574492 #9802:af5118] INFO -- : MIQ(MiqSchedule#next_interval_time) sch_start_time: 2018-08-03 00:00:00 UTC [----] I, [2018-11-20T10:41:10.574939 #9802:af5118] INFO -- : MIQ(MiqSchedule#next_interval_time) next_time: 2018-11-20 16:00:00 UTC [----] I, [2018-11-20T10:41:10.576771 #9802:af5118] INFO -- : MIQ(MiqSchedule#rufus_schedule_opts) Schedule [rss_newest_vms] schedule updated to run at 2018-11-20 16:00:00 UTC with interval 3600 [----] I, [2018-11-20T10:41:10.577141 #9802:af5118] INFO -- : MIQ(MiqScheduleWorker::Runner#reload_schedules) Reloading schedule: [rss_newest_hosts] with id: [19] [----] I, [2018-11-20T10:41:10.577287 #9802:af5118] INFO -- : MIQ(MiqScheduleWorker::Runner#rufus_remove_schedules_by_tag) Unscheduling 1 jobs with tag: miq_schedules_19 [----] I, [2018-11-20T10:41:10.580096 #9802:af5118] INFO -- : MIQ(MiqSchedule#next_interval_time) sch_start_time: 2018-08-03 00:00:00 UTC [----] I, [2018-11-20T10:41:10.580517 #9802:af5118] INFO -- : MIQ(MiqSchedule#next_interval_time) next_time: 2018-11-20 16:00:00 UTC [----] I, [2018-11-20T10:41:10.582263 #9802:af5118] INFO -- : MIQ(MiqSchedule#rufus_schedule_opts) Schedule [rss_newest_hosts] schedule updated to run at 2018-11-20 16:00:00 UTC with interval 3600 [----] I, [2018-11-20T10:41:10.737613 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue.put) Message id: [1030440], 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::Vmware::InfraManager::Vm", :object_id=>174, :attrs=>{:event_type=>"vm_scan_abort", "VmOrTemplate::vm"=>174, :vm_id=>174, "Host::host"=>14, :host_id=>14, "MiqEvent::miq_event"=>41584, :miq_event_id=>41584, "EventStream::event_stream"=>41584, :event_stream_id=>41584}, :instance_name=>"Event", :user_id=>1, :miq_group_id=>2, :tenant_id=>1, :automate_message=>nil}] [----] E, [2018-11-20T10:41:10.737784 #15253:af5118] ERROR -- : Q-task_id([job_dispatcher]) MIQ(VmScan#process_abort) job aborting, Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] [----] I, [2018-11-20T10:41:10.770573 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#process_finished) job finished, Unable to mount filesystem. Reason:[ERROR: VixDiskLib.connect() Unable to determine port used by VixDiskLib Server.] [----] I, [2018-11-20T10:41:10.779206 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmScan#dispatch_finish) Dispatch Status is 'finished' [----] I, [2018-11-20T10:41:10.790419 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(VmOrTemplate.save_metadata) Summary XML received. [<summary created_on='1542728463' display_time='2018-11-20T15:41:03Z' taskid='de21c3f5-8882-48bc-a71f-] [----] I, [2018-11-20T10:41:10.790681 #15253:af5118] INFO -- : Q-task_id([job_dispatcher]) MIQ(MiqQueue#delivered) Message id: [1030439], State: [ok], Delivered in [1.274152888] seconds [----] I, [2018-11-20T10:41:10.902333 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#queue_event) EMS [vcenter.lab.int] as [administrator] Queueing event [GeneralUserEvent] chainId [180961] [----] I, [2018-11-20T10:41:10.928704 #9759:af5118] INFO -- : MIQ(MiqQueue.put) Message id: [1030441], id: [], Zone: [default], Role: [event], Server: [], Ident: [ems], Target id: [6], Instance id: [], Task id: [], Command: [EmsEvent.add], Timeout: [600], Priority: [100], State: [ready], Deliver On: [], Data: [], Args: [{:event_type=>"GeneralUserEvent", :chain_id=>"180961", :is_task=>false, :source=>"VC", :message=>"User logged event: EVM SmartState Analysis completed for VM [haproxy]", :timestamp=>"2018-11-20T15:41:09.823472Z", :full_data=>{"key"=>"180961", "chainId"=>"180961", "createdTime"=>"2018-11-20T15:41:09.823472Z", "userName"=>"VSPHERE.LOCAL\\Administrator", "datacenter"=>{"name"=>"Datacenter", "datacenter"=>"datacenter-2"}, "computeResource"=>{"name"=>"Internal", "computeResource"=>"domain-c7"}, "host"=>{"name"=>"esxi1.lab.int", "host"=>"host-10"}, "vm"=>{"name"=>"haproxy", "vm"=>"vm-107", "path"=>"[ESXi1-DS] haproxy/haproxy.vmx", "uuid"=>"4233d112-6e77-cf90-3885-4d19b2d1912b"}, "fullFormattedMessage"=>"User logged event: EVM SmartState Analysis completed for VM [haproxy]", "changeTag"=>"", "message"=>"EVM SmartState Analysis completed for VM [haproxy]", "eventType"=>"GeneralUserEvent"}, :ems_id=>6, :username=>"VSPHERE.LOCAL\\Administrator", :vm_ems_ref=>"vm-107", :vm_name=>"haproxy", :vm_location=>"[ESXi1-DS] haproxy/haproxy.vmx", :vm_uid_ems=>"4233d112-6e77-cf90-3885-4d19b2d1912b", :host_name=>"esxi1.lab.int", :host_ems_ref=>"host-10"}] [----] I, [2018-11-20T10:41:14.933963 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [vcenter.lab.int] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [180962] [----] I, [2018-11-20T10:41:14.934207 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [vcenter.lab.int] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [180963] [----] I, [2018-11-20T10:41:14.934361 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [vcenter.lab.int] as [administrator] Skipping caught event [EventEx]-[com.vmware.vc.VmDiskConsolidatedEvent] chainId [180964] [----] I, [2018-11-20T10:41:14.934509 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [vcenter.lab.int] as [administrator] Skipping caught event [UserLoginSessionEvent] chainId [180965] [----] I, [2018-11-20T10:41:14.934637 #9759:af5118] INFO -- : MIQ(ManageIQ::Providers::Vmware::InfraManager::EventCatcher::Runner#filtered?) EMS [vcenter.lab.int] as [administrator] Skipping caught event [UserLogoutSessionEvent] chainId [180966]