10:32 a.m.
This is a multi-part message in MIME format.
--------------106EB129C1BC1AEAACE8C19F
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Hi,
We have a failure in test 004_basic_sanity.disk_operations.
From the log I can see that vdsm has a KeyError:
'diskReplicate' and
than reports the drive not found.
Can you please check the issue?
**
*Link to suspected patches: https://gerrit.ovirt.org/#/c/83641/*
*
Link to Job:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653
Link to all logs:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifact/
engine log:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
vdsm log:
**
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
(Relevant) error snippet from the log:
<error>
From engine log:
*
2017-11-07 09:20:42,396-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Failed in
'VmReplicateDiskFinishVDS' method
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] EVENT_ID:
VDS_BROKER_COMMAND_FAILURE(10,802), VDSM lago-basic-suite-mas
ter-host-0 command VmReplicateDiskFinishVDS failed: Drive image file
could not be found
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Command
'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk
FinishVDSCommand' return value 'StatusOnlyReturn [status=Status
[code=13, message=Drive image file could not be found]]'
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] HostName
= lago-basic-suite-master-host-0
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Command
'VmReplicateDiskFinishVDSCommand(HostName = lago-basic-sui
te-master-host-0,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9
1d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution failed:
VDSGenericException: VDSErrorException: Fai
led to VmReplicateDiskFinishVDS, error = Drive image file could not be
found, code = 13
2017-11-07 09:20:42,399-05 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Exception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep
tion: VDSGenericException: VDSErrorException: Failed to
VmReplicateDiskFinishVDS, error = Drive image file could not be found,
code = 13
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]
at
org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
Source) [vdsbroker.jar:]
at sun.reflect.GeneratedMethodAccessor244.invoke(Unknown Source)
[:1.8.0_151]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]
at
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
[common.jar:]
at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
[:1.8.0_151]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]
at
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
Source) [vdsbroker.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
[bll.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
[bll.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
[bll.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
[utils.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
[utils.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
[utils.jar:]
at
org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
[bll.jar:]
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
[bll.jar:]
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
[bll.jar:]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_151]
at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[rt.jar:1.8.0_151]
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
[javax.enterprise.concurrent-1.0.jar:]
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
[javax.enterprise.concurrent-1.0.jar:]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_151]
:
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_151]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
at
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
[javax.enterprise.concurrent-1.0.jar:]
at
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
2017-11-07 09:20:42,400-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] FINISH,
VmReplicateDiskFinishVDSCommand, log id: 32c5a56e
2017-11-07 09:20:42,400-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] method:
runVdsCommand, params: [VmReplicateDiskFinish,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}], timeElapsed: 12ms
2017-11-07 09:20:42,400-05 ERROR
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Replication end of disk '36837a9b-6396-4d65-a354-df97ce808f01' in vm
'61d328bc-c920-4691-997f-09bbecb5de10' back to the source failed,
skipping deletion of the target disk
2017-11-07 09:20:42,408-05 WARN
[org.ovirt.engine.core.bll.lock.InMemoryLockManager]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Trying to
release exclusive lock which does not exist, lock key:
'61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'
2017-11-07 09:20:42,408-05 INFO
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Lock
freed to object
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
sharedLocks=''}'
2017-11-07 09:20:42,428-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] method:
get, params: [038b0c9a-f64c-4aa7-8e36-72e435771dab], timeElapsed: 2ms
2017-11-07 09:20:42,430-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] EVENT_ID:
USER_MOVED_DISK_FINISHED_FAILURE(2,011), User admin@internal-authz have
failed to move disk vm0_disk0 to domain iscsi.**
**
*
*
*
*
vdsm log:
2017-11-07 09:20:41,178-0500 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeSize return={'truesize': '2415919104', 'apparentsize':
'2415919104'} from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e,
task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234
(api:52)
2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
diskReplicateFinish error='diskReplicate' (api:127)
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 558, in
diskReplicateFinish
return self.vm.diskReplicateFinish(srcDisk, dstDisk)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4477, in
diskReplicateFinish
self._delDiskReplica(drive)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4528, in
_delDiskReplica
del dev['diskReplicate']
KeyError: 'diskReplicate'
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'General Exception:
("\'diskReplicate\'",)', 'code': 100}}
from=::ffff:192.168.204.4,49358,
flow_id=4bcdd94e (api:52)
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer]
RPC call VM.diskReplicateFinish failed (error 100) in 0.79 seconds
(__init__:630)
2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api] START
finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
subchainInfo={u'img_id': u'8401cd0f-419c-417c-8da3-52da285fa47c',
u'sd_id': u'4a088fb2-5497-4b4d-adec-4c91d998c5
6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id':
u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap
i:46)
2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api] FINISH
finalizeMerge return=None from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)
2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer]
RPC call StoragePool.finalizeMerge succeeded in 0.03 seconds (__init__:630)
2017-11-07 09:20:41,285-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] START task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method Task.commit of
<vdsm.storage.task.Task instance at 0x2f0a560>>, args=None) (threadPool:208)
2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge] Finalizing
subchain after merge: <SubchainInfo
sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
top_id=7a295270-fdf5-4561-b688-033c5d312d
1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74 base_generation=None at
0x30a7990> (merge:254)
2017-11-07 09:20:41,332-0500 INFO (tasks/8) [storage.SANLock] Acquiring
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:377)
2017-11-07 09:20:41,345-0500 INFO (tasks/8) [storage.SANLock]
Successfully acquired Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:415)
2017-11-07 09:20:41,372-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
(volume:558)
2017-11-07 09:20:41,377-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
(volume:558)
2017-11-07 09:20:41,395-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
(volume:558)
2017-11-07 09:20:41,399-0500 INFO (tasks/8) [storage.VolumeManifest]
sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL (volume:399)
2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge] Updating
Vdsm metadata, syncing new chain:
['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image] Current
chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
7a295270-fdf5-4561-b688-033c5d312d1a <
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image] Unlinking
subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a'] (image:1172)
2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image] Setting
parent of volume a6cb7a60-e500-4a75-9da8-9e7cce3e21ac to
e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)
2017-11-07 09:20:41,824-0500 INFO (tasks/8) [storage.SANLock] Releasing
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:435)
2017-11-07 09:20:41,828-0500 INFO (tasks/8) [storage.SANLock]
Successfully released Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:444)
2017-11-07 09:20:41,842-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] FINISH task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)
2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt] START
diskReplicateFinish(srcDisk={u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID': u'4a08
8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}, dstDisk={u'device':
u'disk',
u'poolID': u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID': u
'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'})
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)
2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
(vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not found (srcDisk:
{u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
u'volumeID': u'8a1660d7-f153-4aca-9f
25-c1184c10841a', u'domainID':
u'4a088fb2-5497-4b4d-adec-4c91d998c56e',
u'imageID': u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'Drive image file
could not be found', 'code': 13}} from=::ffff:192.168.204.4,49358,
flow_id=4bcdd94e (api:52)
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer]
RPC call VM.diskReplicateFinish failed (error 13) in 0.01 seconds
(__init__:630)**
:
*
*
*</error>*
**
--------------106EB129C1BC1AEAACE8C19F
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 have a failure in test 004_basic_sanity.disk_operations. <br>
</p>
<p>From the log I can see that vdsm has a KeyError: 'diskReplicate'
and than reports the drive not found. <br>
</p>
<p>Can you please check the issue? <br>
</p>
<p><br>
</p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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 suspected patches: <a class="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/#/c/83641/">https://gerrit.ov...
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<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;">engine
log:
</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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
<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;">vdsm
log:
</span></p>
</b><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
</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;">(Relevant)
error snippet from the log: </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;"><error></span></p>
<br>
From engine log: <br>
</b></p>
<p><span style="font-weight:normal;">2017-11-07 09:20:42,396-05
ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Failed in 'VmReplicateDiskFinishVDS' method<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM
lago-basic-suite-mas<br>
ter-host-0 command VmReplicateDiskFinishVDS failed: Drive image
file could not be found<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Command
'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk<br>
FinishVDSCommand' return value 'StatusOnlyReturn [status=Status
[code=13, message=Drive image file could not be found]]'<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
HostName = lago-basic-suite-master-host-0<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Command 'VmReplicateDiskFinishVDSCommand(HostName =
lago-basic-sui<br>
te-master-host-0,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9<br>
1d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution
failed: VDSGenericException: VDSErrorException: Fai<br>
led to VmReplicateDiskFinishVDS, error = Drive image file could
not be found, code = 13<br>
2017-11-07 09:20:42,399-05 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Exception:
org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep<br>
tion: VDSGenericException: VDSErrorException: Failed to
VmReplicateDiskFinishVDS, error = Drive image file could not be
found, code = 13<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
Source) [vdsbroker.jar:]<br>
at sun.reflect.GeneratedMethodAccessor244.invoke(Unknown
Source) [:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
[common.jar:]<br>
at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown
Source) [:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
Source) [vdsbroker.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
[bll.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
[utils.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
[bll.jar:]<br>
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_151]<br>
at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_151]<br>
:<br>
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_151]<br>
at java.lang.Thread.run(Thread.java:748)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)<br>
<br>
2017-11-07 09:20:42,400-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
FINISH, VmReplicateDiskFinishVDSCommand, log id: 32c5a56e<br>
2017-11-07 09:20:42,400-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
method: runVdsCommand, params: [VmReplicateDiskFinish,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}], timeElapsed:
12ms<br>
2017-11-07 09:20:42,400-05 ERROR
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Replication end of disk '36837a9b-6396-4d65-a354-df97ce808f01'
in vm '61d328bc-c920-4691-997f-09bbecb5de10' back to the source
failed, skipping deletion of the target disk<br>
2017-11-07 09:20:42,408-05 WARN
[org.ovirt.engine.core.bll.lock.InMemoryLockManager]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Trying to release exclusive lock which does not exist, lock key:
'61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'<br>
2017-11-07 09:20:42,408-05 INFO
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Lock freed to object
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
sharedLocks=''}'<br>
2017-11-07 09:20:42,428-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
method: get, params: [038b0c9a-f64c-4aa7-8e36-72e435771dab],
timeElapsed: 2ms<br>
2017-11-07 09:20:42,430-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User
admin@internal-authz have failed to move disk vm0_disk0 to
domain iscsi.</span><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
</b></b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><span style="font-weight:normal;">vdsm log: <br>
</span></p>
<p><span style="font-weight:normal;"><br>
</span></p>
<p><span style="font-weight:normal;">2017-11-07
09:20:41,178-0500
INFO (jsonrpc/6) [vdsm.api] FINISH getVolumeSize
return={'truesize': '2415919104', 'apparentsize':
'2415919104'}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e,
task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234<br>
(api:52)<br>
2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
diskReplicateFinish error='diskReplicate' (api:127)<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 558,
in diskReplicateFinish<br>
return self.vm.diskReplicateFinish(srcDisk, dstDisk)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line
4477, in diskReplicateFinish<br>
self._delDiskReplica(drive)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line
4528, in _delDiskReplica<br>
del dev['diskReplicate']<br>
KeyError: 'diskReplicate'<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'General
Exception: ("\'diskReplicate\'",)', 'code': 100}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed
(error 100) in 0.79 seconds (__init__:630)<br>
2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api] START
finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
subchainInfo={u'img_id':
u'8401cd0f-419c-417c-8da3-52da285fa47c', u'sd_id':
u'4a088fb2-5497-4b4d-adec-4c91d998c5<br>
6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id': u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap<br>
i:46)<br>
2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api] FINISH
finalizeMerge return=None from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)<br>
2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2)
[jsonrpc.JsonRpcServer] RPC call StoragePool.finalizeMerge
succeeded in 0.03 seconds (__init__:630)<br>
2017-11-07 09:20:41,285-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] START task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method
Task.commit of <vdsm.storage.task.Task instance at
0x2f0a560>>, args=None) (threadPool:208)<br>
2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge]
Finalizing subchain after merge: <SubchainInfo
sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
top_id=7a295270-fdf5-4561-b688-033c5d312d<br>
1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74
base_generation=None at 0x30a7990> (merge:254)<br>
2017-11-07 09:20:41,332-0500 INFO (tasks/8) [storage.SANLock]
Acquiring Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:377)<br>
2017-11-07 09:20:41,345-0500 INFO (tasks/8) [storage.SANLock]
Successfully acquired
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:415)<br>
2017-11-07 09:20:41,372-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
(volume:558)<br>
2017-11-07 09:20:41,377-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
(volume:558)<br>
2017-11-07 09:20:41,395-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
(volume:558)<br>
2017-11-07 09:20:41,399-0500 INFO (tasks/8)
[storage.VolumeManifest]
sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL
(volume:399)<br>
2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge]
Updating Vdsm metadata, syncing new chain:
['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Current chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
7a295270-fdf5-4561-b688-033c5d312d1a <
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Unlinking subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a']
(image:1172)<br>
2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image]
Setting parent of volume a6cb7a60-e500-4a75-9da8-9e7cce3e21ac to
e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)<br>
2017-11-07 09:20:41,824-0500 INFO (tasks/8) [storage.SANLock]
Releasing Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:435)<br>
2017-11-07 09:20:41,828-0500 INFO (tasks/8) [storage.SANLock]
Successfully released
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:444)<br>
2017-11-07 09:20:41,842-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] FINISH task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)<br>
2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt] START
diskReplicateFinish(srcDisk={u'device': u'disk',
u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID':
u'4a08<br>
8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}, dstDisk={u'device':
u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
u'volumeID': u'8a1660d7-f153-4aca-9f25-c1184c10841a',
u'domainID': u<br>
'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'})
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)<br>
2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
(vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not found
(srcDisk: {u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f<br>
25-c1184c10841a', u'domainID':
u'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'Drive
image
file could not be found', 'code': 13}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed
(error 13) in 0.01 seconds (__init__:630)</span><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
:<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>
</body>
</html>
--------------106EB129C1BC1AEAACE8C19F--
2:02 a.m.
This is a multi-part message in MIME format.
--------------7512AC95CB9DDFF27D76BF29
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 8bit
Hi,
let's retry with today's snapshots before investigate this (I will of
course investigate and fix), because I had one green OST run before to
merge patches:
http://jenkins.ovirt.org/view/oVirt%20system%20tests/job/ovirt-system-tes...
The caveat is that OST run 1533 includes both patches 81307 and
83641;with both, it should be fine, but with just 83641, I reckon it can
break.
I'll run plenty of OST tests today, so we will soon see if it is indeed
broken or if it was just a glitch.
Bests,
On 11/07/2017 05:32 PM, Dafna Ron wrote:
Hi,
We have a failure in test 004_basic_sanity.disk_operations.
From the log I can see that vdsm has a KeyError: 'diskReplicate' and
than reports the drive not found.
Can you please check the issue?
**
*Link to suspected patches: https://gerrit.ovirt.org/#/c/83641/*
*
Link to Job:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653
Link to all logs:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifact/
engine log:
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
vdsm log:
**
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
(Relevant) error snippet from the log:
<error>
From engine log:
*
2017-11-07 09:20:42,396-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Failed
in 'VmReplicateDiskFinishVDS' method
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM lago-basic-suite-mas
ter-host-0 command VmReplicateDiskFinishVDS failed: Drive image file
could not be found
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Command
'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk
FinishVDSCommand' return value 'StatusOnlyReturn [status=Status
[code=13, message=Drive image file could not be found]]'
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
HostName = lago-basic-suite-master-host-0
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Command
'VmReplicateDiskFinishVDSCommand(HostName = lago-basic-sui
te-master-host-0,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9
1d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution failed:
VDSGenericException: VDSErrorException: Fai
led to VmReplicateDiskFinishVDS, error = Drive image file could not be
found, code = 13
2017-11-07 09:20:42,399-05 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Exception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep
tion: VDSGenericException: VDSErrorException: Failed to
VmReplicateDiskFinishVDS, error = Drive image file could not be found,
code = 13
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]
at
org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
[vdsbroker.jar:]
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
Source) [vdsbroker.jar:]
at sun.reflect.GeneratedMethodAccessor244.invoke(Unknown
Source) [:1.8.0_151]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]
at
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
[common.jar:]
at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown
Source) [:1.8.0_151]
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]
at
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
Source) [vdsbroker.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
[bll.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
[bll.jar:]
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
[bll.jar:]
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
[bll.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
[utils.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
[utils.jar:]
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
[utils.jar:]
at
org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
[bll.jar:]
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
[bll.jar:]
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
[bll.jar:]
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
[bll.jar:]
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_151]
at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[rt.jar:1.8.0_151]
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
[javax.enterprise.concurrent-1.0.jar:]
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
[javax.enterprise.concurrent-1.0.jar:]
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_151]
:
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_151]
at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
at
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
[javax.enterprise.concurrent-1.0.jar:]
at
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
2017-11-07 09:20:42,400-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] FINISH,
VmReplicateDiskFinishVDSCommand, log id: 32c5a56e
2017-11-07 09:20:42,400-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] method:
runVdsCommand, params: [VmReplicateDiskFinish,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}], timeElapsed: 12ms
2017-11-07 09:20:42,400-05 ERROR
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Replication end of disk '36837a9b-6396-4d65-a354-df97ce808f01' in vm
'61d328bc-c920-4691-997f-09bbecb5de10' back to the source failed,
skipping deletion of the target disk
2017-11-07 09:20:42,408-05 WARN
[org.ovirt.engine.core.bll.lock.InMemoryLockManager]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Trying
to release exclusive lock which does not exist, lock key:
'61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'
2017-11-07 09:20:42,408-05 INFO
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Lock
freed to object
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
sharedLocks=''}'
2017-11-07 09:20:42,428-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] method:
get, params: [038b0c9a-f64c-4aa7-8e36-72e435771dab], timeElapsed: 2ms
2017-11-07 09:20:42,430-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User
admin@internal-authz have failed to move disk vm0_disk0 to domain iscsi.**
**
*
*
*
*
vdsm log:
2017-11-07 09:20:41,178-0500 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeSize return={'truesize': '2415919104', 'apparentsize':
'2415919104'} from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e,
task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234
(api:52)
2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
diskReplicateFinish error='diskReplicate' (api:127)
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 558, in
diskReplicateFinish
return self.vm.diskReplicateFinish(srcDisk, dstDisk)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4477,
in diskReplicateFinish
self._delDiskReplica(drive)
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4528,
in _delDiskReplica
del dev['diskReplicate']
KeyError: 'diskReplicate'
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'General
Exception:
("\'diskReplicate\'",)', 'code': 100}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [jsonrpc.JsonRpcServer]
RPC call VM.diskReplicateFinish failed (error 100) in 0.79 seconds
(__init__:630)
2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api] START
finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
subchainInfo={u'img_id': u'8401cd0f-419c-417c-8da3-52da285fa47c',
u'sd_id': u'4a088fb2-5497-4b4d-adec-4c91d998c5
6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id':
u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap
i:46)
2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api] FINISH
finalizeMerge return=None from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)
2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2) [jsonrpc.JsonRpcServer]
RPC call StoragePool.finalizeMerge succeeded in 0.03 seconds
(__init__:630)
2017-11-07 09:20:41,285-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] START task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method Task.commit of
<vdsm.storage.task.Task instance at 0x2f0a560>>, args=None)
(threadPool:208)
2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge]
Finalizing subchain after merge: <SubchainInfo
sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
top_id=7a295270-fdf5-4561-b688-033c5d312d
1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74 base_generation=None
at 0x30a7990> (merge:254)
2017-11-07 09:20:41,332-0500 INFO (tasks/8) [storage.SANLock]
Acquiring Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:377)
2017-11-07 09:20:41,345-0500 INFO (tasks/8) [storage.SANLock]
Successfully acquired
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:415)
2017-11-07 09:20:41,372-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
(volume:558)
2017-11-07 09:20:41,377-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
(volume:558)
2017-11-07 09:20:41,395-0500 INFO (tasks/8) [storage.VolumeManifest]
Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
(volume:558)
2017-11-07 09:20:41,399-0500 INFO (tasks/8) [storage.VolumeManifest]
sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL (volume:399)
2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge] Updating
Vdsm metadata, syncing new chain:
['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image] Current
chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
7a295270-fdf5-4561-b688-033c5d312d1a <
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image] Unlinking
subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a'] (image:1172)
2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image] Setting
parent of volume a6cb7a60-e500-4a75-9da8-9e7cce3e21ac to
e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)
2017-11-07 09:20:41,824-0500 INFO (tasks/8) [storage.SANLock]
Releasing Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:435)
2017-11-07 09:20:41,828-0500 INFO (tasks/8) [storage.SANLock]
Successfully released
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:444)
2017-11-07 09:20:41,842-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] FINISH task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)
2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt] START
diskReplicateFinish(srcDisk={u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID': u'4a08
8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}, dstDisk={u'device':
u'disk',
u'poolID': u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID': u
'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'})
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)
2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
(vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not found
(srcDisk: {u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f
25-c1184c10841a', u'domainID':
u'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt] FINISH
diskReplicateFinish return={'status': {'message': 'Drive image file
could not be found', 'code': 13}} from=::ffff:192.168.204.4,49358,
flow_id=4bcdd94e (api:52)
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [jsonrpc.JsonRpcServer]
RPC call VM.diskReplicateFinish failed (error 13) in 0.01 seconds
(__init__:630)**
:
*
*
*</error>*
**
--
Francesco Romani
Senior SW Eng., Virtualization R&D
Red Hat
IRC: fromani github: @fromanirh
--------------7512AC95CB9DDFF27D76BF29
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,</p>
<p><br>
</p>
<p>let's retry with today's snapshots before investigate this (I
will of course investigate and fix), because I had one green OST
run before to merge patches:</p>
<p><a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/view/oVirt%20system%20tests/job/ovirt...
The caveat is that OST run 1533 includes both patches 81307 and
83641;with both, it should be fine, but with just 83641, I reckon it
can break.<br>
<br>
I'll run plenty of OST tests today, so we will soon see if it is
indeed broken or if it was just a glitch.<br>
<br>
Bests,<br>
<br>
<br>
<div class="moz-cite-prefix">On 11/07/2017 05:32 PM, Dafna Ron
wrote:<br>
</div>
<blockquote type="cite"
cite="mid:d9c9446b-aafe-7f0a-2132-e80e89ffe4c2@redhat.com">
<meta http-equiv="content-type" content="text/html;
charset=utf-8">
<p>Hi, <br>
</p>
<p>We have a failure in test 004_basic_sanity.disk_operations. <br>
</p>
<p>From the log I can see that vdsm has a KeyError:
'diskReplicate' and than reports the drive not found. <br>
</p>
<p>Can you please check the issue? <br>
</p>
<p><br>
</p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
</b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><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 suspected patches: <a class="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/#/c/83641/"
moz-do-not-send="true">https://gerrit.ovirt.org/#/c/83641/&l...
<b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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;">engine
log:
</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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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;">vdsm
log:
</span></p>
</b><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
</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;">(Relevant)
error snippet from the log: </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;"><error></span></p>
<br>
From engine log: <br>
</b>
<p><span style="font-weight:normal;">2017-11-07
09:20:42,396-05
ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Failed in 'VmReplicateDiskFinishVDS' method<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM
lago-basic-suite-mas<br>
ter-host-0 command VmReplicateDiskFinishVDS failed: Drive
image file could not be found<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Command
'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk<br>
FinishVDSCommand' return value 'StatusOnlyReturn
[status=Status [code=13, message=Drive image file could not be
found]]'<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
HostName = lago-basic-suite-master-host-0<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Command 'VmReplicateDiskFinishVDSCommand(HostName =
lago-basic-sui<br>
te-master-host-0,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9<br>
1d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution
failed: VDSGenericException: VDSErrorException: Fai<br>
led to VmReplicateDiskFinishVDS, error = Drive image file
could not be found, code = 13<br>
2017-11-07 09:20:42,399-05 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Exception:
org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep<br>
tion: VDSGenericException: VDSErrorException: Failed to
VmReplicateDiskFinishVDS, error = Drive image file could not
be found, code = 13<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
Source) [vdsbroker.jar:]<br>
at
sun.reflect.GeneratedMethodAccessor244.invoke(Unknown Source)
[:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
[common.jar:]<br>
at
sun.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
[:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
Source) [vdsbroker.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
[bll.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
[utils.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
[bll.jar:]<br>
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_151]<br>
at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_151]<br>
:<br>
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_151]<br>
at java.lang.Thread.run(Thread.java:748)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)<br>
<br>
2017-11-07 09:20:42,400-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
FINISH, VmReplicateDiskFinishVDSCommand, log id: 32c5a56e<br>
2017-11-07 09:20:42,400-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
method: runVdsCommand, params: [VmReplicateDiskFinish,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}], timeElapsed:
12ms<br>
2017-11-07 09:20:42,400-05 ERROR
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Replication end of disk '36837a9b-6396-4d65-a354-df97ce808f01'
in vm '61d328bc-c920-4691-997f-09bbecb5de10' back to the
source failed, skipping deletion of the target disk<br>
2017-11-07 09:20:42,408-05 WARN
[org.ovirt.engine.core.bll.lock.InMemoryLockManager]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Trying to release exclusive lock which does not exist, lock
key:
'61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'<br>
2017-11-07 09:20:42,408-05 INFO
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
Lock freed to object
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
sharedLocks=''}'<br>
2017-11-07 09:20:42,428-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
method: get, params: [038b0c9a-f64c-4aa7-8e36-72e435771dab],
timeElapsed: 2ms<br>
2017-11-07 09:20:42,430-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User
admin@internal-authz have failed to move disk vm0_disk0 to
domain iscsi.</span><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
</b></b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><span style="font-weight:normal;">vdsm log: <br>
</span></p>
<p><span style="font-weight:normal;"><br>
</span></p>
<p><span style="font-weight:normal;">2017-11-07
09:20:41,178-0500
INFO (jsonrpc/6) [vdsm.api] FINISH getVolumeSize
return={'truesize': '2415919104', 'apparentsize':
'2415919104'} from=::ffff:192.168.204.4,49358,
flow_id=4bcdd94e, task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234<br>
(api:52)<br>
2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
diskReplicateFinish error='diskReplicate' (api:127)<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
558, in diskReplicateFinish<br>
return self.vm.diskReplicateFinish(srcDisk, dstDisk)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 4477, in diskReplicateFinish<br>
self._delDiskReplica(drive)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 4528, in _delDiskReplica<br>
del dev['diskReplicate']<br>
KeyError: 'diskReplicate'<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt]
FINISH diskReplicateFinish return={'status': {'message':
'General Exception: ("\'diskReplicate\'",)',
'code': 100}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed
(error 100) in 0.79 seconds (__init__:630)<br>
2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api]
START
finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
subchainInfo={u'img_id':
u'8401cd0f-419c-417c-8da3-52da285fa47c', u'sd_id':
u'4a088fb2-5497-4b4d-adec-4c91d998c5<br>
6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id': u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap<br>
i:46)<br>
2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api]
FINISH finalizeMerge return=None
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)<br>
2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2)
[jsonrpc.JsonRpcServer] RPC call StoragePool.finalizeMerge
succeeded in 0.03 seconds (__init__:630)<br>
2017-11-07 09:20:41,285-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] START task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method
Task.commit of <vdsm.storage.task.Task instance at
0x2f0a560>>, args=None) (threadPool:208)<br>
2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge]
Finalizing subchain after merge: <SubchainInfo
sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
top_id=7a295270-fdf5-4561-b688-033c5d312d<br>
1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74
base_generation=None at 0x30a7990> (merge:254)<br>
2017-11-07 09:20:41,332-0500 INFO (tasks/8) [storage.SANLock]
Acquiring Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:377)<br>
2017-11-07 09:20:41,345-0500 INFO (tasks/8) [storage.SANLock]
Successfully acquired
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:415)<br>
2017-11-07 09:20:41,372-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
(volume:558)<br>
2017-11-07 09:20:41,377-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
(volume:558)<br>
2017-11-07 09:20:41,395-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
(volume:558)<br>
2017-11-07 09:20:41,399-0500 INFO (tasks/8)
[storage.VolumeManifest]
sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL
(volume:399)<br>
2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge]
Updating Vdsm metadata, syncing new chain:
['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Current chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
7a295270-fdf5-4561-b688-033c5d312d1a <
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Unlinking subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a']
(image:1172)<br>
2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image]
Setting parent of volume a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
to e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)<br>
2017-11-07 09:20:41,824-0500 INFO (tasks/8) [storage.SANLock]
Releasing Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:435)<br>
2017-11-07 09:20:41,828-0500 INFO (tasks/8) [storage.SANLock]
Successfully released
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:444)<br>
2017-11-07 09:20:41,842-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] FINISH task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)<br>
2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt]
START diskReplicateFinish(srcDisk={u'device': u'disk',
u'poolID': u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
u'volumeID': u'8a1660d7-f153-4aca-9f25-c1184c10841a',
u'domainID': u'4a08<br>
8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}, dstDisk={u'device':
u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
u'volumeID': u'8a1660d7-f153-4aca-9f25-c1184c10841a',
u'domainID': u<br>
'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'})
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)<br>
2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
(vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not found
(srcDisk: {u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f<br>
25-c1184c10841a', u'domainID':
u'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt]
FINISH diskReplicateFinish return={'status': {'message':
'Drive image file could not be found', 'code': 13}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed
(error 13) in 0.01 seconds (__init__:630)</span><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
:<br>
</b><br>
</b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><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>
<b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
</b><br
class="Apple-interchange-newline">
</blockquote>
<br>
<pre class="moz-signature" cols="72">--
Francesco Romani
Senior SW Eng., Virtualization R&D
Red Hat
IRC: fromani github: @fromanirh</pre>
</body>
</html>
--------------7512AC95CB9DDFF27D76BF29--
7:16 a.m.
This is a multi-part message in MIME format.
--------------1AD6CB38E8A51355EFFCC60A
Content-Type: text/plain; charset=utf-8
Content-Transfer-Encoding: 7bit
Thank you for the quick reply :)
On 11/08/2017 08:02 AM, Francesco Romani wrote:
Hi,
let's retry with today's snapshots before investigate this (I will of
course investigate and fix), because I had one green OST run before to
merge patches:
http://jenkins.ovirt.org/view/oVirt%20system%20tests/job/ovirt-system-tes...
The caveat is that OST run 1533 includes both patches 81307 and
83641;with both, it should be fine, but with just 83641, I reckon it
can break.
I'll run plenty of OST tests today, so we will soon see if it is
indeed broken or if it was just a glitch.
Bests,
On 11/07/2017 05:32 PM, Dafna Ron wrote:
>
> Hi,
>
> We have a failure in test 004_basic_sanity.disk_operations.
>
> From the log I can see that vdsm has a KeyError: 'diskReplicate' and
> than reports the drive not found.
>
> Can you please check the issue?
>
>
> **
>
> *Link to suspected patches: https://gerrit.ovirt.org/#/c/83641/*
>
> *
>
> Link to Job:
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653
>
>
> Link to all logs:
> http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifact/
>
> engine log:
>
>
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
>
> vdsm log:
>
> **
>
>
http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/3653/artifa...
>
>
>
> (Relevant) error snippet from the log:
>
> <error>
>
>
> From engine log:
> *
>
> 2017-11-07 09:20:42,396-05 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Failed
> in 'VmReplicateDiskFinishVDS' method
> 2017-11-07 09:20:42,399-05 ERROR
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802), VDSM lago-basic-suite-mas
> ter-host-0 command VmReplicateDiskFinishVDS failed: Drive image file
> could not be found
> 2017-11-07 09:20:42,399-05 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> Command 'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk
> FinishVDSCommand' return value 'StatusOnlyReturn [status=Status
> [code=13, message=Drive image file could not be found]]'
> 2017-11-07 09:20:42,399-05 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> HostName = lago-basic-suite-master-host-0
> 2017-11-07 09:20:42,399-05 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> Command 'VmReplicateDiskFinishVDSCommand(HostName = lago-basic-sui
> te-master-host-0,
> VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
> vmId='61d328bc-c920-4691-997f-09bbecb5de10',
> storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
> srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9
> 1d998c56e',
> targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
> imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
> imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution failed:
> VDSGenericException: VDSErrorException: Fai
> led to VmReplicateDiskFinishVDS, error = Drive image file could not
> be found, code = 13
> 2017-11-07 09:20:42,399-05 DEBUG
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> Exception: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep
> tion: VDSGenericException: VDSErrorException: Failed to
> VmReplicateDiskFinishVDS, error = Drive image file could not be
> found, code = 13
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
> [vdsbroker.jar:]
> at
> org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
> [dal.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
> [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
> Source) [vdsbroker.jar:]
> at sun.reflect.GeneratedMethodAccessor244.invoke(Unknown
> Source) [:1.8.0_151]
> at
>
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [rt.jar:1.8.0_151]
> at java.lang.reflect.Method.invoke(Method.java:498)
> [rt.jar:1.8.0_151]
> at
>
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
> [common.jar:]
> at sun.reflect.GeneratedMethodAccessor69.invoke(Unknown
> Source) [:1.8.0_151]
> at
>
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
> [rt.jar:1.8.0_151]
> at java.lang.reflect.Method.invoke(Method.java:498)
> [rt.jar:1.8.0_151]
> at
>
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
> [weld-core-impl-2.4.3.Final.jar:2.4.3.Final]
> at
>
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
> Source) [vdsbroker.jar:]
> at
>
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
> [bll.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
> [bll.jar:]
> at
>
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
> [utils.jar:]
> at
>
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
> [utils.jar:]
> at
>
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
> [utils.jar:]
> at
> org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
> [bll.jar:]
> at
>
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
> [bll.jar:]
> at
> java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
> [rt.jar:1.8.0_151]
> at
> java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
> [rt.jar:1.8.0_151]
> at
>
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
> [javax.enterprise.concurrent-1.0.jar:]
> at
>
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
> [javax.enterprise.concurrent-1.0.jar:]
> at
> java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
> [rt.jar:1.8.0_151]
> :
> at
> java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
> [rt.jar:1.8.0_151]
> at java.lang.Thread.run(Thread.java:748) [rt.jar:1.8.0_151]
> at
>
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
> [javax.enterprise.concurrent-1.0.jar:]
> at
>
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)
>
> 2017-11-07 09:20:42,400-05 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> FINISH, VmReplicateDiskFinishVDSCommand, log id: 32c5a56e
> 2017-11-07 09:20:42,400-05 DEBUG
> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> method: runVdsCommand, params: [VmReplicateDiskFinish,
> VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
> vmId='61d328bc-c920-4691-997f-09bbecb5de10',
> storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
> srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
> targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
> imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
> imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}], timeElapsed: 12ms
> 2017-11-07 09:20:42,400-05 ERROR
> [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> Replication end of disk '36837a9b-6396-4d65-a354-df97ce808f01' in vm
> '61d328bc-c920-4691-997f-09bbecb5de10' back to the source failed,
> skipping deletion of the target disk
> 2017-11-07 09:20:42,408-05 WARN
> [org.ovirt.engine.core.bll.lock.InMemoryLockManager]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Trying
> to release exclusive lock which does not exist, lock key:
> '61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'
> 2017-11-07 09:20:42,408-05 INFO
> [org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e] Lock
> freed to object
>
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
> sharedLocks=''}'
> 2017-11-07 09:20:42,428-05 DEBUG
> [org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> method: get, params: [038b0c9a-f64c-4aa7-8e36-72e435771dab],
> timeElapsed: 2ms
> 2017-11-07 09:20:42,430-05 ERROR
> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
> (EE-ManagedThreadFactory-engineScheduled-Thread-72) [4bcdd94e]
> EVENT_ID: USER_MOVED_DISK_FINISHED_FAILURE(2,011), User
> admin@internal-authz have failed to move disk vm0_disk0 to domain
> iscsi.**
> **
>
> *
> *
>
> *
> *
>
> vdsm log:
>
>
> 2017-11-07 09:20:41,178-0500 INFO (jsonrpc/6) [vdsm.api] FINISH
> getVolumeSize return={'truesize': '2415919104',
'apparentsize':
> '2415919104'} from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e,
> task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234
> (api:52)
> 2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
> diskReplicateFinish error='diskReplicate' (api:127)
> 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 558, in
> diskReplicateFinish
> return self.vm.diskReplicateFinish(srcDisk, dstDisk)
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4477,
> in diskReplicateFinish
> self._delDiskReplica(drive)
> File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py", line 4528,
> in _delDiskReplica
> del dev['diskReplicate']
> KeyError: 'diskReplicate'
> 2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt] FINISH
> diskReplicateFinish return={'status': {'message': 'General
Exception:
> ("\'diskReplicate\'",)', 'code': 100}}
> from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)
> 2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6)
> [jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed (error
> 100) in 0.79 seconds (__init__:630)
> 2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api] START
> finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
> subchainInfo={u'img_id': u'8401cd0f-419c-417c-8da3-52da285fa47c',
> u'sd_id': u'4a088fb2-5497-4b4d-adec-4c91d998c5
> 6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id':
> u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
> from=::ffff:192.168.204.4,49380,
> flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
> task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap
> i:46)
> 2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api] FINISH
> finalizeMerge return=None from=::ffff:192.168.204.4,49380,
> flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
> task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)
> 2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2)
> [jsonrpc.JsonRpcServer] RPC call StoragePool.finalizeMerge succeeded
> in 0.03 seconds (__init__:630)
> 2017-11-07 09:20:41,285-0500 INFO (tasks/8)
> [storage.ThreadPool.WorkerThread] START task
> 9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method Task.commit
> of <vdsm.storage.task.Task instance at 0x2f0a560>>, args=None)
> (threadPool:208)
> 2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge]
> Finalizing subchain after merge: <SubchainInfo
> sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
> img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
> top_id=7a295270-fdf5-4561-b688-033c5d312d
> 1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74 base_generation=None
> at 0x30a7990> (merge:254)
> 2017-11-07 09:20:41,332-0500 INFO (tasks/8) [storage.SANLock]
> Acquiring Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
>
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
> f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
> offset=0) for host id 1 (clusterlock:377)
> 2017-11-07 09:20:41,345-0500 INFO (tasks/8) [storage.SANLock]
> Successfully acquired
> Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
>
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
> offset=0) for host id 1 (clusterlock:415)
> 2017-11-07 09:20:41,372-0500 INFO (tasks/8) [storage.VolumeManifest]
> Volume: preparing volume
> 4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
> (volume:558)
> 2017-11-07 09:20:41,377-0500 INFO (tasks/8) [storage.VolumeManifest]
> Volume: preparing volume
> 4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
> (volume:558)
> 2017-11-07 09:20:41,395-0500 INFO (tasks/8) [storage.VolumeManifest]
> Volume: preparing volume
> 4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
> (volume:558)
> 2017-11-07 09:20:41,399-0500 INFO (tasks/8) [storage.VolumeManifest]
> sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
> imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
> 7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL (volume:399)
> 2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge] Updating
> Vdsm metadata, syncing new chain:
> ['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
> u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)
> 2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image] Current
> chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
> 7a295270-fdf5-4561-b688-033c5d312d1a <
> a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)
> 2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
> Unlinking subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a'] (image:1172)
> 2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image] Setting
> parent of volume a6cb7a60-e500-4a75-9da8-9e7cce3e21ac to
> e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)
> 2017-11-07 09:20:41,824-0500 INFO (tasks/8) [storage.SANLock]
> Releasing Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
>
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0
> f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
> offset=0) (clusterlock:435)
> 2017-11-07 09:20:41,828-0500 INFO (tasks/8) [storage.SANLock]
> Successfully released
> Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
>
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im
>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
> offset=0) (clusterlock:444)
> 2017-11-07 09:20:41,842-0500 INFO (tasks/8)
> [storage.ThreadPool.WorkerThread] FINISH task
> 9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)
> 2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt] START
> diskReplicateFinish(srcDisk={u'device': u'disk', u'poolID':
> u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
> u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID': u'4a08
> 8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
> u'36837a9b-6396-4d65-a354-df97ce808f01'}, dstDisk={u'device':
> u'disk', u'poolID': u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
> u'volumeID': u'8a1660d7-f153-4aca-9f25-c1184c10841a',
u'domainID': u
> '4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
> u'36837a9b-6396-4d65-a354-df97ce808f01'})
> from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)
> 2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
> (vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not found
> (srcDisk: {u'device': u'disk', u'poolID':
> u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
> u'8a1660d7-f153-4aca-9f
> 25-c1184c10841a', u'domainID':
> u'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
> u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)
> 2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt] FINISH
> diskReplicateFinish return={'status': {'message': 'Drive image
file
> could not be found', 'code': 13}} from=::ffff:192.168.204.4,49358,
> flow_id=4bcdd94e (api:52)
> 2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4)
> [jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish failed (error
> 13) in 0.01 seconds (__init__:630)**
> :
> *
> *
>
> *</error>*
>
> **
--
Francesco Romani
Senior SW Eng., Virtualization R&D
Red Hat
IRC: fromani github: @fromanirh
--------------1AD6CB38E8A51355EFFCC60A
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">
<div class="moz-cite-prefix">Thank you for the quick reply :)
<br>
<br>
<br>
<br>
On 11/08/2017 08:02 AM, Francesco Romani wrote:<br>
</div>
<blockquote type="cite"
cite="mid:46eac215-c05b-db92-f0a6-6ff76777e0c1@redhat.com">
<meta http-equiv="Content-Type" content="text/html;
charset=utf-8">
<p>Hi,</p>
<p><br>
</p>
<p>let's retry with today's snapshots before investigate this (I
will of course investigate and fix), because I had one green OST
run before to merge patches:</p>
<p><a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/view/oVirt%20system%20tests/job/ovirt...
moz-do-not-send="true">http://jenkins.ovirt.org/view/oVirt%2...
The caveat is that OST run 1533 includes both patches 81307 and
83641;with both, it should be fine, but with just 83641, I reckon
it can break.<br>
<br>
I'll run plenty of OST tests today, so we will soon see if it is
indeed broken or if it was just a glitch.<br>
<br>
Bests,<br>
<br>
<br>
<div class="moz-cite-prefix">On 11/07/2017 05:32 PM, Dafna Ron
wrote:<br>
</div>
<blockquote type="cite"
cite="mid:d9c9446b-aafe-7f0a-2132-e80e89ffe4c2@redhat.com">
<meta http-equiv="content-type" content="text/html;
charset=utf-8">
<p>Hi, <br>
</p>
<p>We have a failure in test 004_basic_sanity.disk_operations. <br>
</p>
<p>From the log I can see that vdsm has a KeyError:
'diskReplicate' and than reports the drive not found. <br>
</p>
<p>Can you please check the issue? <br>
</p>
<p><br>
</p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
</b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><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 suspected patches: <a class="moz-txt-link-freetext"
href="https://gerrit.ovirt.org/#/c/83641/"
moz-do-not-send="true">https://gerrit.ovirt.org/#/c/83641/&l...
<b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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: <a class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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;">engine
log:
</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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
<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;">vdsm
log:
</span></p>
</b><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
<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;"><a
class="moz-txt-link-freetext"
href="http://jenkins.ovirt.org/job/ovirt-master_change-queue-tester/...
moz-do-not-send="true">http://jenkins.ovirt.org/job/ovirt-ma...
</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;">(Relevant)
error snippet from the log: </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;"><error></span></p>
<br>
From engine log: <br>
</b>
<p><span style="font-weight:normal;">2017-11-07
09:20:42,396-05
ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Failed in 'VmReplicateDiskFinishVDS' method<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] EVENT_ID: VDS_BROKER_COMMAND_FAILURE(10,802),
VDSM lago-basic-suite-mas<br>
ter-host-0 command VmReplicateDiskFinishVDS failed: Drive
image file could not be found<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Command
'org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDisk<br>
FinishVDSCommand' return value 'StatusOnlyReturn
[status=Status [code=13, message=Drive image file could not
be found]]'<br>
2017-11-07 09:20:42,399-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] HostName = lago-basic-suite-master-host-0<br>
2017-11-07 09:20:42,399-05 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Command 'VmReplicateDiskFinishVDSCommand(HostName
= lago-basic-sui<br>
te-master-host-0,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c9<br>
1d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'})' execution
failed: VDSGenericException: VDSErrorException: Fai<br>
led to VmReplicateDiskFinishVDS, error = Drive image file
could not be found, code = 13<br>
2017-11-07 09:20:42,399-05 DEBUG
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Exception:
org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorExcep<br>
tion: VDSGenericException: VDSErrorException: Failed to
VmReplicateDiskFinishVDS, error = Drive image file could not
be found, code = 13<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.createDefaultConcreteException(VdsBrokerCommand.java:81)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.createException(BrokerCommandBase.java:223)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase.proceedProxyReturnValue(BrokerCommandBase.java:193)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand.executeVdsBrokerCommand(VmReplicateDiskFinishVDSCommand.java:15)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.VdsBrokerCommand.executeVDSCommand(VdsBrokerCommand.java:112)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.VDSCommandBase.executeCommand(VDSCommandBase.java:73)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.dal.VdcCommandBase.execute(VdcCommandBase.java:33)
[dal.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.vdsbroker.DefaultVdsCommandExecutor.execute(DefaultVdsCommandExecutor.java:14)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager.runVdsCommand(ResourceManager.java:387)
[vdsbroker.jar:]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand$$super(Unknown
Source) [vdsbroker.jar:]<br>
at
sun.reflect.GeneratedMethodAccessor244.invoke(Unknown
Source) [:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.proxy.TerminalAroundInvokeInvocationContext.proceedInternal(TerminalAroundInvokeInvocationContext.java:49)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.AroundInvokeInvocationContext.proceed(AroundInvokeInvocationContext.java:77)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.common.di.interceptor.LoggingInterceptor.apply(LoggingInterceptor.java:12)
[common.jar:]<br>
at
sun.reflect.GeneratedMethodAccessor69.invoke(Unknown Source)
[:1.8.0_151]<br>
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
[rt.jar:1.8.0_151]<br>
at java.lang.reflect.Method.invoke(Method.java:498)
[rt.jar:1.8.0_151]<br>
at
org.jboss.weld.interceptor.reader.SimpleInterceptorInvocation$SimpleMethodInvocation.invoke(SimpleInterceptorInvocation.java:73)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeAroundInvoke(InterceptorMethodHandler.java:84)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.executeInterception(InterceptorMethodHandler.java:72)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.interceptor.proxy.InterceptorMethodHandler.invoke(InterceptorMethodHandler.java:56)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:79)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.jboss.weld.bean.proxy.CombinedInterceptorAndDecoratorStackMethodHandler.invoke(CombinedInterceptorAndDecoratorStackMethodHandler.java:68)
[weld-core-impl-2.4.3.Final.jar:2.4.3.Final]<br>
at
org.ovirt.engine.core.vdsbroker.ResourceManager$Proxy$_$$_WeldSubclass.runVdsCommand(Unknown
Source) [vdsbroker.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.replicateDiskFinish(LiveMigrateDiskCommand.java:374)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.handleDestDisk(LiveMigrateDiskCommand.java:681)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand.endWithFailure(LiveMigrateDiskCommand.java:337)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.internalEndWithFailure(CommandBase.java:783)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endActionInTransactionScope(CommandBase.java:712)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1989)
[bll.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:202)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:137)
[utils.jar:]<br>
at
org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:105)
[utils.jar:]<br>
at
org.ovirt.engine.core.bll.CommandBase.endAction(CommandBase.java:574)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.endAction(ChildCommandsCallbackBase.java:125)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.ChildCommandsCallbackBase.onFailed(ChildCommandsCallbackBase.java:156)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.endCallback(CommandCallbacksPoller.java:65)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethodsImpl(CommandCallbacksPoller.java:141)
[bll.jar:]<br>
at
org.ovirt.engine.core.bll.tasks.CommandCallbacksPoller.invokeCallbackMethods(CommandCallbacksPoller.java:106)
[bll.jar:]<br>
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[rt.jar:1.8.0_151]<br>
at
java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.access$201(ManagedScheduledThreadPoolExecutor.java:383)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.glassfish.enterprise.concurrent.internal.ManagedScheduledThreadPoolExecutor$ManagedScheduledFutureTask.run(ManagedScheduledThreadPoolExecutor.java:534)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[rt.jar:1.8.0_151]<br>
:<br>
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[rt.jar:1.8.0_151]<br>
at java.lang.Thread.run(Thread.java:748)
[rt.jar:1.8.0_151]<br>
at
org.glassfish.enterprise.concurrent.ManagedThreadFactoryImpl$ManagedThread.run(ManagedThreadFactoryImpl.java:250)
[javax.enterprise.concurrent-1.0.jar:]<br>
at
org.jboss.as.ee.concurrent.service.ElytronManagedThreadFactory$ElytronManagedThread.run(ElytronManagedThreadFactory.java:78)<br>
<br>
2017-11-07 09:20:42,400-05 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.VmReplicateDiskFinishVDSCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] FINISH, VmReplicateDiskFinishVDSCommand, log id:
32c5a56e<br>
2017-11-07 09:20:42,400-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] method: runVdsCommand, params:
[VmReplicateDiskFinish,
VmReplicateDiskParameters:{hostId='038b0c9a-f64c-4aa7-8e36-72e435771dab',
vmId='61d328bc-c920-4691-997f-09bbecb5de10',
storagePoolId='b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
srcStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
targetStorageDomainId='4a088fb2-5497-4b4d-adec-4c91d998c56e',
imageGroupId='36837a9b-6396-4d65-a354-df97ce808f01',
imageId='8a1660d7-f153-4aca-9f25-c1184c10841a'}],
timeElapsed: 12ms<br>
2017-11-07 09:20:42,400-05 ERROR
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Replication end of disk
'36837a9b-6396-4d65-a354-df97ce808f01' in vm
'61d328bc-c920-4691-997f-09bbecb5de10' back to the source
failed, skipping deletion of the target disk<br>
2017-11-07 09:20:42,408-05 WARN
[org.ovirt.engine.core.bll.lock.InMemoryLockManager]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Trying to release exclusive lock which does not
exist, lock key:
'61d328bc-c920-4691-997f-09bbecb5de10LIVE_STORAGE_MIGRATION'<br>
2017-11-07 09:20:42,408-05 INFO
[org.ovirt.engine.core.bll.storage.lsm.LiveMigrateDiskCommand]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] Lock freed to object
'EngineLock:{exclusiveLocks='[61d328bc-c920-4691-997f-09bbecb5de10=LIVE_STORAGE_MIGRATION]',
sharedLocks=''}'<br>
2017-11-07 09:20:42,428-05 DEBUG
[org.ovirt.engine.core.common.di.interceptor.DebugLoggingInterceptor]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] method: get, params:
[038b0c9a-f64c-4aa7-8e36-72e435771dab], timeElapsed: 2ms<br>
2017-11-07 09:20:42,430-05 ERROR
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(EE-ManagedThreadFactory-engineScheduled-Thread-72)
[4bcdd94e] EVENT_ID:
USER_MOVED_DISK_FINISHED_FAILURE(2,011), User
admin@internal-authz have failed to move disk vm0_disk0 to
domain iscsi.</span><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
</b></b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><br>
</b></p>
<p><span style="font-weight:normal;">vdsm log: <br>
</span></p>
<p><span style="font-weight:normal;"><br>
</span></p>
<p><span style="font-weight:normal;">2017-11-07
09:20:41,178-0500 INFO (jsonrpc/6) [vdsm.api] FINISH
getVolumeSize return={'truesize': '2415919104',
'apparentsize': '2415919104'}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e,
task_id=042481eb-74ac-42a8-9d1e-8fb1c84db234<br>
(api:52)<br>
2017-11-07 09:20:41,193-0500 ERROR (jsonrpc/6) [api] FINISH
diskReplicateFinish error='diskReplicate' (api:127)<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
558, in diskReplicateFinish<br>
return self.vm.diskReplicateFinish(srcDisk, dstDisk)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 4477, in diskReplicateFinish<br>
self._delDiskReplica(drive)<br>
File "/usr/lib/python2.7/site-packages/vdsm/virt/vm.py",
line 4528, in _delDiskReplica<br>
del dev['diskReplicate']<br>
KeyError: 'diskReplicate'<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6) [api.virt]
FINISH diskReplicateFinish return={'status': {'message':
'General Exception: ("\'diskReplicate\'",)',
'code': 100}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:41,195-0500 INFO (jsonrpc/6)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish
failed (error 100) in 0.79 seconds (__init__:630)<br>
2017-11-07 09:20:41,253-0500 INFO (jsonrpc/2) [vdsm.api]
START
finalizeMerge(spUUID=u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
subchainInfo={u'img_id':
u'8401cd0f-419c-417c-8da3-52da285fa47c', u'sd_id':
u'4a088fb2-5497-4b4d-adec-4c91d998c5<br>
6e', u'top_id': u'7a295270-fdf5-4561-b688-033c5d312d1a',
u'base_id': u'e77f8714-9e0f-4f39-8437-e75a3fa44c74'})
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (ap<br>
i:46)<br>
2017-11-07 09:20:41,267-0500 INFO (jsonrpc/2) [vdsm.api]
FINISH finalizeMerge return=None
from=::ffff:192.168.204.4,49380,
flow_id=56c9f051-c091-49cd-9fd5-cc98e92ef05f,
task_id=9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (api:52)<br>
2017-11-07 09:20:41,285-0500 INFO (jsonrpc/2)
[jsonrpc.JsonRpcServer] RPC call StoragePool.finalizeMerge
succeeded in 0.03 seconds (__init__:630)<br>
2017-11-07 09:20:41,285-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] START task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (cmd=<bound method
Task.commit of <vdsm.storage.task.Task instance at
0x2f0a560>>, args=None) (threadPool:208)<br>
2017-11-07 09:20:41,295-0500 INFO (tasks/8) [storage.merge]
Finalizing subchain after merge: <SubchainInfo
sd_id=4a088fb2-5497-4b4d-adec-4c91d998c56e,
img_id=8401cd0f-419c-417c-8da3-52da285fa47c,
top_id=7a295270-fdf5-4561-b688-033c5d312d<br>
1a, base_id=e77f8714-9e0f-4f39-8437-e75a3fa44c74
base_generation=None at 0x30a7990> (merge:254)<br>
2017-11-07 09:20:41,332-0500 INFO (tasks/8)
[storage.SANLock] Acquiring
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:377)<br>
2017-11-07 09:20:41,345-0500 INFO (tasks/8)
[storage.SANLock] Successfully acquired
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) for host id 1 (clusterlock:415)<br>
2017-11-07 09:20:41,372-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/e77f8714-9e0f-4f39-8437-e75a3fa44c74
(volume:558)<br>
2017-11-07 09:20:41,377-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/7a295270-fdf5-4561-b688-033c5d312d1a
(volume:558)<br>
2017-11-07 09:20:41,395-0500 INFO (tasks/8)
[storage.VolumeManifest] Volume: preparing volume
4a088fb2-5497-4b4d-adec-4c91d998c56e/a6cb7a60-e500-4a75-9da8-9e7cce3e21ac
(volume:558)<br>
2017-11-07 09:20:41,399-0500 INFO (tasks/8)
[storage.VolumeManifest]
sdUUID=4a088fb2-5497-4b4d-adec-4c91d998c56e
imgUUID=8401cd0f-419c-417c-8da3-52da285fa47c volUUID =
7a295270-fdf5-4561-b688-033c5d312d1a legality = ILLEGAL
(volume:399)<br>
2017-11-07 09:20:41,667-0500 INFO (tasks/8) [storage.merge]
Updating Vdsm metadata, syncing new chain:
['e77f8714-9e0f-4f39-8437-e75a3fa44c74',
u'a6cb7a60-e500-4a75-9da8-9e7cce3e21ac'] (merge:311)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Current chain=e77f8714-9e0f-4f39-8437-e75a3fa44c74 <
7a295270-fdf5-4561-b688-033c5d312d1a <
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac (top) (image:1162)<br>
2017-11-07 09:20:41,690-0500 INFO (tasks/8) [storage.Image]
Unlinking subchain: ['7a295270-fdf5-4561-b688-033c5d312d1a']
(image:1172)<br>
2017-11-07 09:20:41,709-0500 INFO (tasks/8) [storage.Image]
Setting parent of volume
a6cb7a60-e500-4a75-9da8-9e7cce3e21ac to
e77f8714-9e0f-4f39-8437-e75a3fa44c74 (image:1185)<br>
2017-11-07 09:20:41,824-0500 INFO (tasks/8)
[storage.SANLock] Releasing
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/images/8401cd0<br>
f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:435)<br>
2017-11-07 09:20:41,828-0500 INFO (tasks/8)
[storage.SANLock] Successfully released
Lease(name='e77f8714-9e0f-4f39-8437-e75a3fa44c74',
path=u'/rhev/data-center/mnt/192.168.204.4:_exports_nfs_share1/4a088fb2-5497-4b4d-adec-4c91d998c56e/im<br>
ages/8401cd0f-419c-417c-8da3-52da285fa47c/e77f8714-9e0f-4f39-8437-e75a3fa44c74.lease',
offset=0) (clusterlock:444)<br>
2017-11-07 09:20:41,842-0500 INFO (tasks/8)
[storage.ThreadPool.WorkerThread] FINISH task
9ce348bc-e3fb-4f4e-aea0-f8c79e7ae204 (threadPool:210)<br>
2017-11-07 09:20:42,388-0500 INFO (jsonrpc/4) [api.virt]
START diskReplicateFinish(srcDisk={u'device': u'disk',
u'poolID': u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5',
u'volumeID': u'8a1660d7-f153-4aca-9f25-c1184c10841a',
u'domainID': u'4a08<br>
8fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'},
dstDisk={u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f25-c1184c10841a', u'domainID':
u<br>
'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'})
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:46)<br>
2017-11-07 09:20:42,388-0500 ERROR (jsonrpc/4) [virt.vm]
(vmId='61d328bc-c920-4691-997f-09bbecb5de10') Drive not
found (srcDisk: {u'device': u'disk', u'poolID':
u'b20f0eb7-6bea-4994-b87b-e1080c4fd9e5', u'volumeID':
u'8a1660d7-f153-4aca-9f<br>
25-c1184c10841a', u'domainID':
u'4a088fb2-5497-4b4d-adec-4c91d998c56e', u'imageID':
u'36837a9b-6396-4d65-a354-df97ce808f01'}) (vm:4386)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4) [api.virt]
FINISH diskReplicateFinish return={'status': {'message':
'Drive image file could not be found', 'code': 13}}
from=::ffff:192.168.204.4,49358, flow_id=4bcdd94e (api:52)<br>
2017-11-07 09:20:42,389-0500 INFO (jsonrpc/4)
[jsonrpc.JsonRpcServer] RPC call VM.diskReplicateFinish
failed (error 13) in 0.01 seconds (__init__:630)</span><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><b><br>
:<br>
</b><br>
</b></p>
<p dir="ltr"
style="line-height:1.38;margin-top:0pt;margin-bottom:0pt;"><b
style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d"><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>
<b style="font-weight:normal;"
id="docs-internal-guid-5859b7a1-974d-e74a-41ed-aa8671a5b48d">
</b><br class="Apple-interchange-newline">
</blockquote>
<br>
<pre class="moz-signature" cols="72">--
Francesco Romani
Senior SW Eng., Virtualization R&D
Red Hat
IRC: fromani github: @fromanirh</pre>
</blockquote>
<p><br>
</p>
</body>
</html>
--------------1AD6CB38E8A51355EFFCC60A--
2355
days inactive
2356
days old
2 comments
2 participants
participants (2)
-
Dafna Ron -
Francesco Romani