Attachment 1471407 Details for Bug 1609614 – engine.log

engine.log

engine.log (text/plain), 13.49 KB, created by mxie@redhat.com on 2018-07-30 03:23:49 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: mxie@redhat.com

Created: 2018-07-30 03:23:49 UTC

Size: 13.49 KB

patch

obsolete

>2018-07-26 18:27:18,926+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (default task-24) [7378c991-d65c-40ee-9e34-66647c3e0bec] Lock Acquired to object 'EngineLock:{exclusiveLocks='[846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3=VM]', sharedLocks=''}'
>2018-07-26 18:27:18,938+08 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default task-24) [7378c991-d65c-40ee-9e34-66647c3e0bec] START, IsVmDuringInitiatingVDSCommand( IsVmDuringInitiatingVDSCommandParameters:{vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3'}), log id: 7f7ee7ae
>2018-07-26 18:27:18,938+08 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (default task-24) [7378c991-d65c-40ee-9e34-66647c3e0bec] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 7f7ee7ae
>2018-07-26 18:27:18,963+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] Running command: RunVmCommand internal: false. Entities affected :  ID: 846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3 Type: VMAction group RUN_VM with role type USER
>2018-07-26 18:27:18,980+08 INFO  [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] START, UpdateVmDynamicDataVDSCommand( UpdateVmDynamicDataVDSCommandParameters:{hostId='null', vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3', vmDynamic='org.ovirt.engine.core.common.businessentities.VmDynamic@a3c7ce68'}), log id: 589591cc
>2018-07-26 18:27:18,982+08 INFO  [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] FINISH, UpdateVmDynamicDataVDSCommand, log id: 589591cc
>2018-07-26 18:27:18,984+08 INFO  [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] START, CreateVDSCommand( CreateVDSCommandParameters:{hostId='6d79c0ea-4747-4187-b748-db33ab11bce7', vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3', vm='VM [aacraid-modify-cpu-rhv]'}), log id: 238fe136
>2018-07-26 18:27:18,985+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] START, CreateBrokerVDSCommand(HostName = p2v, CreateVDSCommandParameters:{hostId='6d79c0ea-4747-4187-b748-db33ab11bce7', vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3', vm='VM [aacraid-modify-cpu-rhv]'}), log id: 28484bb5
>2018-07-26 18:27:18,992+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] 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>aacraid-modify-cpu-rhv</name>
>  <uuid>846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3</uuid>
>  <memory>1048576</memory>
>  <currentMemory>1048576</currentMemory>
>  <maxMemory slots="16">4194304</maxMemory>
>  <vcpu current="4">64</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">846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3</entry>
>    </system>
>  </sysinfo>
>  <clock offset="variable" adjustment="3600">
>    <timer name="hypervclock" present="yes"/>
>    <timer name="rtc" tickpolicy="catchup"/>
>    <timer name="pit" tickpolicy="delay"/>
>    <timer name="hpet" present="no"/>
>  </clock>
>  <features>
>    <acpi/>
>    <hyperv>
>      <relaxed state="on"/>
>      <vapic state="on"/>
>      <spinlocks state="on" retries="8191"/>
>    </hyperv>
>  </features>
>  <cpu match="exact">
>    <model>SandyBridge</model>
>    <topology cores="4" threads="1" sockets="16"/>
>    <numa>
>      <cell id="0" cpus="0,1,2,3" memory="1048576"/>
>    </numa>
>  </cpu>
>  <cputune/>
>  <devices>
>    <input type="mouse" bus="ps2"/>
>    <channel type="unix">
>      <target type="virtio" name="ovirt-guest-agent.0"/>
>      <source mode="bind" path="/var/lib/libvirt/qemu/channels/846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3.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/846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3.org.qemu.guest_agent.0"/>
>    </channel>
>    <memballoon model="virtio">
>      <stats period="5"/>
>      <alias name="ua-19b6ea52-808e-4de3-9b46-2955fb59e5dc"/>
>      <address bus="0x00" domain="0x0000" function="0x0" slot="0x06" type="pci"/>
>    </memballoon>
>    <graphics type="spice" port="-1" autoport="yes" passwd="*****" passwdValidTo="1970-01-01T00:00:01" tlsPort="-1">
>      <channel name="main" mode="secure"/>
>      <channel name="inputs" mode="secure"/>
>      <channel name="cursor" mode="secure"/>
>      <channel name="playback" mode="secure"/>
>      <channel name="record" mode="secure"/>
>      <channel name="display" mode="secure"/>
>      <channel name="smartcard" mode="secure"/>
>      <channel name="usbredir" mode="secure"/>
>      <listen type="network" network="vdsm-ovirtmgmt"/>
>    </graphics>
>    <controller type="ide" index="0">
>      <address bus="0x00" domain="0x0000" function="0x1" slot="0x01" type="pci"/>
>    </controller>
>    <video>
>      <model type="qxl" vram="8192" heads="1" ram="65536" vgamem="16384"/>
>      <alias name="ua-8116ded9-d18f-447f-be93-40e8682e7f45"/>
>      <address bus="0x00" domain="0x0000" function="0x0" slot="0x02" type="pci"/>
>    </video>
>    <controller type="usb" model="piix3-uhci" index="0">
>      <address bus="0x00" domain="0x0000" function="0x2" slot="0x01" type="pci"/>
>    </controller>
>    <rng model="virtio">
>      <backend model="random">/dev/urandom</backend>
>      <alias name="ua-8d3a5b7b-3e03-4aef-a81e-7d67e0272c7c"/>
>    </rng>
>    <controller type="virtio-serial" index="0" ports="16">
>      <alias name="ua-c5f54903-f18e-44a9-873f-9b89355391f3"/>
>      <address bus="0x00" domain="0x0000" function="0x0" slot="0x04" type="pci"/>
>    </controller>
>    <channel type="spicevmc">
>      <target type="virtio" name="com.redhat.spice.0"/>
>    </channel>
>    <interface type="bridge">
>      <model type="virtio"/>
>      <link state="up"/>
>      <source bridge="ovirtmgmt"/>
>      <alias name="ua-ed754e44-01c0-452a-ae7f-4306dcb69489"/>
>      <address bus="0x00" domain="0x0000" function="0x0" slot="0x03" type="pci"/>
>      <mac address="d4:ae:52:cc:bf:1a"/>
>      <filterref filter="vdsm-no-mac-spoofing"/>
>      <bandwidth/>
>    </interface>
>    <disk type="file" device="cdrom" snapshot="no">
>      <driver name="qemu" type="raw" error_policy="report"/>
>      <source file="" startupPolicy="optional"/>
>      <target dev="hdc" bus="ide"/>
>      <readonly/>
>      <alias name="ua-837185cc-2c71-4654-b96c-bcbd63335d8a"/>
>      <address bus="1" controller="0" unit="0" type="drive" target="0"/>
>    </disk>
>    <disk snapshot="no" type="file" device="disk">
>      <target dev="vda" bus="virtio"/>
>      <source file="/rhev/data-center/55adaa8a-c2f4-4890-bb16-0ecbef6b9817/6dc5f2ee-aa0d-42db-8ccd-65723207dd4e/images/da648b95-981c-4a62-872f-dfe880b45c3d/171a4a2f-be78-4667-a3c1-8f4c144385e6"/>
>      <driver name="qemu" io="threads" type="raw" error_policy="stop" cache="none"/>
>      <alias name="ua-da648b95-981c-4a62-872f-dfe880b45c3d"/>
>      <address bus="0x00" domain="0x0000" function="0x0" slot="0x05" type="pci"/>
>      <boot order="1"/>
>      <serial>da648b95-981c-4a62-872f-dfe880b45c3d</serial>
>    </disk>
>  </devices>
>  <pm>
>    <suspend-to-disk enabled="no"/>
>    <suspend-to-mem enabled="no"/>
>  </pm>
>  <os>
>    <type arch="x86_64" machine="pc-i440fx-rhel7.5.0">hvm</type>
>    <smbios mode="sysinfo"/>
>  </os>
>  <metadata>
>    <ovirt-tune:qos/>
>    <ovirt-vm:vm>
>      <minGuaranteedMemoryMb type="int">1024</minGuaranteedMemoryMb>
>      <clusterVersion>4.2</clusterVersion>
>      <ovirt-vm:custom/>
>      <ovirt-vm:device mac_address="d4:ae:52:cc:bf:1a">
>        <ovirt-vm:custom/>
>      </ovirt-vm:device>
>      <ovirt-vm:device devtype="disk" name="vda">
>        <ovirt-vm:poolID>55adaa8a-c2f4-4890-bb16-0ecbef6b9817</ovirt-vm:poolID>
>        <ovirt-vm:volumeID>171a4a2f-be78-4667-a3c1-8f4c144385e6</ovirt-vm:volumeID>
>        <ovirt-vm:imageID>da648b95-981c-4a62-872f-dfe880b45c3d</ovirt-vm:imageID>
>        <ovirt-vm:domainID>6dc5f2ee-aa0d-42db-8ccd-65723207dd4e</ovirt-vm:domainID>
>      </ovirt-vm:device>
>      <launchPaused>false</launchPaused>
>      <resumeBehavior>auto_resume</resumeBehavior>
>    </ovirt-vm:vm>
>  </metadata>
></domain>
>
>2018-07-26 18:27:19,002+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateBrokerVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] FINISH, CreateBrokerVDSCommand, log id: 28484bb5
>2018-07-26 18:27:19,007+08 INFO  [org.ovirt.engine.core.vdsbroker.CreateVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] FINISH, CreateVDSCommand, return: WaitForLaunch, log id: 238fe136
>2018-07-26 18:27:19,007+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] Lock freed to object 'EngineLock:{exclusiveLocks='[846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3=VM]', sharedLocks=''}'
>2018-07-26 18:27:19,009+08 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-152435) [7378c991-d65c-40ee-9e34-66647c3e0bec] EVENT_ID: USER_STARTED_VM(153), VM aacraid-modify-cpu-rhv was started by admin@internal-authz (Host: p2v).
>2018-07-26 18:27:20,592+08 INFO  [org.ovirt.engine.core.bll.ConcurrentChildCommandsExecutionCallback] (EE-ManagedThreadFactory-engineScheduled-Thread-17) [69a6ea19-fb26-4599-9fb9-c5dc8b7dc979] Command 'ImportVm' (id: '63862d29-c824-4664-b39b-6d83b9477dda') waiting on child command id: '4ff30a80-3c28-435d-bde8-76465613ce91' type:'CopyImageGroup' to complete
>2018-07-26 18:27:21,649+08 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-12) [] VM '846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3' was reported as Down on VDS '6d79c0ea-4747-4187-b748-db33ab11bce7'(p2v)
>2018-07-26 18:27:21,650+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-12) [] START, DestroyVDSCommand(HostName = p2v, DestroyVmVDSCommandParameters:{hostId='6d79c0ea-4747-4187-b748-db33ab11bce7', vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3', secondsToWait='0', gracefully='false', reason='', ignoreNoVm='true'}), log id: 208d03c8
>2018-07-26 18:27:22,712+08 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ForkJoinPool-1-worker-12) [] FINISH, DestroyVDSCommand, log id: 208d03c8
>2018-07-26 18:27:22,712+08 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-12) [] VM '846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3'(aacraid-modify-cpu-rhv) moved from 'WaitForLaunch' --> 'Down'
>2018-07-26 18:27:22,746+08 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-12) [] EVENT_ID: VM_DOWN_ERROR(119), VM aacraid-modify-cpu-rhv is down with error. Exit message: The name org.fedoraproject.FirewallD1 was not provided by any .service files.
>2018-07-26 18:27:22,746+08 INFO  [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer] (ForkJoinPool-1-worker-12) [] add VM '846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3'(aacraid-modify-cpu-rhv) to rerun treatment
>2018-07-26 18:27:22,748+08 ERROR [org.ovirt.engine.core.vdsbroker.monitoring.VmsMonitoring] (ForkJoinPool-1-worker-12) [] Rerun VM '846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3'. Called from VDS 'p2v'
>2018-07-26 18:27:22,753+08 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-152438) [] EVENT_ID: USER_INITIATED_RUN_VM_FAILED(151), Failed to run VM aacraid-modify-cpu-rhv on Host p2v.
>2018-07-26 18:27:22,756+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-152438) [] Lock Acquired to object 'EngineLock:{exclusiveLocks='[846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3=VM]', sharedLocks=''}'
>2018-07-26 18:27:22,783+08 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152438) [] START, IsVmDuringInitiatingVDSCommand( IsVmDuringInitiatingVDSCommandParameters:{vmId='846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3'}), log id: 6b6f325a
>2018-07-26 18:27:22,783+08 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (EE-ManagedThreadFactory-engine-Thread-152438) [] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 6b6f325a
>2018-07-26 18:27:22,790+08 WARN  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-152438) [] Validation of action 'RunVm' failed for user admin@internal-authz. Reasons: VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,VAR__ACTION__RUN,VAR__TYPE__VM,SCHEDULING_NO_HOSTS
>2018-07-26 18:27:22,791+08 INFO  [org.ovirt.engine.core.bll.RunVmCommand] (EE-ManagedThreadFactory-engine-Thread-152438) [] Lock freed to object 'EngineLock:{exclusiveLocks='[846ed6c9-f0e6-4c99-933f-2cc95b2ed9f3=VM]', sharedLocks=''}'
>2018-07-26 18:27:22,807+08 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-152438) [] EVENT_ID: USER_FAILED_RUN_VM(54), Failed to run VM aacraid-modify-cpu-rhv  (User: admin@internal-authz).
>2018-07-26 18:27:22,812+08 INFO  [org.ovirt.engine.core.bll.ProcessDownVmCommand] (EE-ManagedThreadFactory-engine-Thread-152439) [10e9cc37] Running command: ProcessDownVmCommand internal: true.
>

Actions: View

Attachments on bug 1609614: 1471407 | 1471408 | 1471694