6:26 a.m.
This is a multi-part message in MIME format.
--------------D695925BEA0466FA018AF9F5
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Hi,
We had a failure for test 006_migrations.migrate_vm on master.
There was a libvirt disruption in the migration src and after that vdsm
reported the migration as failed because the vm already exists which
makes me suspect a split bran case.
The patch reported has nothing to do with this issue and I think we
simply stumbled on a race condition which can cause a split brain.
Please note that there are several metrics related issues reported in
vdsm logs as well.
**
*Link and headline of suspected patches: *
*
*Not related *
Link to Job:
*
**http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/**
*
*
*Link to all logs:*
*
*
**http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/post-006_migrations.py/**
*
*
*(Relevant) error snippet from the log: *
*
*<error>*
**
**Engine: * *
*2017-12-05 06:26:48,546-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engine-Thread-385) [] EVENT_ID:
VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM: vm0, Source:
lago- basic-suite-master-host-1, Destination:
lago-basic-suite-master-host-0). *
*dst:**
**
*2017-12-05 06:26:46,615-0500 WARN (jsonrpc/6) [vds] vm
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists (API:179)
2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH create
error=Virtual machine already exists (api:124)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 117,
in method
ret = func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 180, in create
raise exception.VMExists()
VMExists: Virtual machine already exists
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH create
return={'status': {'message': 'Virtual machine already exists',
'code':
4}} from=::ffff:192.168.201.3,50394 (api:52)
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH
migrationCreate return={'status': {'message': 'Virtual machine
already
exists', 'code': 4}} from=::ffff:192.168.201.3,50394 (api:52)
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer]
RPC call VM.migrationCreate failed (error 4) in 0.03 seconds (__init__:573)
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.201.3,50394 (api:46)
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources (vm:4967)
2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set state to
Powering down when already Down (vm:575)
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') _destroyVmGraceful attempt
#0 (vm:5004)
2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' couldn't be destroyed in libvirt:
Requested operation is not valid: domain is not running (vm
:5025)
2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None) from
=::ffff:192.168.201.3,50394,
task_id=2da93725-5533-4354-a369-751eb44f9ef2 (api:46)
*
**scr *
*
*2017-12-05 06:26:46,623-0500 ERROR (migsrc/b3962e5c) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration destination
error: Virtual machine already exists (migration:290)
*
**disruption on **dst**: *
*
**2017-12-05 06:20:04,662-0500 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer]
RPC call VM.shutdown succeeded in 0.00 seconds (__init__:573)
2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown by QEMU
Guest Agent failed (vm:5097)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5088, in
qemuGuestAgentShutdown
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line
98, in f
ret = attr(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py",
line 126, in wrapper
ret = f(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 512, in
wrapper
return func(inst, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2403, in
shutdownFlags
if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed',
dom=self)
libvirtError: Guest agent is not responding: QEMU guest agent is not
connected
2017-12-05 06:20:04,697-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') block threshold 1 exceeded
on 'vda'
(/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-99ef-49970d3aaf70/images/e6eadbae-ec7a-48f4-
8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df) (drivemonitor:162)
2017-12-05 06:20:04,698-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda' threshold
exceeded (storage:872)
2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host] START
getAllVmStats() from=::1,41118 (api:46)
2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host] FINISH
getAllVmStats return={'status': {'message': 'Done',
'code': 0},
'statsList': (suppressed)} from=::1,41118 (api:52)
2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer]
RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:573)
2017-12-05 06:20:07,466-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying process
disconnected (vm:1024)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources (vm:4967)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None)
from=internal, task_id=9efedf46-d3be-4e41-b7f9-a074ed6344f6 (api:46)
*
*
*</error>*
**
--------------D695925BEA0466FA018AF9F5
Content-Type: text/html; charset=utf-8
Content-Transfer-Encoding: 8bit
<html>
<head>
<meta http-equiv="content-type" content="text/html;
charset=utf-8">
</head>
<body text="#000000" bgcolor="#FFFFFF">
<p>Hi, <br>
</p>
<p>We had a failure for test 006_migrations.migrate_vm on master. </p>
<p>There was a libvirt disruption in the migration src and after
that vdsm reported the migration as failed because the vm already
exists which makes me suspect a split bran case. <br>
</p>
<p>The patch reported has nothing to do with this issue and I think
we simply stumbled on a race condition which can cause a split
brain. <br>
</p>
<p>Please note that there are several metrics related issues
reported in vdsm logs as well. <br>
</p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550">
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
and headline of suspected patches:
</span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">
</span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><b>Not
related </b>
</span></p>
<br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
to Job:</span></p>
<br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"><b><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">Link
to all logs:</span></p>
<br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"><b><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">(Relevant)
error snippet from the log: </span></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><error></span></b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">
</span></b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"><b>Engine:
</b>
</span></b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;">2017-12-05
06:26:48,546-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engine-Thread-385) [] EVENT_ID:
VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM: vm0, Source: lago-
basic-suite-master-host-1, Destination: lago-basic-suite-master-host-0).
</span></b></p>
<br>
<b>dst:</b><b><br>
</b></b></p>
<p><b><span style="font-weight:normal;">2017-12-05
06:26:46,615-0500
WARN (jsonrpc/6) [vds] vm
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists (API:179)<br>
2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH
create error=Virtual machine already exists (api:124)<br>
Traceback (most recent call last):<br>
File "/usr/lib/python2.7/site-packages/vdsm/common/api.py",
line 117, in method<br>
ret = func(*args, **kwargs)<br>
File "/usr/lib/python2.7/site-packages/vdsm/API.py", line
180, in create<br>
raise exception.VMExists()<br>
VMExists: Virtual machine already exists<br>
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt]
FINISH create return={'status': {'message': 'Virtual
machine
already exists', 'code': 4}} from=::ffff:192.168.201.3,50394
(api:52)<br>
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt]
FINISH migrationCreate return={'status': {'message':
'Virtual
machine already exists', 'code': 4}}
from=::ffff:192.168.201.3,50394 (api:52)<br>
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.migrationCreate failed
(error 4) in 0.03 seconds (__init__:573)<br>
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt]
START destroy(gracefulAttempts=1)
from=::ffff:192.168.201.3,50394 (api:46)<br>
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM
resources (vm:4967)<br>
2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set
state to Powering down when already Down (vm:575)<br>
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping
connection (guestagent:435)<br>
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7')
_destroyVmGraceful attempt #0 (vm:5004)<br>
2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' couldn't be destroyed
in libvirt: Requested operation is not valid: domain is not
running (vm<br>
:5025)<br>
2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api]
START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None)
from<br>
=::ffff:192.168.201.3,50394,
task_id=2da93725-5533-4354-a369-751eb44f9ef2 (api:46)<br>
</span></b></p>
<p><b><span style="font-weight:normal;"><b>scr
</b><br>
</span></b></p>
<p><b><span style="font-weight:normal;">2017-12-05
06:26:46,623-0500
ERROR (migsrc/b3962e5c) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration
destination error: Virtual machine already exists
(migration:290)<br>
</span></b></p>
<p><b><span
style="font-weight:normal;"><b>disruption on
</b><b>dst</b><b>:
</b><br>
</span></b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"><b>2017-12-05
06:20:04,662-0500 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer]
RPC call VM.shutdown succeeded in 0.00 seconds (__init__:573)<br>
2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown
by QEMU Guest Agent failed (vm:5097)<br>
Traceback (most recent call last):<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 5088, in qemuGuestAgentShutdown<br>
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)<br>
File
"/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py",
line 98, in f<br>
ret = attr(*args, **kwargs)<br>
File
"/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py",
line 126, in wrapper<br>
ret = f(*args, **kwargs)<br>
File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line
512, in wrapper<br>
return func(inst, *args, **kwargs)<br>
File "/usr/lib64/python2.7/site-packages/libvirt.py", line
2403, in shutdownFlags<br>
if ret == -1: raise libvirtError
('virDomainShutdownFlags() failed', dom=self)<br>
libvirtError: Guest agent is not responding: QEMU guest agent
is not connected<br>
2017-12-05 06:20:04,697-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') block threshold
1 exceeded on 'vda'
(/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-99ef-49970d3aaf70/images/e6eadbae-ec7a-48f4-<br>
8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df)
(drivemonitor:162)<br>
2017-12-05 06:20:04,698-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda'
threshold exceeded (storage:872)<br>
2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host]
START getAllVmStats() from=::1,41118 (api:46)<br>
2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host]
FINISH getAllVmStats return={'status': {'message':
'Done',
'code': 0}, 'statsList': (suppressed)} from=::1,41118
(api:52)<br>
2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7)
[jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded
in 0.00 seconds (__init__:573)<br>
2017-12-05 06:20:07,466-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying
process disconnected (vm:1024)<br>
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM
resources (vm:4967)<br>
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping
connection (guestagent:435)<br>
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [vdsm.api]
START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None)<br>
from=internal, task_id=9efedf46-d3be-4e41-b7f9-a074ed6344f6
(api:46)<br>
</b><br>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><span
style="font-size:11pt;font-family:Arial;color:#000000;background-color:transparent;font-weight:400;font-style:normal;font-variant:normal;text-decoration:none;vertical-align:baseline;white-space:pre-wrap;"></error></span></p>
</b><br class="Apple-interchange-newline">
</p>
<p><br>
</p>
<p><br>
</p>
</body>
</html>
--------------D695925BEA0466FA018AF9F5--
9:26 a.m.
--Apple-Mail=_9A4D98BA-C601-4816-8587-5700FE4F5348
Content-Transfer-Encoding: quoted-printable
Content-Type: text/plain;
charset=utf-8
Milan,
log [1], VM b3962e5c-08e3-444e-910e-ea675fa1a5c7
migration away finished at 2017-12-05 06:26:24,515-0500
incoming migration of the same VM back, at 2017-12-05 06:26:46,614-0500
seems to me the migration away didn=E2=80=99t really properly clean up =
the VM. Milane, can you check that if logs matches? Perhaps orphaned =
libvirt=E2=80=99s xml?
Otherwise it would need reproduction in CI and some more logs=E2=80=A6.
[1] =
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifac=
t/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/po=
st-006_migrations.py/lago-basic-suite-master-host-0/_var_log/vdsm/vdsm.log=
=
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa=
ct/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/p=
ost-006_migrations.py/lago-basic-suite-master-host-0/_var_log/vdsm/vdsm.lo=
g>
On 5 Dec 2017, at 13:26, Dafna Ron <dron(a)redhat.com> wrote:
=20
Hi,=20
We had a failure for test 006_migrations.migrate_vm on master.=20
=20
There was a libvirt disruption in the migration src and after that =
vdsm reported
the migration as failed because the vm already exists =
which makes me suspect a split bran case.=20
The patch reported has nothing to do with this issue and I think we =
simply stumbled on a race condition which can cause a split brain.=20
Please note that there are several metrics related issues reported in
=
vdsm logs as well.=20
=20
Link and headline of suspected patches:=20
=20
Not related=20
=20
Link to Job:
=20
=20
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/ =
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/>
=20
Link to all logs:
=20
=20
=
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifac=
t/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/po=
st-006_migrations.py/ =
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa=
ct/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-master/p=
ost-006_migrations.py/>
=20
(Relevant) error snippet from the log:=20
<error>
=20
Engine:=20
2017-12-05 06:26:48,546-05 ERROR =
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] =
(EE-ManagedThreadFactory-engine-Thread-385) [] EVENT_ID: =
VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM: vm0, Source: =
lago-
basic-suite-master-host-1, Destination: =
lago-basic-suite-master-host-0).
=20
=20
dst:
=20
2017-12-05 06:26:46,615-0500 WARN (jsonrpc/6) [vds] vm =
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists (API:179)
2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH create =
error=3DVirtual machine already exists (api:124)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line =
117,
in method
ret =3D func(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 180, in =
create
raise exception.VMExists()
VMExists: Virtual machine already exists
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH =
create
return=3D{'status': {'message': 'Virtual machine already exists',
=
'code': 4}} from=3D::ffff:192.168.201.3,50394 (api:52)
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH =
migrationCreate return=3D{'status': {'message': 'Virtual machine
already =
exists', 'code': 4}} from=3D::ffff:192.168.201.3,50394 (api:52)
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] =
RPC call VM.migrationCreate failed (error 4) in 0.03
seconds =
(__init__:573)
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt] START =
destroy(gracefulAttempts=3D1) from=3D::ffff:192.168.201.3,50394 (api:46)
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources =
(vm:4967)
2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set state to =
Powering down when already Down (vm:575)
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection =
(guestagent:435)
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') _destroyVmGraceful =
attempt #0 (vm:5004)
2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM =
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' couldn't be destroyed in libvirt: =
Requested operation is not valid: domain is not running (vm
:5025)
2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api] START =
teardownImage(sdUUID=3D'952bb427-b88c-4fbe-99ef-49970d3aaf70', =
spUUID=3D'9dcfeaaf-96b7-4e26-a327-5570e0e39261', =
imgUUID=3D'e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=3DNone) from
=3D::ffff:192.168.201.3,50394, =
task_id=3D2da93725-5533-4354-a369-751eb44f9ef2 (api:46)
=20
scr=20
=20
2017-12-05 06:26:46,623-0500 ERROR (migsrc/b3962e5c) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration destination =
error: Virtual machine already exists (migration:290)
=20
disruption on dst:=20
=20
2017-12-05 06:20:04,662-0500 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] =
RPC call
VM.shutdown succeeded in 0.00 seconds (__init__:573)
2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown by QEMU
=
Guest Agent failed (vm:5097)
Traceback (most recent call last):
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5088, =
in qemuGuestAgentShutdown
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line =
98, in f
ret =3D attr(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", =
line 126, in wrapper
ret =3D f(*args, **kwargs)
File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 512, in =
wrapper
return func(inst, *args, **kwargs)
File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2403, in =
shutdownFlags
if ret =3D=3D -1: raise libvirtError
('virDomainShutdownFlags() =
failed', dom=3Dself)
libvirtError: Guest agent is not responding: QEMU guest agent is not
=
connected
2017-12-05 06:20:04,697-0500 INFO (libvirt/events) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') block threshold 1 =
exceeded on 'vda' =
(/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-99ef-49970d3aaf70/images=
/e6eadbae-ec7a-48f4-
8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df) =
(drivemonitor:162)
2017-12-05 06:20:04,698-0500 INFO (libvirt/events) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda'
threshold =
exceeded (storage:872)
2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host] START =
getAllVmStats() from=3D::1,41118 (api:46)
2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host] FINISH =
getAllVmStats return=3D{'status': {'message': 'Done',
'code': 0}, =
'statsList': (suppressed)} from=3D::1,41118 (api:52)
2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7)
[jsonrpc.JsonRpcServer] =
RPC call Host.getAllVmStats succeeded in 0.00 seconds
(__init__:573)
2017-12-05 06:20:07,466-0500 INFO (libvirt/events) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying process =
disconnected (vm:1024)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources =
(vm:4967)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm] =
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection =
(guestagent:435)
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [vdsm.api] START
=
teardownImage(sdUUID=3D'952bb427-b88c-4fbe-99ef-49970d3aaf70', =
spUUID=3D'9dcfeaaf-96b7-4e26-a327-5570e0e39261', =
imgUUID=3D'e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=3DNone)
from=3Dinternal, task_id=3D9efedf46-d3be-4e41-b7f9-a074ed6344f6 =
(api:46)
=20
=20
</error>
=20
=20
=20
=20
_______________________________________________
Devel mailing list
Devel(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
--Apple-Mail=_9A4D98BA-C601-4816-8587-5700FE4F5348
Content-Transfer-Encoding: quoted-printable
Content-Type: text/html;
charset=utf-8
<html><head><meta http-equiv=3D"Content-Type"
content=3D"text/html =
charset=3Dutf-8"></head><body style=3D"word-wrap: break-word; =
-webkit-nbsp-mode: space; -webkit-line-break: after-white-space;" =
class=3D""><div class=3D"">Milan,</div><div
class=3D""><br =
class=3D""></div>log [1], VM
b3962e5c-08e3-444e-910e-ea675fa1a5c7<div =
class=3D"">migration away finished at 2017-12-05 =
06:26:24,515-0500</div><div class=3D"">incoming migration of the
same VM =
back, at 2017-12-05 06:26:46,614-0500</div><div class=3D""><br =
class=3D""></div><div class=3D"">seems to me the
migration away didn=E2=80=
=99t really properly clean up the VM. Milane, can you check that if logs =
matches? Perhaps orphaned libvirt=E2=80=99s xml?</div><div =
class=3D"">Otherwise it would need reproduction in CI and some more =
logs=E2=80=A6.</div><div class=3D""><br
class=3D""></div><div =
class=3D"">[1] <a =
href=3D"http://jenkins.ovirt.org/job/ovirt-master_change-queue-teste...
/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-m=
aster/post-006_migrations.py/lago-basic-suite-master-host-0/_var_log/vdsm/=
vdsm.log" =
class=3D"">http://jenkins.ovirt.org/job/ovirt-master_change-...
278/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suit=
e-master/post-006_migrations.py/lago-basic-suite-master-host-0/_var_log/vd=
sm/vdsm.log</a></div><div class=3D""><br
class=3D""><div><blockquote =
type=3D"cite" class=3D""><div class=3D"">On 5 Dec
2017, at 13:26, Dafna =
Ron <<a href=3D"mailto:dron@redhat.com" =
class=3D"">dron(a)redhat.com</a>&gt; wrote:</div><br =
class=3D"Apple-interchange-newline"><div class=3D"">
=20
<meta http-equiv=3D"content-type" content=3D"text/html; =
charset=3Dutf-8" class=3D"">
=20
<div text=3D"#000000" bgcolor=3D"#FFFFFF"
class=3D""><p class=3D"">Hi, =
<br class=3D"">
</p><p class=3D"">We had a failure for test =
006_migrations.migrate_vm on master. </p><p
class=3D"">There was a =
libvirt disruption in the migration src and after
that vdsm reported the migration as failed because the vm already
exists which makes me suspect a split bran case. <br class=3D"">
</p><p class=3D"">The patch reported has nothing to do with this
=
issue and I think
we simply stumbled on a race condition which can cause a split
brain. <br class=3D"">
</p><p class=3D"">Please note that there are several metrics
related =
issues
reported in vdsm logs as well. <br class=3D"">
</p><p class=3D""><b style=3D"font-weight:normal;"
=
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"
class=3D"">=
</b></p><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><span style=3D"font-size: 11pt; font-family: Arial; =
background-color: transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">Link and headline of suspected patches:=20
</span></b></div><b style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><p dir=3D"ltr" =
style=3D"line-height:1.38;margin-top:0pt;margin-bottom:0pt;" =
class=3D""><span style=3D"font-size: 11pt; font-family: Arial; =
background-color: transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">
</span></p><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><span style=3D"font-size: 11pt;
=
font-family: Arial; background-color: transparent; font-weight: 400; =
font-style: normal; font-variant-ligatures: normal; font-variant-caps: =
normal; font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D""><b class=3D"">Not related </b>
</span></div>
<br class=3D""><div style=3D"line-height: 1.38;
margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><span style=3D"font-size: 11pt;
=
font-family: Arial; background-color: transparent; font-weight: 400; =
font-style: normal; font-variant-ligatures: normal; font-variant-caps: =
normal; font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">Link to Job:</span></div>
<br class=3D"">
</b><div class=3D""><br
class=3D"webkit-block-placeholder"></div><p =
class=3D""><b style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><b class=3D""><a
class=3D"moz-txt-link-freetext" =
href=3D"http://jenkins.ovirt.org/job/ovirt-master_change-queue-teste...
/">http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/</a>=
</b></b></p><p class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><br class=3D"">
</b></p><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><span style=3D"font-size: 11pt; font-family: Arial; =
background-color: transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">Link to all logs:</span></b></div><b =
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550"
class=3D"">=
<br class=3D"">
</b><div class=3D""><br
class=3D"webkit-block-placeholder"></div><p =
class=3D""><b style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><b class=3D""><a
class=3D"moz-txt-link-freetext" =
href=3D"http://jenkins.ovirt.org/job/ovirt-master_change-queue-teste...
/artifact/exported-artifacts/basic-suit-master-el7/test_logs/basic-suite-m=
aster/post-006_migrations.py/">http://jenkins.ovirt.org/job/ovirt...
hange-queue-tester/4278/artifact/exported-artifacts/basic-suit-master-el7/=
test_logs/basic-suite-master/post-006_migrations.py/</a></b></b></p><p
=
class=3D""><b style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><br class=3D"">
</b></p><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><span style=3D"font-size: 11pt; font-family: Arial; =
background-color: transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">(Relevant) error snippet from the log:
</span></b></div><b =
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><b class=3D""><span
style=3D"font-size: =
11pt; font-family: Arial; background-color: transparent; font-weight: =
400; font-style: normal; font-variant-ligatures: normal; =
font-variant-caps: normal; font-variant-east-asian: normal; =
font-variant-position: normal; text-decoration: none; vertical-align: =
baseline; white-space: pre-wrap;" =
class=3D""><error></span></b></div><div
style=3D"line-height: =
1.38; margin-top: 0pt; margin-bottom: 0pt;" class=3D""><b
class=3D""><span=
style=3D"font-size: 11pt; font-family: Arial; background-color: =
transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D"">
</span></b></div><div style=3D"line-height: 1.38; margin-top:
0pt; =
margin-bottom: 0pt;" class=3D""><b class=3D""><span
style=3D"font-size: =
11pt; font-family: Arial; background-color: transparent; font-weight: =
400; font-style: normal; font-variant-ligatures: normal; =
font-variant-caps: normal; font-variant-east-asian: normal; =
font-variant-position: normal; text-decoration: none; vertical-align: =
baseline; white-space: pre-wrap;" class=3D""><b
class=3D"">Engine: </b>
</span></b></div><div style=3D"line-height: 1.38; margin-top:
0pt; =
margin-bottom: 0pt;" class=3D""><b class=3D""><span
style=3D"font-size: =
11pt; font-family: Arial; background-color: transparent; font-weight: =
400; font-style: normal; font-variant-ligatures: normal; =
font-variant-caps: normal; font-variant-east-asian: normal; =
font-variant-position: normal; text-decoration: none; vertical-align: =
baseline; white-space: pre-wrap;" class=3D"">2017-12-05 06:26:48,546-05
=
ERROR =
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] =
(EE-ManagedThreadFactory-engine-Thread-385) [] EVENT_ID: =
VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM: vm0, Source: =
lago-
basic-suite-master-host-1, Destination: lago-basic-suite-master-host-0).
</span></b></div>
<br class=3D"">
<b class=3D"">dst:</b><b class=3D""><br
class=3D"">
</b></b><div class=3D""><br =
class=3D"webkit-block-placeholder"></div><p
class=3D""><b class=3D""><span=
style=3D"font-weight:normal;" class=3D"">2017-12-05
06:26:46,615-0500
WARN (jsonrpc/6) [vds] vm
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists =
(API:179)<br class=3D"">
2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH
create error=3DVirtual machine already exists (api:124)<br =
class=3D"">
Traceback (most recent call last):<br class=3D"">
File =
"/usr/lib/python2.7/site-packages/vdsm/common/api.py",
line 117, in method<br class=3D"">
ret =3D func(*args, **kwargs)<br
class=3D"">
File "/usr/lib/python2.7/site-packages/vdsm/API.py", =
line
180, in create<br class=3D"">
raise exception.VMExists()<br
class=3D"">
VMExists: Virtual machine already exists<br class=3D"">
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt]
FINISH create return=3D{'status': {'message': 'Virtual
machine
already exists', 'code': 4}} from=3D::ffff:192.168.201.3,50394
(api:52)<br class=3D"">
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt]
FINISH migrationCreate return=3D{'status': {'message': =
'Virtual
machine already exists', 'code': 4}}
from=3D::ffff:192.168.201.3,50394 (api:52)<br class=3D"">
2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.migrationCreate failed
(error 4) in 0.03 seconds (__init__:573)<br class=3D"">
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt]
START destroy(gracefulAttempts=3D1)
from=3D::ffff:192.168.201.3,50394 (api:46)<br class=3D"">
2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM
resources (vm:4967)<br class=3D"">
2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set
state to Powering down when already Down (vm:575)<br
class=3D"">=
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping
connection (guestagent:435)<br class=3D"">
2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7')
_destroyVmGraceful attempt #0 (vm:5004)<br class=3D"">
2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' couldn't be destroyed
in libvirt: Requested operation is not valid: domain is not
running (vm<br class=3D"">
:5025)<br class=3D"">
2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api]
START
teardownImage(sdUUID=3D'952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID=3D'9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID=3D'e6eadbae-ec7a-48f4-8832-64a622a12bef', =
volUUID=3DNone)
from<br class=3D"">
=3D::ffff:192.168.201.3,50394,
task_id=3D2da93725-5533-4354-a369-751eb44f9ef2 (api:46)<br =
class=3D"">
</span></b></p><p class=3D""><b
class=3D""><span =
style=3D"font-weight:normal;" class=3D""><b
class=3D"">scr </b><br =
class=3D"">
</span></b></p><p class=3D""><b
class=3D""><span =
style=3D"font-weight:normal;" class=3D"">2017-12-05
06:26:46,623-0500
ERROR (migsrc/b3962e5c) [virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration
destination error: Virtual machine already exists
(migration:290)<br class=3D"">
</span></b></p><p class=3D""><b
class=3D""><span =
style=3D"font-weight:normal;" class=3D""><b
class=3D"">disruption on =
</b><b class=3D"">dst</b><b class=3D"">:
</b><br class=3D"">
</span></b></p><p class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><b class=3D"">2017-12-05
06:20:04,662-0500 INFO (jsonrpc/3) =
[jsonrpc.JsonRpcServer]
RPC call VM.shutdown succeeded in 0.00 seconds =
(__init__:573)<br class=3D"">
2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown
by QEMU Guest Agent failed (vm:5097)<br class=3D"">
Traceback (most recent call last):<br class=3D"">
File =
"/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 5088, in qemuGuestAgentShutdown<br class=3D"">
=
self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)<br =
class=3D"">
File
"/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py",
line 98, in f<br class=3D"">
ret =3D attr(*args, **kwargs)<br
class=3D"">
File
"/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py",
line 126, in wrapper<br class=3D"">
ret =3D f(*args, **kwargs)<br
class=3D"">
File "/usr/lib/python2.7/site-packages/vdsm/utils.py", =
line
512, in wrapper<br class=3D"">
return func(inst, *args, **kwargs)<br =
class=3D"">
File "/usr/lib64/python2.7/site-packages/libvirt.py", =
line
2403, in shutdownFlags<br class=3D"">
if ret =3D=3D -1: raise libvirtError
('virDomainShutdownFlags() failed', dom=3Dself)<br
class=3D"">
libvirtError: Guest agent is not responding: QEMU guest agent
is not connected<br class=3D"">
2017-12-05 06:20:04,697-0500 INFO (libvirt/events) =
[virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') block =
threshold
1 exceeded on 'vda'
=
(/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-99ef-49970d3aaf70/images=
/e6eadbae-ec7a-48f4-<br class=3D"">
8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df)
(drivemonitor:162)<br class=3D"">
2017-12-05 06:20:04,698-0500 INFO (libvirt/events) =
[virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda'
threshold exceeded (storage:872)<br class=3D"">
2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host]
START getAllVmStats() from=3D::1,41118 (api:46)<br class=3D"">
2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host]
FINISH getAllVmStats return=3D{'status': {'message':
'Done',
'code': 0}, 'statsList': (suppressed)} from=3D::1,41118 =
(api:52)<br class=3D"">
2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7)
[jsonrpc.JsonRpcServer] RPC call Host.getAllVmStats succeeded
in 0.00 seconds (__init__:573)<br class=3D"">
2017-12-05 06:20:07,466-0500 INFO (libvirt/events) =
[virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying
process disconnected (vm:1024)<br class=3D"">
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) =
[virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM
resources (vm:4967)<br class=3D"">
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) =
[virt.vm]
(vmId=3D'b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping
connection (guestagent:435)<br class=3D"">
2017-12-05 06:20:07,469-0500 INFO (libvirt/events) =
[vdsm.api]
START
teardownImage(sdUUID=3D'952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID=3D'9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID=3D'e6eadbae-ec7a-48f4-8832-64a622a12bef', =
volUUID=3DNone)<br class=3D"">
from=3Dinternal, =
task_id=3D9efedf46-d3be-4e41-b7f9-a074ed6344f6
(api:46)<br class=3D"">
</b><br class=3D"">
</b></p><div style=3D"line-height: 1.38; margin-top: 0pt; =
margin-bottom: 0pt;" class=3D""><b
style=3D"font-weight:normal;" =
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D""><span style=3D"font-size: 11pt; font-family: Arial; =
background-color: transparent; font-weight: 400; font-style: normal; =
font-variant-ligatures: normal; font-variant-caps: normal; =
font-variant-east-asian: normal; font-variant-position: normal; =
text-decoration: none; vertical-align: baseline; white-space: pre-wrap;" =
class=3D""></error></span></b></div><b
style=3D"font-weight:normal;"=
id=3D"docs-internal-guid-5859b7a1-269d-3fbb-6886-821a181fd550" =
class=3D"">
</b><br class=3D"Apple-interchange-newline"><div
class=3D""><br =
class=3D"webkit-block-placeholder"></div><p
class=3D""><br class=3D"">
</p><p class=3D""><br class=3D"">
</p>
</div>
_______________________________________________<br class=3D"">Devel =
mailing list<br class=3D""><a href=3D"mailto:Devel@ovirt.org"
=
class=3D"">Devel(a)ovirt.org</a><br =
class=3D"">http://lists.ovirt.org/mailman/listinfo/devel<...
</div><br
class=3D""></div></body></html>=
--Apple-Mail=_9A4D98BA-C601-4816-8587-5700FE4F5348--
10:44 a.m.
Michal Skrivanek <michal.skrivanek(a)redhat.com> writes:
Milan,
log [1], VM b3962e5c-08e3-444e-910e-ea675fa1a5c7
migration away finished at 2017-12-05 06:26:24,515-0500
incoming migration of the same VM back, at 2017-12-05 06:26:46,614-0500
seems to me the migration away didn’t really properly clean up the VM. Milane,
can you check that if logs matches? Perhaps orphaned libvirt’s xml?
It seems that, for unknown reasons, Engine didn’t call Destroy on the
source after the first migration. So while the VM was no longer running
there, it was still present in Vdsm (in Down status) and thus the
following create call was rejected in API.
There are weird messages in engine.log during the first migration such
as the following ones, I don’t know whether they are harmless or not:
2017-12-05 06:26:19,799-05 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer]
(EE-ManagedThreadFactory-engineScheduled-Thread-89) [] VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7'(vm0) was unexpectedly detected as
'MigratingTo' on VDS
'56bf5bdd-8a95-4b7a-9c72-7206d6b59e38'(lago-basic-suite-master-host-1) (expected
on '104bd4da-24bb-4368-a5ca-21a465aca70e')
2017-12-05 06:26:19,799-05 INFO [org.ovirt.engine.core.vdsbroker.monitoring.VmAnalyzer]
(EE-ManagedThreadFactory-engineScheduled-Thread-89) [] VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' is migrating to VDS
'56bf5bdd-8a95-4b7a-9c72-7206d6b59e38'(lago-basic-suite-master-host-1) ignoring it
in the refresh until migration is done
The migration completion event was successfully obtained by Engine:
2017-12-05 06:26:24,542-05 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(ForkJoinPool-1-worker-2) [] EVENT_ID: VM_MIGRATION_DONE(63), Migration completed (VM:
vm0, Source: lago-basic-suite-master-host-0, Destination: lago-basic-suite-master-host-1,
Duration: 6 seconds, Total: 6 seconds, Actual downtime: 73ms)
Otherwise it would need reproduction in CI and some more logs….
[1]
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa...
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa...
> On 5 Dec 2017, at 13:26, Dafna Ron <dron(a)redhat.com> wrote:
>
> Hi,
> We had a failure for test 006_migrations.migrate_vm on master.
>
> There was a libvirt disruption in the migration src and after that vdsm reported the
migration as failed because the vm already exists which makes me suspect a split bran
case.
> The patch reported has nothing to do with this issue and I think we simply stumbled
on a race condition which can cause a split brain.
> Please note that there are several metrics related issues reported in vdsm logs as
well.
>
> Link and headline of suspected patches:
>
> Not related
>
> Link to Job:
>
>
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/>
>
> Link to all logs:
>
>
>
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa...
<http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/artifa...
>
> (Relevant) error snippet from the log:
> <error>
>
> Engine:
> 2017-12-05 06:26:48,546-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engine-Thread-385) [] EVENT_ID:
VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM: vm0, Source: lago-
> basic-suite-master-host-1, Destination: lago-basic-suite-master-host-0).
>
>
> dst:
>
> 2017-12-05 06:26:46,615-0500 WARN (jsonrpc/6) [vds] vm
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists (API:179)
> 2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH create error=Virtual
machine already exists (api:124)
> Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line 117, in
method
> ret = func(*args, **kwargs)
> File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 180, in create
> raise exception.VMExists()
> VMExists: Virtual machine already exists
> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH create
return={'status': {'message': 'Virtual machine already exists',
'code': 4}} from=::ffff:192.168.201.3,50394 (api:52)
> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH migrationCreate
return={'status': {'message': 'Virtual machine already exists',
'code': 4}} from=::ffff:192.168.201.3,50394 (api:52)
> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer] RPC call
VM.migrationCreate failed (error 4) in 0.03 seconds (__init__:573)
> 2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.201.3,50394 (api:46)
> 2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources (vm:4967)
> 2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set state to Powering down
when already Down (vm:575)
> 2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
> 2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') _destroyVmGraceful attempt #0
(vm:5004)
> 2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7' couldn't be destroyed in libvirt:
Requested operation is not valid: domain is not running (vm
> :5025)
> 2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None) from
> =::ffff:192.168.201.3,50394, task_id=2da93725-5533-4354-a369-751eb44f9ef2 (api:46)
>
> scr
>
> 2017-12-05 06:26:46,623-0500 ERROR (migsrc/b3962e5c) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration destination error: Virtual
machine already exists (migration:290)
>
> disruption on dst:
>
> 2017-12-05 06:20:04,662-0500 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer] RPC call
VM.shutdown succeeded in 0.00 seconds (__init__:573)
> 2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown by QEMU Guest Agent
failed (vm:5097)
> Traceback (most recent call last):
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5088, in
qemuGuestAgentShutdown
> self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
> File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py", line 98,
in f
> ret = attr(*args, **kwargs)
> File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py", line
126, in wrapper
> ret = f(*args, **kwargs)
> File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 512, in
wrapper
> return func(inst, *args, **kwargs)
> File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2403, in
shutdownFlags
> if ret == -1: raise libvirtError ('virDomainShutdownFlags() failed',
dom=self)
> libvirtError: Guest agent is not responding: QEMU guest agent is not connected
> 2017-12-05 06:20:04,697-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') block threshold 1 exceeded on
'vda'
(/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-99ef-49970d3aaf70/images/e6eadbae-ec7a-48f4-
> 8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df) (drivemonitor:162)
> 2017-12-05 06:20:04,698-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda' threshold
exceeded (storage:872)
> 2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host] START getAllVmStats()
from=::1,41118 (api:46)
> 2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host] FINISH getAllVmStats
return={'status': {'message': 'Done', 'code': 0},
'statsList': (suppressed)} from=::1,41118 (api:52)
> 2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer] RPC call
Host.getAllVmStats succeeded in 0.00 seconds (__init__:573)
> 2017-12-05 06:20:07,466-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying process disconnected
(vm:1024)
> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources (vm:4967)
> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None)
> from=internal, task_id=9efedf46-d3be-4e41-b7f9-a074ed6344f6 (api:46)
>
>
> </error>
>
>
>
>
> _______________________________________________
> Devel mailing list
> Devel(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/devel
10:54 a.m.
On Mon, Dec 11, 2017 at 6:44 PM, Milan Zamazal <mzamazal(a)redhat.com> wrote:
Michal Skrivanek <michal.skrivanek(a)redhat.com> writes:
> Milan,
>
> log [1], VM b3962e5c-08e3-444e-910e-ea675fa1a5c7
> migration away finished at 2017-12-05 06:26:24,515-0500
> incoming migration of the same VM back, at 2017-12-05 06:26:46,614-0500
>
> seems to me the migration away didn’t really properly clean up the VM.
Milane,
> can you check that if logs matches? Perhaps orphaned libvirt’s xml?
It seems that, for unknown reasons, Engine didn’t call Destroy on the
source after the first migration. So while the VM was no longer running
there, it was still present in Vdsm (in Down status) and thus the
following create call was rejected in API.
There are weird messages in engine.log during the first migration such
as the following ones, I don’t know whether they are harmless or not:
2017-12-05 06:26:19,799-05 INFO [org.ovirt.engine.core.
vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-89)
[] VM 'b3962e5c-08e3-444e-910e-ea675fa1a5c7'(vm0) was unexpectedly
detected as 'MigratingTo' on VDS '56bf5bdd-8a95-4b7a-9c72-
7206d6b59e38'(lago-basic-suite-master-host-1) (expected on
'104bd4da-24bb-4368-a5ca-21a465aca70e')
2017-12-05 06:26:19,799-05 INFO [org.ovirt.engine.core.
vdsbroker.monitoring.VmAnalyzer] (EE-ManagedThreadFactory-engineScheduled-Thread-89)
[] VM 'b3962e5c-08e3-444e-910e-ea675fa1a5c7' is migrating to VDS
'56bf5bdd-8a95-4b7a-9c72-7206d6b59e38'(lago-basic-suite-master-host-1)
ignoring it in the refresh until migration is done
These logs are completely harmless - they only indicate that the VM's
run_on_vds still points to the source host and the hand-over was not done
yet.
The migration completion event was successfully obtained by Engine:
2017-12-05 06:26:24,542-05 INFO [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (ForkJoinPool-1-worker-2) []
EVENT_ID: VM_MIGRATION_DONE(63), Migration completed (VM: vm0, Source:
lago-basic-suite-master-host-0, Destination: lago-basic-suite-master-host-1,
Duration: 6 seconds, Total: 6 seconds, Actual downtime: 73ms)
> Otherwise it would need reproduction in CI and some more logs….
>
> [1]
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/4278/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/
lago-basic-suite-master-host-0/_var_log/vdsm/vdsm.log
> <http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/4278/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/
lago-basic-suite-master-host-0/_var_log/vdsm/vdsm.log>
>
>> On 5 Dec 2017, at 13:26, Dafna Ron <dron(a)redhat.com> wrote:
>>
>> Hi,
>> We had a failure for test 006_migrations.migrate_vm on master.
>>
>> There was a libvirt disruption in the migration src and after that
vdsm reported the migration as failed because the vm already exists which
makes me suspect a split bran case.
>> The patch reported has nothing to do with this issue and I think we
simply stumbled on a race condition which can cause a split brain.
>> Please note that there are several metrics related issues reported in
vdsm logs as well.
>>
>> Link and headline of suspected patches:
>>
>> Not related
>>
>> Link to Job:
>>
>>
>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/ <
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/4278/>
>>
>> Link to all logs:
>>
>>
>> http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/4278/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/ <
http://jenkins.ovirt.org/job/ovirt-master_change-queue-
tester/4278/artifact/exported-artifacts/basic-suit-master-
el7/test_logs/basic-suite-master/post-006_migrations.py/>
>>
>> (Relevant) error snippet from the log:
>> <error>
>>
>> Engine:
>> 2017-12-05 06:26:48,546-05 ERROR [org.ovirt.engine.core.dal.
dbbroker.auditloghandling.AuditLogDirector] (EE-ManagedThreadFactory-engine-Thread-385)
[] EVENT_ID: VM_MIGRATION_TO_SERVER_FAILED(120), Migration failed (VM:
vm0, Source: lago-
>> basic-suite-master-host-1, Destination: lago-basic-suite-master-host-
0).
>>
>>
>> dst:
>>
>> 2017-12-05 06:26:46,615-0500 WARN (jsonrpc/6) [vds] vm
b3962e5c-08e3-444e-910e-ea675fa1a5c7 already exists (API:179)
>> 2017-12-05 06:26:46,615-0500 ERROR (jsonrpc/6) [api] FINISH create
error=Virtual machine already exists (api:124)
>> Traceback (most recent call last):
>> File "/usr/lib/python2.7/site-packages/vdsm/common/api.py", line
117, in method
>> ret = func(*args, **kwargs)
>> File "/usr/lib/python2.7/site-packages/vdsm/API.py", line 180, in
create
>> raise exception.VMExists()
>> VMExists: Virtual machine already exists
>> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH create
return={'status': {'message': 'Virtual machine already exists',
'code': 4}}
from=::ffff:192.168.201.3,50394 (api:52)
>> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [api.virt] FINISH
migrationCreate return={'status': {'message': 'Virtual machine
already
exists', 'code': 4}} from=::ffff:192.168.201.3,50394 (api:52)
>> 2017-12-05 06:26:46,620-0500 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer]
RPC call VM.migrationCreate failed (error 4) in 0.03 seconds (__init__:573)
>> 2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [api.virt] START
destroy(gracefulAttempts=1) from=::ffff:192.168.201.3,50394 (api:46)
>> 2017-12-05 06:26:46,624-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources
(vm:4967)
>> 2017-12-05 06:26:46,625-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') trying to set state to
Powering down when already Down (vm:575)
>> 2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
>> 2017-12-05 06:26:46,625-0500 INFO (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') _destroyVmGraceful attempt
#0 (vm:5004)
>> 2017-12-05 06:26:46,626-0500 WARN (jsonrpc/2) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') VM
'b3962e5c-08e3-444e-910e-ea675fa1a5c7'
couldn't be destroyed in libvirt: Requested operation is not valid: domain
is not running (vm
>> :5025)
>> 2017-12-05 06:26:46,627-0500 INFO (jsonrpc/2) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None) from
>> =::ffff:192.168.201.3,50394, task_id=2da93725-5533-4354-a369-751eb44f9ef2
(api:46)
>>
>> scr
>>
>> 2017-12-05 06:26:46,623-0500 ERROR (migsrc/b3962e5c) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') migration destination
error: Virtual machine already exists (migration:290)
>>
>> disruption on dst:
>>
>> 2017-12-05 06:20:04,662-0500 INFO (jsonrpc/3) [jsonrpc.JsonRpcServer]
RPC call VM.shutdown succeeded in 0.00 seconds (__init__:573)
>> 2017-12-05 06:20:04,676-0500 ERROR (Thread-1) [root] Shutdown by QEMU
Guest Agent failed (vm:5097)
>> Traceback (most recent call last):
>> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 5088,
in qemuGuestAgentShutdown
>> self._dom.shutdownFlags(libvirt.VIR_DOMAIN_SHUTDOWN_GUEST_AGENT)
>> File "/usr/lib/python2.7/site-packages/vdsm/virt/virdomain.py",
line
98, in f
>> ret = attr(*args, **kwargs)
>> File "/usr/lib/python2.7/site-packages/vdsm/libvirtconnection.py",
line 126, in wrapper
>> ret = f(*args, **kwargs)
>> File "/usr/lib/python2.7/site-packages/vdsm/utils.py", line 512, in
wrapper
>> return func(inst, *args, **kwargs)
>> File "/usr/lib64/python2.7/site-packages/libvirt.py", line 2403, in
shutdownFlags
>> if ret == -1: raise libvirtError ('virDomainShutdownFlags()
failed', dom=self)
>> libvirtError: Guest agent is not responding: QEMU guest agent is not
connected
>> 2017-12-05 06:20:04,697-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') block threshold 1 exceeded
on 'vda' (/rhev/data-center/mnt/blockSD/952bb427-b88c-4fbe-
99ef-49970d3aaf70/images/e6eadbae-ec7a-48f4-
>> 8832-64a622a12bef/1f063c73-f5cd-44e8-a84f-7810857f82df)
(drivemonitor:162)
>> 2017-12-05 06:20:04,698-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') drive 'vda' threshold
exceeded (storage:872)
>> 2017-12-05 06:20:05,889-0500 INFO (jsonrpc/7) [api.host] START
getAllVmStats() from=::1,41118 (api:46)
>> 2017-12-05 06:20:05,891-0500 INFO (jsonrpc/7) [api.host] FINISH
getAllVmStats return={'status': {'message': 'Done',
'code': 0},
'statsList': (suppressed)} from=::1,41118 (api:52)
>> 2017-12-05 06:20:05,892-0500 INFO (jsonrpc/7) [jsonrpc.JsonRpcServer]
RPC call Host.getAllVmStats succeeded in 0.00 seconds (__init__:573)
>> 2017-12-05 06:20:07,466-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') underlying process
disconnected (vm:1024)
>> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Release VM resources
(vm:4967)
>> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [virt.vm]
(vmId='b3962e5c-08e3-444e-910e-ea675fa1a5c7') Stopping connection
(guestagent:435)
>> 2017-12-05 06:20:07,469-0500 INFO (libvirt/events) [vdsm.api] START
teardownImage(sdUUID='952bb427-b88c-4fbe-99ef-49970d3aaf70',
spUUID='9dcfeaaf-96b7-4e26-a327-5570e0e39261',
imgUUID='e6eadbae-ec7a-48f4-8832-64a622a12bef', volUUID=None)
>> from=internal, task_id=9efedf46-d3be-4e41-b7f9-a074ed6344f6 (api:46)
>>
>>
>> </error>
>>
>>
>>
>>
>> _______________________________________________
>> Devel mailing list
>> Devel(a)ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/devel
_______________________________________________
Devel mailing list
Devel(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/devel
2336
days inactive
2342
days old
3 comments
4 participants
participants (4)
-
Arik Hadas -
Dafna Ron -
Michal Skrivanek -
Milan Zamazal