Bug 1651702 - SmartState Analysis fails on VMware Vsphere 6.7
Summary: SmartState Analysis fails on VMware Vsphere 6.7
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: Red Hat CloudForms Management Engine
Classification: Red Hat
Component: SmartState Analysis
Version: 5.9.7
Hardware: x86_64
OS: Linux
high
high
Target Milestone: GA
: 5.11.0
Assignee: Jerry Keselman
QA Contact: Satyajit Bulage
Red Hat CloudForms Documentation
URL:
Whiteboard:
Depends On:
Blocks: 1669626 1669627
TreeView+ depends on / blocked
 
Reported: 2018-11-20 15:52 UTC by Phil Avery
Modified: 2019-12-13 15:09 UTC (History)
7 users (show)

Fixed In Version: 5.11.0.1
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
: 1669626 1669627 (view as bug list)
Environment:
Last Closed: 2019-12-13 15:09:16 UTC
Category: Bug
Cloudforms Team: CFME Core
Target Upstream Version:


Attachments (Terms of Use)

Description Phil Avery 2018-11-20 15:52:17 UTC
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@vsphere.local\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@vsphere.local", :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@vsphere.local]...
[----] 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@vsphere.local] 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@vsphere.local] 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@vsphere.local] 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@vsphere.local] 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@vsphere.local] 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@vsphere.local] Skipping caught event [UserLogoutSessionEvent] chainId [180966]

Comment 3 Satyajit Bulage 2018-11-21 15:20:18 UTC
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.

Comment 6 Rich Oliveri 2018-11-26 15:23:10 UTC
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?

Comment 7 Phil Avery 2018-11-26 15:34:37 UTC
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".

Comment 8 Jerry Keselman 2018-11-26 15:43:09 UTC
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.

Comment 9 Phil Avery 2018-11-26 15:56:05 UTC
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.

Comment 10 Jerry Keselman 2018-11-26 16:12:13 UTC
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.

Comment 11 Jerry Keselman 2018-11-26 20:45:04 UTC
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.

Comment 15 Jerry Keselman 2019-01-25 16:50:29 UTC
https://github.com/ManageIQ/manageiq/pull/18395

Comment 18 Phil Avery 2019-01-26 15:37:24 UTC
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@redhat.com

Comment 19 Satyajit Bulage 2019-05-09 08:14:56 UTC
Able to perform SSA on vSphere 6.7 using VDDK 6.7

Verified Version: 5.11.0.3.20190507174347_a77bd90


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