2018-07-02 19:22:02,316+0800 INFO  (libvirt/events) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') CPU running: onResume (vm:5742)

2018-07-02 19:22:02,586+0800 INFO  (vm/0febbdb6) [root] /usr/libexec/vdsm/hooks/after_vm_start/50_openstacknet: rc=0 err= (hooks:109)

2018-07-02 19:22:02,807+0800 INFO  (vm/0febbdb6) [root] /usr/libexec/vdsm/hooks/after_vm_start/openstacknet_utils.py: rc=0 err= (hooks:109)

2018-07-02 19:22:02,824+0800 WARN  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Found unknown drive: {'alias': 'ide0-1-0', 'readonly': 'True', 'iface': 'ide', 'name': 'hdc', 'address': {'bus': '1', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'cdrom', 'path': '/rhev/data-center/mnt/192.168.100.59:_exports_iso/6ff100c0-d08d-4504-832d-53876bf97349/images/11111111-1111-1111-1111-111111111111/CentOS-7-x86_64-Minimal-1804.iso', 'type': 'disk', 'bootOrder': '2'} (storage:217)

2018-07-02 19:22:02,824+0800 WARN  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Found unknown drive: {'alias': 'scsi0-0-0', 'readonly': 'False', 'iface': 'ide', 'name': 'sda', 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '0'}, 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.100.59:_exports_vmstorage/461517fd-986a-4b39-9b84-5fd54ef06967/images/1ea736ad-164c-4ac2-a6ce-9b8e6eceefde/b7f8140f-3a34-40fd-9fec-878df3d159a4', 'type': 'disk', 'bootOrder': '1'} (storage:217)

2018-07-02 19:22:02,825+0800 WARN  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Found unknown drive: {'alias': 'scsi0-0-1', 'readonly': 'False', 'iface': 'ide', 'name': 'sdb', 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '1'}, 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.100.241:_exports_vmstorage/c5a790c2-2885-4220-b803-35e4a40ecef6/images/183b3ace-64e1-49cf-a214-b5462f989171/36ea0af6-b681-4923-bf70-6b51717f372d', 'type': 'disk'} (storage:217)

2018-07-02 19:22:02,825+0800 WARN  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Found unknown drive: {'alias': 'scsi0-0-2', 'readonly': 'False', 'iface': 'ide', 'name': 'sdc', 'address': {'bus': '0', 'controller': '0', 'type': 'drive', 'target': '0', 'unit': '2'}, 'device': 'disk', 'path': '/rhev/data-center/mnt/192.168.100.241:_exports_vmstorage/c5a790c2-2885-4220-b803-35e4a40ecef6/images/5866d66c-0756-4544-af6a-95f5aed9312b/1751cd16-fd89-4441-b847-45169689c9a7', 'type': 'disk'} (storage:217)

2018-07-02 19:22:02,840+0800 INFO  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Starting connection (guestagent:244)

2018-07-02 19:22:02,841+0800 ERROR (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') Failed to connect to guest agent channel (vm:2415)

Traceback (most recent call last):

  File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 2413, in _vmDependentInit

    self.guestAgent.start()

  File "/usr/lib/python2.7/site-packages/vdsm/virt/guestagent.py", line 245, in start

    self._prepare_socket()

  File "/usr/lib/python2.7/site-packages/vdsm/virt/guestagent.py", line 287, in _prepare_socket

    supervdsm.getProxy().prepareVmChannel(self._socketName)

  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm.py", line 53, in __call__

    return callMethod()

  File "/usr/lib/python2.7/site-packages/vdsm/supervdsm.py", line 51, in <lambda>

    **kwargs)

  File "<string>", line 2, in prepareVmChannel

  File "/usr/lib64/python2.7/multiprocessing/managers.py", line 773, in _callmethod

    raise convert_to_error(kind, result)

OSError: [Errno 2] No such file or directory: '/var/lib/libvirt/qemu/channels/0febbdb6-9b90-4052-8169-4f6792d99d1e.com.redhat.rhevm.vdsm'

2018-07-02 19:22:02,843+0800 INFO  (vm/0febbdb6) [virt.vm] (vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e') CPU running: domain initialization (vm:5742)

2018-07-02 19:22:02,910+0800 INFO  (jsonrpc/6) [api.host] START dumpxmls(vmList=[u'0febbdb6-9b90-4052-8169-4f6792d99d1e']) from=::ffff:192.168.100.59,60612 (api:46)

2018-07-02 19:22:09,292+0800 ERROR (periodic/39) [virt.vmstats] VM metrics collection failed (vmstats:260)

Traceback (most recent call last):

  File "/usr/lib/python2.7/site-packages/vdsm/virt/vmstats.py", line 217, in send_metrics

    diskinfo['readOps']

KeyError: 'readOps'

2018-07-02 19:22:09,813+0800 INFO  (jsonrpc/2) [api.host] START getStats() from=::ffff:192.168.100.59,60612 (api:46)

2018-07-02 19:22:09,816+0800 INFO  (jsonrpc/2) [vdsm.api] START repoStats(domains=()) from=::ffff:192.168.100.59,60612, task_id=36236da1-3586-4324-a842-71aafb37d124 (api:46)

2018-07-02 19:22:09,816+0800 INFO  (jsonrpc/2) [vdsm.api] FINISH repoStats return={u'6ff100c0-d08d-4504-832d-53876bf97349': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000776933', 'lastCheck': '6.6', 'valid': True}, u'5a50d04c-4d39-4249-8fc6-24df9bd096b0': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000358834', 'lastCheck': '4.1', 'valid': True}, u'c5a790c2-2885-4220-b803-35e4a40ecef6': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000328361', 'lastCheck': '3.3', 'valid': True}, u'461517fd-986a-4b39-9b84-5fd54ef06967': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000412804', 'lastCheck': '5.7', 'valid': True}} from=::ffff:192.168.100.59,60612, task_id=36236da1-3586-4324-a842-71aafb37d124 (api:52)

2018-07-02 19:22:09,831+0800 INFO  (periodic/39) [vdsm.api] START repoStats(domains=()) from=internal, task_id=b4dcd456-df92-4270-92be-d73d7e7127f9 (api:46)

2018-07-02 19:22:09,832+0800 INFO  (periodic/39) [vdsm.api] FINISH repoStats return={u'6ff100c0-d08d-4504-832d-53876bf97349': {'code': 0, 'actual': True, 'version': 0, 'acquired': True, 'delay': '0.000776933', 'lastCheck': '6.6', 'valid': True}, u'5a50d04c-4d39-4249-8fc6-24df9bd096b0': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000358834', 'lastCheck': '4.1', 'valid': True}, u'c5a790c2-2885-4220-b803-35e4a40ecef6': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000328361', 'lastCheck': '3.3', 'valid': True}, u'461517fd-986a-4b39-9b84-5fd54ef06967': {'code': 0, 'actual': True, 'version': 4, 'acquired': True, 'delay': '0.000412804', 'lastCheck': '5.7', 'valid': True}} from=internal, task_id=b4dcd456-df92-4270-92be-d73d7e7127f9 (api:52)

2018-07-02 19:22:08,079+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] START, IsoPrefixVDSCommand(HostName = tchypnode1.ecr.com, VdsAndPoolIDVDSParametersBase:{hostId='7902d7f8-348e-426e-a3c3-399d08b0eb1e', storagePoolId='5b0f6949-02d6-00bf-008b-000000000167'}), log id: 3d66a9a0

2018-07-02 19:22:08,079+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.IsoPrefixVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] FINISH, IsoPrefixVDSCommand, return: /rhev/data-center/mnt/192.168.100.59:_exports_iso/6ff100c0-d08d-4504-832d-53876bf97349/images/11111111-1111-1111-1111-111111111111, log id: 3d66a9a0

2018-07-02 19:22:08,087+08 INFO  [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] START, CreateVDSCommand( CreateVDSCommandParameters:{hostId='7902d7f8-348e-426e-a3c3-399d08b0eb1e', vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e', vm='VM [badvm-avodev-controller]'}), log id: 54fa1fca

2018-07-02 19:22:08,090+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] START, CreateBrokerVDSCommand(HostName = tchypnode1.ecr.com, CreateVDSCommandParameters:{hostId='7902d7f8-348e-426e-a3c3-399d08b0eb1e', vmId='0febbdb6-9b90-4052-8169-4f6792d99d1e', vm='VM [badvm-avodev-controller]'}), log id: 54926511

2018-07-02 19:22:08,096+08 INFO  [org.ovirt.engine.core.vdsbroker.builder.vminfo.VmInfoBuilderImpl] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] Bootable disk '1ea736ad-164c-4ac2-a6ce-9b8e6eceefde' set to index '0'

2018-07-02 19:22:08,130+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] VM <?xml version="1.0" encoding="UTF-8"?><domain type="kvm" xmlns:ovirt-tune="http://ovirt.org/vm/tune/1.0" xmlns:ovirt-vm="http://ovirt.org/vm/1.0">

  <name>badvm-avodev-controller</name>

  <uuid>0febbdb6-9b90-4052-8169-4f6792d99d1e</uuid>

  <memory>8388608</memory>

  <currentMemory>8388608</currentMemory>

  <maxMemory slots="16">33554432</maxMemory>

  <vcpu current="4">16</vcpu>

  <sysinfo type="smbios">

    <system>

      <entry name="manufacturer">oVirt</entry>

      <entry name="product">OS-NAME:</entry>

      <entry name="version">OS-VERSION:</entry>

      <entry name="serial">HOST-SERIAL:</entry>

      <entry name="uuid">0febbdb6-9b90-4052-8169-4f6792d99d1e</entry>

    </system>

  </sysinfo>

  <clock offset="variable" adjustment="0">

    <timer name="rtc" tickpolicy="catchup"/>

    <timer name="pit" tickpolicy="delay"/>

    <timer name="hpet" present="no"/>

  </clock>

  <features>

    <acpi/>

  </features>

  <cpu match="exact">

    <model>Nehalem</model>

    <topology cores="1" threads="1" sockets="16"/>

    <numa>

      <cell cpus="0,1,2,3" memory="8388608"/>

    <numa>

      <cell cpus="0,1,2,3" memory="8388608"/>

    </numa>

  </cpu>

  <cputune/>

  <devices>

    <input type="tablet" bus="usb"/>

    <channel type="unix">

      <target type="virtio" name="ovirt-guest-agent.0"/>

      <source mode="bind" path="/var/lib/libvirt/qemu/channels/0febbdb6-9b90-4052-8169-4f6792d99d1e.ovirt-guest-agent.0"/>

    </channel>

    <channel type="unix">

      <target type="virtio" name="org.qemu.guest_agent.0"/>

      <source mode="bind" path="/var/lib/libvirt/qemu/channels/0febbdb6-9b90-4052-8169-4f6792d99d1e.org.qemu.guest_agent.0"/>

    </channel>

    <controller type="usb" model="piix3-uhci" index="0">

      <address bus="0x00" domain="0x0000" function="0x2" slot="0x01" type="pci"/>

    </controller>

    <memballoon model="virtio">

      <stats period="5"/>

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>

    </memballoon>

    <controller type="ide">

      <address bus="0x00" domain="0x0000" function="0x1" slot="0x01" type="pci"/>

    </controller>

    <controller type="scsi" model="virtio-scsi" index="0"/>

    <controller type="scsi" index="0">

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x05" type="pci"/>

    </controller>

    <graphics type="vnc" port="-1" autoport="yes" passwd="*****" passwdValidTo="1970-01-01T00:00:01" keymap="en-us">

      <listen type="network" network="vdsm-ovirtmgmt"/>

    <graphics type="vnc" port="-1" autoport="yes" passwd="*****" passwdValidTo="1970-01-01T00:00:01" keymap="en-us">

      <listen type="network" network="vdsm-ovirtmgmt"/>

    </graphics>

    <video>

      <model type="vga" vram="16384" heads="1"/>

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x02" type="pci"/>

    </video>

    <rng model="virtio">

      <backend model="random">/dev/urandom</backend>

    </rng>

    <controller type="virtio-serial" index="0" ports="16">

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/>

    </controller>

    <interface type="bridge">

      <model type="virtio"/>

      <link state="up"/>

      <source bridge="ovirtmgmt"/>

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>

      <mac address="00:1a:4a:16:01:f5"/>

      <filterref filter="vdsm-no-mac-spoofing"/>

      <bandwidth/>

    </interface>

    <interface type="bridge">

      <model type="virtio"/>

      <link state="up"/>

      <source bridge="ovirtmgmt"/>

      <address bus="0x00" domain="0x0000" function="0x0" slot="0x07" type="pci"/>

      <mac address="00:1a:4a:16:01:f6"/>

      <filterref filter="vdsm-no-mac-spoofing"/>

      <bandwidth/>

    </interface>

      <bandwidth/>

    </interface>

    <disk type="file" device="cdrom" snapshot="no">

      <driver name="qemu" type="raw" error_policy="report"/>

      <source file="/rhev/data-center/mnt/192.168.100.59:_exports_iso/6ff100c0-d08d-4504-832d-53876bf97349/images/11111111-1111-1111-1111-111111111111/CentOS-7-x86_64-Minimal-1804.iso" startupPolicy="optional"/>

      <target dev="hdc" bus="ide"/>

      <readonly/>

      <address bus="1" controller="0" unit="0" type="drive" target="0"/>

      <boot order="2"/>

    </disk>

    <disk snapshot="no" type="file" device="disk">

      <target dev="sda" bus="scsi"/>

      <source file="/rhev/data-center/5b0f6949-02d6-00bf-008b-000000000167/461517fd-986a-4b39-9b84-5fd54ef06967/images/1ea736ad-164c-4ac2-a6ce-9b8e6eceefde/b7f8140f-3a34-40fd-9fec-878df3d159a4"/>

      <driver name="qemu" io="threads" type="qcow2" error_policy="stop" cache="none"/>

      <address bus="0" controller="0" unit="0" type="drive" target="0"/>

      <boot order="1"/>

      <serial>1ea736ad-164c-4ac2-a6ce-9b8e6eceefde</serial>

    </disk>

    <disk snapshot="no" type="file" device="disk">

      <target dev="sdb" bus="scsi"/>

      <source file="/rhev/data-center/5b0f6949-02d6-00bf-008b-000000000167/c5a790c2-2885-4220-b803-35e4a40ecef6/images/183b3ace-64e1-49cf-a214-b5462f989171/36ea0af6-b681-4923-bf70-6b51717f372d"/>

      <driver name="qemu" io="threads" type="qcow2" error_policy="stop" cache="none"/>

      <address bus="0" controller="0" unit="1" type="drive" target="0"/>

      <serial>183b3ace-64e1-49cf-a214-b5462f989171</serial>

    </disk>

    <disk snapshot="no" type="file" device="disk">

      <target dev="sdc" bus="scsi"/>

    <disk snapshot="no" type="file" device="disk">

      <target dev="sdc" bus="scsi"/>

      <source file="/rhev/data-center/5b0f6949-02d6-00bf-008b-000000000167/c5a790c2-2885-4220-b803-35e4a40ecef6/images/5866d66c-0756-4544-af6a-95f5aed9312b/1751cd16-fd89-4441-b847-45169689c9a7"/>

      <driver name="qemu" io="threads" type="qcow2" error_policy="stop" cache="none"/>

      <address bus="0" controller="0" unit="2" type="drive" target="0"/>

      <serial>5866d66c-0756-4544-af6a-95f5aed9312b</serial>

    </disk>

  </devices>

  <pm>

    <suspend-to-disk enabled="no"/>

    <suspend-to-mem enabled="no"/>

  </pm>

  <os>

    <type arch="x86_64" machine="pc-i440fx-2.5">hvm</type>

    <smbios mode="sysinfo"/>

  </os>

  <metadata>

    <ovirt-tune:qos/>

    <ovirt-vm:vm>

      <minGuaranteedMemoryMb type="int">4096</minGuaranteedMemoryMb>

      <clusterVersion>4.2</clusterVersion>

      <ovirt-vm:custom/>

      <ovirt-vm:device mac_address="00:1a:4a:16:01:f6">

        <ovirt-vm:custom/>

      </ovirt-vm:device>

      <ovirt-vm:device mac_address="00:1a:4a:16:01:f5">

        <ovirt-vm:custom/>

      </ovirt-vm:device>

      <ovirt-vm:device devtype="disk" name="sdb">

        <ovirt-vm:imageID>183b3ace-64e1-49cf-a214-b5462f989171</ovirt-vm:imageID>

      <ovirt-vm:device devtype="disk" name="sdb">

        <ovirt-vm:imageID>183b3ace-64e1-49cf-a214-b5462f989171</ovirt-vm:imageID>

        <ovirt-vm:poolID>5b0f6949-02d6-00bf-008b-000000000167</ovirt-vm:poolID>

        <ovirt-vm:volumeID>36ea0af6-b681-4923-bf70-6b51717f372d</ovirt-vm:volumeID>

        <ovirt-vm:domainID>c5a790c2-2885-4220-b803-35e4a40ecef6</ovirt-vm:domainID>

      </ovirt-vm:device>

      <ovirt-vm:device devtype="disk" name="sda">

        <ovirt-vm:imageID>1ea736ad-164c-4ac2-a6ce-9b8e6eceefde</ovirt-vm:imageID>

        <ovirt-vm:poolID>5b0f6949-02d6-00bf-008b-000000000167</ovirt-vm:poolID>

        <ovirt-vm:volumeID>b7f8140f-3a34-40fd-9fec-878df3d159a4</ovirt-vm:volumeID>

        <ovirt-vm:domainID>461517fd-986a-4b39-9b84-5fd54ef06967</ovirt-vm:domainID>

      </ovirt-vm:device>

      <ovirt-vm:device devtype="disk" name="sdc">

        <ovirt-vm:imageID>5866d66c-0756-4544-af6a-95f5aed9312b</ovirt-vm:imageID>

        <ovirt-vm:poolID>5b0f6949-02d6-00bf-008b-000000000167</ovirt-vm:poolID>

        <ovirt-vm:volumeID>1751cd16-fd89-4441-b847-45169689c9a7</ovirt-vm:volumeID>

        <ovirt-vm:domainID>c5a790c2-2885-4220-b803-35e4a40ecef6</ovirt-vm:domainID>

      </ovirt-vm:device>

      <launchPaused>false</launchPaused>

      <resumeBehavior>auto_resume</resumeBehavior>

    </ovirt-vm:vm>

  </metadata>

</domain>

2018-07-02 19:22:08,143+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] FINISH, CreateBrokerVDSCommand, log id: 54926511

2018-07-02 19:22:08,144+08 INFO  [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] FINISH, CreateVDSCommand, return: WaitForLaunch, log id: 54fa1fca

2018-07-02 19:22:08,145+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-23066) [2f069134-d730-4ca5-93b7-3925a06234da] Lock freed to object 'EngineLock:{exclusiveLocks='[0febbdb6-9b90-4052-8169-4f6792d99d1e=VM]', sharedLocks=''}'