Re: [Users] Unable to remove Vdisk and Ovirt UI spams finished messages

[Itamar Heim]

On 10/16/2013 05:45 PM, Aslam, Usman wrote:
The version Im using is
oVirt Engine Version: 3.1.0-3.26.3.el6.centos.alt
It is the latest available from this repo 
"http://dev.centos.org/centos/6/ovirt/x86_64/";

Which stable repo can I use for upgrades? Would it be safe to yum update from 
3.1 to 3.3?

http://resources.ovirt.org/releases and then the right version.
(not sure who maintained the centos repos to newer versions)


Vdsm version I'm using

vdsm-python-4.10.3-10.el6.centos.alt.x86_64
vdsm-xmlrpc-4.10.3-10.el6.centos.alt.noarch
vdsm-cli-4.10.3-10.el6.centos.alt.noarch
vdsm-4.10.3-10.el6.centos.alt.x86_64

repo for upgrades? Safe to just do yum update?

for vdsm, should be safe to update. you should do it via engine. via 
host you may need to restart to reconfigure libvirt (note the message on 
vdsm start if it fails).

for engine, 3.2.1 was the first version we had .el6 in ovirt. previous 
versions were maintained by dreyou.
we usually tests upgrades only from one version to the next, not 
directly skipping more than a single version, which is what i recommend 
trying.
(or back it up and try to go the full way, just do it in morning hours 
for more support if needed...)


Thanks,
Usman

-----Original Message-----
From: Daniel Erez [mailto:de...@redhat.com]
Sent: Wednesday, October 16, 2013 10:10 AM
To: Aslam, Usman
Cc: users@ovirt.org
Subject: Re: [Users] Unable to remove Vdisk and Ovirt UI spams finished messages



----- Original Message -----
From: "Usman Aslam" <usman.as...@tufts.edu>
To: "Daniel Erez" <de...@redhat.com>
Cc: users@ovirt.org
Sent: Wednesday, October 16, 2013 2:27:44 AM
Subject: RE: [Users] Unable to remove Vdisk and Ovirt UI spams
finished messages

Daniel,



I did manage to remove the lock on disk by change the value in the
images table.

The spam messages have since I first reported the issue have gone away.
However, I am still unable to remove the VM or its Disks.



On the SPM the suggested getAllTasks comes back with a blank line (I
assume no active tasks). The db table " async_task" also has not data in it.

But as shown in the screenshot below. The Ovirt Web UI shows 0 tasks
but also shows a week old task on still trying to remove that vdisk.



[cid:image001.png@01CEC9DB.F3296440]



Furthermore, below are logs of ovirt engine and vdsm (from SPM) for
period when I try to first remove the VM (it fails) and then the two
vdisks (which also fail) similar to the above screenshot.



Please let me know if there is any more info I can send over. Thanks!

You may encountered bug 884635 [1] which has already been resolved and 
integrated to oVirt 3.3. Are you using the latest source code or an older 
release?

[1]
http://bugzilla.redhat.com/show_bug.cgi?id=884635




###*** vdsm.log ***###



2013-10-15 19:23:50,174 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(ajp--127.0.0.1-8702-4) Lock Acquired to object EngineLock
[exclusiveLocks=
key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

, sharedLocks= ]

2013-10-15 19:23:50,188 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-4) START, IsValidVDSCommand( storagePoolId =
430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null), log id: 18c4d4ab

2013-10-15 19:23:50,194 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-4) FINISH, IsValidVDSCommand, return: true, log id:
18c4d4ab

2013-10-15 19:23:50,280 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-49) [36218b4b] Running command: RemoveVmCommand internal:
false. Entities affected :  ID: f0462ff5-d22b-49d0-b308-af4a4381b93d Type:
VM

2013-10-15 19:23:50,286 INFO
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(pool-3-thread-49) [36218b4b] START, SetVmStatusVDSCommand( vmId =
f0462ff5-d22b-49d0-b308-af4a4381b93d, status = ImageLocked), log id:
59fc9345

2013-10-15 19:23:50,296 INFO
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(pool-3-thread-49) [36218b4b] FINISH, SetVmStatusVDSCommand, log id:
59fc9345

2013-10-15 19:23:50,301 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-49) [36218b4b] Lock freed to object EngineLock
[exclusiveLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

, sharedLocks= ]

2013-10-15 19:23:50,304 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand]
(pool-3-thread-49) [36218b4b] START, RemoveVMVDSCommand( storagePoolId
= 430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null, storageDomainId =
00000000-0000-0000-0000-000000000000, vmGuid =
f0462ff5-d22b-49d0-b308-af4a4381b93d), log id: 13c7a395

2013-10-15 19:23:50,323 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand]
(pool-3-thread-49) [36218b4b] FINISH, RemoveVMVDSCommand, log id:
13c7a395

2013-10-15 19:23:50,346 INFO
[org.ovirt.engine.core.bll.RemoveAllVmImagesCommand]
(pool-3-thread-49) [148b1174] Running command: RemoveAllVmImagesCommand 
internal: true.
Entities affected :  ID: f0462ff5-d22b-49d0-b308-af4a4381b93d Type: VM

2013-10-15 19:23:50,377 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-49) [183aa7b5] Running command: RemoveImageCommand internal:
true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type:
Storage

2013-10-15 19:23:50,382 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-49) [183aa7b5] START, DeleteImageGroupVDSCommand(
storagePoolId = 430cd986-6488-403b-8d46-29abbc3eba38,
ignoreFailoverLimit = false, compatabilityVersion = 3.2,
storageDomainId = fa3279ec-2912-45ac-b7bc-9fe89151ed99, imageGroupId =
bcb77522-8cac-45a7-a5a6-b3c1f55614b8, postZeros = false, forceDelete =
false), log id: 52c1a1fe

2013-10-15 19:23:50,489 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(pool-3-thread-49) [183aa7b5] IrsBroker::Failed::DeleteImageGroupVDS due to:
IrsOperationFailedNoFailoverException: IRSGenericException:
IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:23:50,495 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-49) [183aa7b5] FINISH, DeleteImageGroupVDSCommand, log id:
52c1a1fe

2013-10-15 19:23:50,499 ERROR
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-49) [183aa7b5] Command
org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception.
With error message VdcBLLException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:23:50,520 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-49) [183aa7b5] Command
[id=1ae3c964-48ab-474d-b6e9-64947510be1b]: Compensating
CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.VmDynamic; 
snapshot:
EntityStatusSnapshot [id=f0462ff5-d22b-49d0-b308-af4a4381b93d, status=Down].

2013-10-15 19:23:55,404 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(ajp--127.0.0.1-8702-6) Lock Acquired to object EngineLock
[exclusiveLocks=
key: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:23:55,415 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-6) START, IsValidVDSCommand( storagePoolId =
430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null), log id: 288b190f

2013-10-15 19:23:55,421 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-6) FINISH, IsValidVDSCommand, return: true, log id:
288b190f

2013-10-15 19:23:55,489 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(pool-3-thread-49) [12886b63] Running command: RemoveDiskCommand internal:
false. Entities affected :  ID: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 Type:
Disk

2013-10-15 19:23:55,501 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-49) [68af83cd] Running command: RemoveImageCommand internal:
true. Entities affected :  ID: fa3279ec-2912-45ac-b7bc-9fe89151ed99 Type:
Storage

2013-10-15 19:23:55,506 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-49) [68af83cd] Lock freed to object EngineLock
[exclusiveLocks= key: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:23:55,511 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-49) [68af83cd] START, DeleteImageGroupVDSCommand(
storagePoolId = 430cd986-6488-403b-8d46-29abbc3eba38,
ignoreFailoverLimit = false, compatabilityVersion = 3.2,
storageDomainId = fa3279ec-2912-45ac-b7bc-9fe89151ed99, imageGroupId =
a9ffc7b8-6e64-4dc4-81b8-e52425cbae00, postZeros = false, forceDelete =
false), log id: 70e20b2f

2013-10-15 19:23:55,576 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(pool-3-thread-49) [68af83cd] IrsBroker::Failed::DeleteImageGroupVDS due to:
IrsOperationFailedNoFailoverException: IRSGenericException:
IRSErrorException: Image does not exist in domain:
'image=a9ffc7b8-6e64-4dc4-81b8-e52425cbae00,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:23:55,582 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-49) [68af83cd] FINISH, DeleteImageGroupVDSCommand, log id:
70e20b2f

2013-10-15 19:23:55,588 ERROR
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-49) [68af83cd] Command
org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception.
With error message VdcBLLException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Image does not exist in domain:
'image=a9ffc7b8-6e64-4dc4-81b8-e52425cbae00,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:03,992 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(ajp--127.0.0.1-8702-6) Lock Acquired to object EngineLock
[exclusiveLocks=
key: bcb77522-8cac-45a7-a5a6-b3c1f55614b8 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:24:04,006 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-6) START, IsValidVDSCommand( storagePoolId =
430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null), log id: 67c54350

2013-10-15 19:24:04,013 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-6) FINISH, IsValidVDSCommand, return: true, log id:
67c54350

2013-10-15 19:24:04,036 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(pool-3-thread-46) [3d055b94] Running command: RemoveDiskCommand internal:
false. Entities affected :  ID: bcb77522-8cac-45a7-a5a6-b3c1f55614b8 Type:
Disk

2013-10-15 19:24:04,044 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [2fa6b13] Running command: RemoveImageCommand internal:
true. Entities affected :  ID: fa3279ec-2912-45ac-b7bc-9fe89151ed99 Type:
Storage

2013-10-15 19:24:04,050 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [2fa6b13] Lock freed to object EngineLock
[exclusiveLocks= key: bcb77522-8cac-45a7-a5a6-b3c1f55614b8 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:24:04,056 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [2fa6b13] START, DeleteImageGroupVDSCommand(
storagePoolId = 430cd986-6488-403b-8d46-29abbc3eba38,
ignoreFailoverLimit = false, compatabilityVersion = 3.2,
storageDomainId = fa3279ec-2912-45ac-b7bc-9fe89151ed99, imageGroupId =
bcb77522-8cac-45a7-a5a6-b3c1f55614b8, postZeros = false, forceDelete =
false), log id: 54e25ce0

2013-10-15 19:24:04,147 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(pool-3-thread-46) [2fa6b13] IrsBroker::Failed::DeleteImageGroupVDS due to:
IrsOperationFailedNoFailoverException: IRSGenericException:
IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:04,149 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [2fa6b13] FINISH, DeleteImageGroupVDSCommand, log id:
54e25ce0

2013-10-15 19:24:04,152 ERROR
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [2fa6b13] Command
org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception.
With error message VdcBLLException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:18,376 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(ajp--127.0.0.1-8702-8) Lock Acquired to object EngineLock
[exclusiveLocks=
key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

, sharedLocks= ]

2013-10-15 19:24:18,408 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-8) START, IsValidVDSCommand( storagePoolId =
430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null), log id: 733f30f5

2013-10-15 19:24:18,410 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-8) FINISH, IsValidVDSCommand, return: true, log id:
733f30f5

2013-10-15 19:24:18,445 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-46) [26fd8426] Running command: RemoveVmCommand internal:
false. Entities affected :  ID: f0462ff5-d22b-49d0-b308-af4a4381b93d Type:
VM

2013-10-15 19:24:18,451 INFO
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(pool-3-thread-46) [26fd8426] START, SetVmStatusVDSCommand( vmId =
f0462ff5-d22b-49d0-b308-af4a4381b93d, status = ImageLocked), log id:
34c97c50

2013-10-15 19:24:18,456 INFO
[org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand]
(pool-3-thread-46) [26fd8426] FINISH, SetVmStatusVDSCommand, log id:
34c97c50

2013-10-15 19:24:18,458 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-46) [26fd8426] Lock freed to object EngineLock
[exclusiveLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

, sharedLocks= ]

2013-10-15 19:24:18,459 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand]
(pool-3-thread-46) [26fd8426] START, RemoveVMVDSCommand( storagePoolId
= 430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null, storageDomainId =
00000000-0000-0000-0000-000000000000, vmGuid =
f0462ff5-d22b-49d0-b308-af4a4381b93d), log id: 91998d2

2013-10-15 19:24:18,475 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand]
(pool-3-thread-46) [26fd8426] FINISH, RemoveVMVDSCommand, log id:
91998d2

2013-10-15 19:24:18,496 INFO
[org.ovirt.engine.core.bll.RemoveAllVmImagesCommand]
(pool-3-thread-46) [7178d46f] Running command: RemoveAllVmImagesCommand 
internal: true.
Entities affected :  ID: f0462ff5-d22b-49d0-b308-af4a4381b93d Type: VM

2013-10-15 19:24:18,507 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [da18cdc] Running command: RemoveImageCommand internal:
true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type:
Storage

2013-10-15 19:24:18,510 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [da18cdc] START, DeleteImageGroupVDSCommand(
storagePoolId = 430cd986-6488-403b-8d46-29abbc3eba38,
ignoreFailoverLimit = false, compatabilityVersion = 3.2,
storageDomainId = fa3279ec-2912-45ac-b7bc-9fe89151ed99, imageGroupId =
bcb77522-8cac-45a7-a5a6-b3c1f55614b8, postZeros = false, forceDelete =
false), log id: 1f803250

2013-10-15 19:24:18,574 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(pool-3-thread-46) [da18cdc] IrsBroker::Failed::DeleteImageGroupVDS due to:
IrsOperationFailedNoFailoverException: IRSGenericException:
IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:18,578 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [da18cdc] FINISH, DeleteImageGroupVDSCommand, log id:
1f803250

2013-10-15 19:24:18,582 ERROR
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [da18cdc] Command
org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception.
With error message VdcBLLException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Image does not exist in domain:
'image=bcb77522-8cac-45a7-a5a6-b3c1f55614b8,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:18,597 INFO
[org.ovirt.engine.core.bll.RemoveVmCommand]
(pool-3-thread-46) [da18cdc] Command
[id=00574670-3db7-4758-b68e-98b54d8ff42d]: Compensating
CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.VmDynamic; 
snapshot:
EntityStatusSnapshot [id=f0462ff5-d22b-49d0-b308-af4a4381b93d, status=Down].

2013-10-15 19:24:29,383 WARN
[org.ovirt.engine.core.bll.DetachDiskFromVmCommand]
(ajp--127.0.0.1-8702-9) CanDoAction of action DetachDiskFromVm failed.
Reasons:VAR__ACTION__DETACH_ACTION_TO,VAR__TYPE__VM_DISK,ERROR_CANNOT_
DETACH_DISK_WITH_SNAPSHOT

2013-10-15 19:24:35,371 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(ajp--127.0.0.1-8702-4) Lock Acquired to object EngineLock
[exclusiveLocks=
key: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:24:35,379 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-4) START, IsValidVDSCommand( storagePoolId =
430cd986-6488-403b-8d46-29abbc3eba38, ignoreFailoverLimit = false,
compatabilityVersion = null), log id: 4b0926da

2013-10-15 19:24:35,382 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand]
(ajp--127.0.0.1-8702-4) FINISH, IsValidVDSCommand, return: true, log id:
4b0926da

2013-10-15 19:24:35,420 INFO
[org.ovirt.engine.core.bll.RemoveDiskCommand]
(pool-3-thread-46) [3f8a0b7d] Running command: RemoveDiskCommand internal:
false. Entities affected :  ID: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 Type:
Disk

2013-10-15 19:24:35,430 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [617a9b78] Running command: RemoveImageCommand internal:
true. Entities affected :  ID: fa3279ec-2912-45ac-b7bc-9fe89151ed99 Type:
Storage

2013-10-15 19:24:35,432 INFO
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [617a9b78] Lock freed to object EngineLock
[exclusiveLocks= key: a9ffc7b8-6e64-4dc4-81b8-e52425cbae00 value: DISK

, sharedLocks= key: f0462ff5-d22b-49d0-b308-af4a4381b93d value: VM

]

2013-10-15 19:24:35,435 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [617a9b78] START, DeleteImageGroupVDSCommand(
storagePoolId = 430cd986-6488-403b-8d46-29abbc3eba38,
ignoreFailoverLimit = false, compatabilityVersion = 3.2,
storageDomainId = fa3279ec-2912-45ac-b7bc-9fe89151ed99, imageGroupId =
a9ffc7b8-6e64-4dc4-81b8-e52425cbae00, postZeros = false, forceDelete =
false), log id: 6993df94

2013-10-15 19:24:35,496 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(pool-3-thread-46) [617a9b78] IrsBroker::Failed::DeleteImageGroupVDS due to:
IrsOperationFailedNoFailoverException: IRSGenericException:
IRSErrorException: Image does not exist in domain:
'image=a9ffc7b8-6e64-4dc4-81b8-e52425cbae00,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:24:35,504 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand]
(pool-3-thread-46) [617a9b78] FINISH, DeleteImageGroupVDSCommand, log id:
6993df94

2013-10-15 19:24:35,506 ERROR
[org.ovirt.engine.core.bll.RemoveImageCommand]
(pool-3-thread-46) [617a9b78] Command
org.ovirt.engine.core.bll.RemoveImageCommand throw Vdc Bll exception.
With error message VdcBLLException:
org.ovirt.engine.core.vdsbroker.irsbroker.IrsOperationFailedNoFailoverException:
IRSGenericException: IRSErrorException: Image does not exist in domain:
'image=a9ffc7b8-6e64-4dc4-81b8-e52425cbae00,
domain=fa3279ec-2912-45ac-b7bc-9fe89151ed99'

2013-10-15 19:25:00,001 INFO
[org.ovirt.engine.core.bll.AutoRecoveryManager]
(QuartzScheduler_Worker-52) Autorecovering hosts is disabled, skipping

2013-10-15 19:25:00,002 INFO
[org.ovirt.engine.core.bll.AutoRecoveryManager]
(QuartzScheduler_Worker-52) Autorecovering storage domains is
disabled, skipping



###*** vdsm.log ***###



VM Channels Listener::DEBUG::2013-10-15
19:23:48,075::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 93.

Thread-363707::DEBUG::2013-10-15
19:23:51,861::task::568::TaskManager.Task::(_updateState)
Task=`502bf2d7-ba12-47b2-aba2-8f9ae401b77d`::moving from state init ->
state preparing

Thread-363707::INFO::2013-10-15
19:23:51,861::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363707::INFO::2013-10-15
19:23:51,862::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00687623023987', 'lastCheck': '6.4', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00651216506958',
'lastCheck': '9.3', 'code': 0, 'valid': True}}

Thread-363707::DEBUG::2013-10-15
19:23:51,862::task::1151::TaskManager.Task::(prepare)
Task=`502bf2d7-ba12-47b2-aba2-8f9ae401b77d`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00687623023987',
'lastCheck': '6.4', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00651216506958',
'lastCheck': '9.3', 'code': 0, 'valid': True}}

Thread-363707::DEBUG::2013-10-15
19:23:51,863::task::568::TaskManager.Task::(_updateState)
Task=`502bf2d7-ba12-47b2-aba2-8f9ae401b77d`::moving from state
preparing -> state finished

Thread-363707::DEBUG::2013-10-15
19:23:51,863::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363707::DEBUG::2013-10-15
19:23:51,863::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363707::DEBUG::2013-10-15
19:23:51,864::task::957::TaskManager.Task::(_decref)
Task=`502bf2d7-ba12-47b2-aba2-8f9ae401b77d`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:23:56,083::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 20.

Thread-1841::DEBUG::2013-10-15
19:23:56,725::task::568::TaskManager.Task::(_updateState)
Task=`f0184ed3-d107-41aa-a468-4c29b5e0ac0a`::moving from state init ->
state preparing

Thread-1841::INFO::2013-10-15
19:23:56,725::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='0941095c-7a1f-410c-8453-361be8f8adbc',
volUUID='45bd040f-e8c7-493c-b8f2-a5dbeb32c56d', options=None)

Thread-2173::DEBUG::2013-10-15
19:23:56,730::task::568::TaskManager.Task::(_updateState)
Task=`272090f3-d569-440a-b249-386cb5ed9c0f`::moving from state init ->
state preparing

Thread-2173::INFO::2013-10-15
19:23:56,734::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='c2f279d6-14df-4f60-b9ae-d51559c59013',
volUUID='f17d3d6d-4324-4e4a-bfd8-28f62cf3753f', options=None)

Thread-1841::DEBUG::2013-10-15
19:23:56,740::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for 45bd040f-e8c7-493c-b8f2-a5dbeb32c56d

Thread-2173::DEBUG::2013-10-15
19:23:56,750::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for f17d3d6d-4324-4e4a-bfd8-28f62cf3753f

Thread-1841::INFO::2013-10-15
19:23:56,750::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '13492871168', 'apparentsize':
'53687091200'}

Thread-1841::DEBUG::2013-10-15
19:23:56,752::task::1151::TaskManager.Task::(prepare)
Task=`f0184ed3-d107-41aa-a468-4c29b5e0ac0a`::finished: {'truesize':
'13492871168', 'apparentsize': '53687091200'}

Thread-1841::DEBUG::2013-10-15
19:23:56,753::task::568::TaskManager.Task::(_updateState)
Task=`f0184ed3-d107-41aa-a468-4c29b5e0ac0a`::moving from state
preparing -> state finished

Thread-1841::DEBUG::2013-10-15
19:23:56,755::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-1841::DEBUG::2013-10-15
19:23:56,755::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-1841::DEBUG::2013-10-15
19:23:56,756::task::957::TaskManager.Task::(_decref)
Task=`f0184ed3-d107-41aa-a468-4c29b5e0ac0a`::ref 0 aborting False

Thread-2173::INFO::2013-10-15
19:23:56,757::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '10940887040', 'apparentsize':
'53687091200'}

Thread-2173::DEBUG::2013-10-15
19:23:56,758::task::1151::TaskManager.Task::(prepare)
Task=`272090f3-d569-440a-b249-386cb5ed9c0f`::finished: {'truesize':
'10940887040', 'apparentsize': '53687091200'}

Thread-2173::DEBUG::2013-10-15
19:23:56,758::task::568::TaskManager.Task::(_updateState)
Task=`272090f3-d569-440a-b249-386cb5ed9c0f`::moving from state
preparing -> state finished

Thread-2173::DEBUG::2013-10-15
19:23:56,758::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-2173::DEBUG::2013-10-15
19:23:56,759::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-2173::DEBUG::2013-10-15
19:23:56,759::task::957::TaskManager.Task::(_decref)
Task=`272090f3-d569-440a-b249-386cb5ed9c0f`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:23:59,085::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 83.

VM Channels Listener::DEBUG::2013-10-15
19:24:02,088::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 60.

Thread-363713::DEBUG::2013-10-15
19:24:02,156::task::568::TaskManager.Task::(_updateState)
Task=`74b2ce46-dccd-44a6-9b7b-f61dbfe60045`::moving from state init ->
state preparing

Thread-363713::INFO::2013-10-15
19:24:02,156::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363713::INFO::2013-10-15
19:24:02,156::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00695705413818', 'lastCheck': '6.7', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00702095031738',
'lastCheck': '9.6', 'code': 0, 'valid': True}}

Thread-363713::DEBUG::2013-10-15
19:24:02,157::task::1151::TaskManager.Task::(prepare)
Task=`74b2ce46-dccd-44a6-9b7b-f61dbfe60045`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00695705413818',
'lastCheck': '6.7', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00702095031738',
'lastCheck': '9.6', 'code': 0, 'valid': True}}

Thread-363713::DEBUG::2013-10-15
19:24:02,157::task::568::TaskManager.Task::(_updateState)
Task=`74b2ce46-dccd-44a6-9b7b-f61dbfe60045`::moving from state
preparing -> state finished

Thread-363713::DEBUG::2013-10-15
19:24:02,157::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363713::DEBUG::2013-10-15
19:24:02,158::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363713::DEBUG::2013-10-15
19:24:02,158::task::957::TaskManager.Task::(_decref)
Task=`74b2ce46-dccd-44a6-9b7b-f61dbfe60045`::ref 0 aborting False

Thread-1696::DEBUG::2013-10-15
19:24:02,196::task::568::TaskManager.Task::(_updateState)
Task=`b2f2abe6-13de-443e-a5a7-d2a63f422cef`::moving from state init ->
state preparing

Thread-1696::INFO::2013-10-15
19:24:02,197::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='96312a42-8407-44ef-9aad-60c6778a3ae6',
volUUID='01474eea-fcb8-4294-b58b-b6134cadc3e2', options=None)

Thread-1696::DEBUG::2013-10-15
19:24:02,200::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for 01474eea-fcb8-4294-b58b-b6134cadc3e2

Thread-1696::INFO::2013-10-15
19:24:02,203::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '1945018368', 'apparentsize':
'1937506304'}

Thread-1696::DEBUG::2013-10-15
19:24:02,203::task::1151::TaskManager.Task::(prepare)
Task=`b2f2abe6-13de-443e-a5a7-d2a63f422cef`::finished: {'truesize':
'1945018368', 'apparentsize': '1937506304'}

Thread-1696::DEBUG::2013-10-15
19:24:02,204::task::568::TaskManager.Task::(_updateState)
Task=`b2f2abe6-13de-443e-a5a7-d2a63f422cef`::moving from state
preparing -> state finished

Thread-1696::DEBUG::2013-10-15
19:24:02,204::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-1696::DEBUG::2013-10-15
19:24:02,204::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-1696::DEBUG::2013-10-15
19:24:02,204::task::957::TaskManager.Task::(_decref)
Task=`b2f2abe6-13de-443e-a5a7-d2a63f422cef`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:04,090::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 86.

VM Channels Listener::DEBUG::2013-10-15
19:24:05,092::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 65.

Thread-363719::DEBUG::2013-10-15
19:24:12,487::task::568::TaskManager.Task::(_updateState)
Task=`cb5f0f17-fe04-44b9-8fcb-7643e0ed0a11`::moving from state init ->
state preparing

Thread-363719::INFO::2013-10-15
19:24:12,488::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363719::INFO::2013-10-15
19:24:12,489::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00698399543762', 'lastCheck': '7.0', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00687909126282',
'lastCheck': '9.9', 'code': 0, 'valid': True}}

Thread-363719::DEBUG::2013-10-15
19:24:12,489::task::1151::TaskManager.Task::(prepare)
Task=`cb5f0f17-fe04-44b9-8fcb-7643e0ed0a11`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00698399543762',
'lastCheck': '7.0', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00687909126282',
'lastCheck': '9.9', 'code': 0, 'valid': True}}

Thread-363719::DEBUG::2013-10-15
19:24:12,489::task::568::TaskManager.Task::(_updateState)
Task=`cb5f0f17-fe04-44b9-8fcb-7643e0ed0a11`::moving from state
preparing -> state finished

Thread-363719::DEBUG::2013-10-15
19:24:12,490::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363719::DEBUG::2013-10-15
19:24:12,490::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363719::DEBUG::2013-10-15
19:24:12,490::task::957::TaskManager.Task::(_decref)
Task=`cb5f0f17-fe04-44b9-8fcb-7643e0ed0a11`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:13,099::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 78.

Thread-89621::DEBUG::2013-10-15
19:24:15,235::task::568::TaskManager.Task::(_updateState)
Task=`9a53f6e1-7fa3-4b09-bded-7f692c9ac8fd`::moving from state init ->
state preparing

Thread-89621::INFO::2013-10-15
19:24:15,235::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='86fd8e9f-dba9-4f74-90b1-b6db5b89f2d3',
volUUID='ec6af89e-c1bd-4158-a792-53db7ecb530c', options=None)

Thread-89621::DEBUG::2013-10-15
19:24:15,239::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for ec6af89e-c1bd-4158-a792-53db7ecb530c

Thread-89621::INFO::2013-10-15
19:24:15,242::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '43427708928', 'apparentsize':
'53687091200'}

Thread-89621::DEBUG::2013-10-15
19:24:15,242::task::1151::TaskManager.Task::(prepare)
Task=`9a53f6e1-7fa3-4b09-bded-7f692c9ac8fd`::finished: {'truesize':
'43427708928', 'apparentsize': '53687091200'}

Thread-89621::DEBUG::2013-10-15
19:24:15,242::task::568::TaskManager.Task::(_updateState)
Task=`9a53f6e1-7fa3-4b09-bded-7f692c9ac8fd`::moving from state
preparing -> state finished

Thread-89621::DEBUG::2013-10-15
19:24:15,243::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-89621::DEBUG::2013-10-15
19:24:15,243::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-89621::DEBUG::2013-10-15
19:24:15,243::task::957::TaskManager.Task::(_decref)
Task=`9a53f6e1-7fa3-4b09-bded-7f692c9ac8fd`::ref 0 aborting False

Thread-89621::DEBUG::2013-10-15
19:24:15,244::task::568::TaskManager.Task::(_updateState)
Task=`f38a9b5b-f5cf-4bb2-b0aa-3d61a6091ef6`::moving from state init ->
state preparing

Thread-89621::INFO::2013-10-15
19:24:15,244::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='253d7bfc-c3b3-4ab2-bc48-0ea06dfea662',
volUUID='f347ea5a-db1e-42e6-8761-ae4dbb7fe3bd', options=None)

Thread-89621::DEBUG::2013-10-15
19:24:15,248::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for f347ea5a-db1e-42e6-8761-ae4dbb7fe3bd

Thread-89621::INFO::2013-10-15
19:24:15,251::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '201092349952', 'apparentsize':
'214748364800'}

Thread-89621::DEBUG::2013-10-15
19:24:15,251::task::1151::TaskManager.Task::(prepare)
Task=`f38a9b5b-f5cf-4bb2-b0aa-3d61a6091ef6`::finished: {'truesize':
'201092349952', 'apparentsize': '214748364800'}

Thread-89621::DEBUG::2013-10-15
19:24:15,251::task::568::TaskManager.Task::(_updateState)
Task=`f38a9b5b-f5cf-4bb2-b0aa-3d61a6091ef6`::moving from state
preparing -> state finished

Thread-89621::DEBUG::2013-10-15
19:24:15,251::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-89621::DEBUG::2013-10-15
19:24:15,252::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-89621::DEBUG::2013-10-15
19:24:15,252::task::957::TaskManager.Task::(_decref)
Task=`f38a9b5b-f5cf-4bb2-b0aa-3d61a6091ef6`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:18,103::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 93.

Thread-3186::DEBUG::2013-10-15
19:24:20,579::task::568::TaskManager.Task::(_updateState)
Task=`26d73e84-3fb2-4e6f-aaeb-1907eeba0383`::moving from state init ->
state preparing

Thread-3186::INFO::2013-10-15
19:24:20,580::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='9025469e-78c7-4c22-affa-fefc04558cc1',
volUUID='4f275b5a-bb0c-46da-8fc1-36cb21c982f1', options=None)

Thread-3197::DEBUG::2013-10-15
19:24:20,580::task::568::TaskManager.Task::(_updateState)
Task=`6d3441fa-a343-4e83-a8d7-ba029eaf3854`::moving from state init ->
state preparing

Thread-3197::INFO::2013-10-15
19:24:20,581::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='add15d07-5c94-428d-affe-d4d6e0c8b9b0',
volUUID='066c921f-d9cc-4d4d-8283-dde22138a9f6', options=None)

Thread-3304::DEBUG::2013-10-15
19:24:20,584::task::568::TaskManager.Task::(_updateState)
Task=`de16904a-b59f-41f9-b48c-860cbc43f5ba`::moving from state init ->
state preparing

Thread-3304::INFO::2013-10-15
19:24:20,584::logUtils::41::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='fa3279ec-2912-45ac-b7bc-9fe89151ed99',
spUUID='430cd986-6488-403b-8d46-29abbc3eba38',
imgUUID='3f580639-d72a-464f-8ed3-2453cbf9196a',
volUUID='e2b2c6a3-38c8-4a97-9747-fc508f985448', options=None)

Thread-3186::DEBUG::2013-10-15
19:24:20,586::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for 4f275b5a-bb0c-46da-8fc1-36cb21c982f1

Thread-3197::DEBUG::2013-10-15
19:24:20,588::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for 066c921f-d9cc-4d4d-8283-dde22138a9f6

Thread-3186::INFO::2013-10-15
19:24:20,592::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '3157008384', 'apparentsize':
'3144744960'}

Thread-3304::DEBUG::2013-10-15
19:24:20,592::fileVolume::561::Storage.Volume::(validateVolumePath)
validate path for e2b2c6a3-38c8-4a97-9747-fc508f985448

Thread-3197::INFO::2013-10-15
19:24:20,593::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '4603097088', 'apparentsize':
'4585160704'}

Thread-3186::DEBUG::2013-10-15
19:24:20,593::task::1151::TaskManager.Task::(prepare)
Task=`26d73e84-3fb2-4e6f-aaeb-1907eeba0383`::finished: {'truesize':
'3157008384', 'apparentsize': '3144744960'}

Thread-3197::DEBUG::2013-10-15
19:24:20,594::task::1151::TaskManager.Task::(prepare)
Task=`6d3441fa-a343-4e83-a8d7-ba029eaf3854`::finished: {'truesize':
'4603097088', 'apparentsize': '4585160704'}

Thread-3186::DEBUG::2013-10-15
19:24:20,594::task::568::TaskManager.Task::(_updateState)
Task=`26d73e84-3fb2-4e6f-aaeb-1907eeba0383`::moving from state
preparing -> state finished

Thread-3197::DEBUG::2013-10-15
19:24:20,595::task::568::TaskManager.Task::(_updateState)
Task=`6d3441fa-a343-4e83-a8d7-ba029eaf3854`::moving from state
preparing -> state finished

Thread-3186::DEBUG::2013-10-15
19:24:20,595::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-3197::DEBUG::2013-10-15
19:24:20,596::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-3186::DEBUG::2013-10-15
19:24:20,596::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-3304::INFO::2013-10-15
19:24:20,597::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize, Return response: {'truesize': '3145695232', 'apparentsize':
'3133472768'}

Thread-3197::DEBUG::2013-10-15
19:24:20,597::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-3186::DEBUG::2013-10-15
19:24:20,597::task::957::TaskManager.Task::(_decref)
Task=`26d73e84-3fb2-4e6f-aaeb-1907eeba0383`::ref 0 aborting False

Thread-3304::DEBUG::2013-10-15
19:24:20,598::task::1151::TaskManager.Task::(prepare)
Task=`de16904a-b59f-41f9-b48c-860cbc43f5ba`::finished: {'truesize':
'3145695232', 'apparentsize': '3133472768'}

Thread-3197::DEBUG::2013-10-15
19:24:20,598::task::957::TaskManager.Task::(_decref)
Task=`6d3441fa-a343-4e83-a8d7-ba029eaf3854`::ref 0 aborting False

Thread-3304::DEBUG::2013-10-15
19:24:20,598::task::568::TaskManager.Task::(_updateState)
Task=`de16904a-b59f-41f9-b48c-860cbc43f5ba`::moving from state
preparing -> state finished

Thread-3304::DEBUG::2013-10-15
19:24:20,599::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-3304::DEBUG::2013-10-15
19:24:20,599::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-3304::DEBUG::2013-10-15
19:24:20,599::task::957::TaskManager.Task::(_decref)
Task=`de16904a-b59f-41f9-b48c-860cbc43f5ba`::ref 0 aborting False

Thread-363725::DEBUG::2013-10-15
19:24:22,791::task::568::TaskManager.Task::(_updateState)
Task=`f29b0787-f8a0-4ac2-be7d-153b14d77be3`::moving from state init ->
state preparing

Thread-363725::INFO::2013-10-15
19:24:22,792::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363725::INFO::2013-10-15
19:24:22,792::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00645804405212', 'lastCheck': '7.3', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00722193717957',
'lastCheck': '0.2', 'code': 0, 'valid': True}}

Thread-363725::DEBUG::2013-10-15
19:24:22,792::task::1151::TaskManager.Task::(prepare)
Task=`f29b0787-f8a0-4ac2-be7d-153b14d77be3`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00645804405212',
'lastCheck': '7.3', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00722193717957',
'lastCheck': '0.2', 'code': 0, 'valid': True}}

Thread-363725::DEBUG::2013-10-15
19:24:22,793::task::568::TaskManager.Task::(_updateState)
Task=`f29b0787-f8a0-4ac2-be7d-153b14d77be3`::moving from state
preparing -> state finished

Thread-363725::DEBUG::2013-10-15
19:24:22,793::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363725::DEBUG::2013-10-15
19:24:22,793::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363725::DEBUG::2013-10-15
19:24:22,794::task::957::TaskManager.Task::(_decref)
Task=`f29b0787-f8a0-4ac2-be7d-153b14d77be3`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:26,110::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 20.

VM Channels Listener::DEBUG::2013-10-15
19:24:29,113::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 83.

VM Channels Listener::DEBUG::2013-10-15
19:24:32,115::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 60.

Thread-363731::DEBUG::2013-10-15
19:24:33,081::task::568::TaskManager.Task::(_updateState)
Task=`f6fb70e4-5130-4ef3-8e78-603f3bf20447`::moving from state init ->
state preparing

Thread-363731::INFO::2013-10-15
19:24:33,081::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363731::INFO::2013-10-15
19:24:33,082::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00757598876953', 'lastCheck': '7.5', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00686383247375',
'lastCheck': '0.4', 'code': 0, 'valid': True}}

Thread-363731::DEBUG::2013-10-15
19:24:33,082::task::1151::TaskManager.Task::(prepare)
Task=`f6fb70e4-5130-4ef3-8e78-603f3bf20447`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00757598876953',
'lastCheck': '7.5', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00686383247375',
'lastCheck': '0.4', 'code': 0, 'valid': True}}

Thread-363731::DEBUG::2013-10-15
19:24:33,082::task::568::TaskManager.Task::(_updateState)
Task=`f6fb70e4-5130-4ef3-8e78-603f3bf20447`::moving from state
preparing -> state finished

Thread-363731::DEBUG::2013-10-15
19:24:33,082::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363731::DEBUG::2013-10-15
19:24:33,083::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363731::DEBUG::2013-10-15
19:24:33,083::task::957::TaskManager.Task::(_decref)
Task=`f6fb70e4-5130-4ef3-8e78-603f3bf20447`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:34,117::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 86.

VM Channels Listener::DEBUG::2013-10-15
19:24:35,119::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 65.

VM Channels Listener::DEBUG::2013-10-15
19:24:43,125::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 78.

Thread-363737::DEBUG::2013-10-15
19:24:43,372::task::568::TaskManager.Task::(_updateState)
Task=`576f2cb3-5299-4c0e-a0d8-08f664ce6fdb`::moving from state init ->
state preparing

Thread-363737::INFO::2013-10-15
19:24:43,373::logUtils::41::dispatcher::(wrapper) Run and protect:
repoStats(options=None)

Thread-363737::INFO::2013-10-15
19:24:43,373::logUtils::44::dispatcher::(wrapper) Run and protect:
repoStats, Return response: {'fa3279ec-2912-45ac-b7bc-9fe89151ed99':
{'delay': '0.00689101219177', 'lastCheck': '7.8', 'code': 0, 'valid':
True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00665497779846',
'lastCheck': '0.7', 'code': 0, 'valid': True}}

Thread-363737::DEBUG::2013-10-15
19:24:43,374::task::1151::TaskManager.Task::(prepare)
Task=`576f2cb3-5299-4c0e-a0d8-08f664ce6fdb`::finished:
{'fa3279ec-2912-45ac-b7bc-9fe89151ed99': {'delay': '0.00689101219177',
'lastCheck': '7.8', 'code': 0, 'valid': True},
'ee2ae498-6e45-448d-8f91-0efca377dcf6': {'delay': '0.00665497779846',
'lastCheck': '0.7', 'code': 0, 'valid': True}}

Thread-363737::DEBUG::2013-10-15
19:24:43,374::task::568::TaskManager.Task::(_updateState)
Task=`576f2cb3-5299-4c0e-a0d8-08f664ce6fdb`::moving from state
preparing -> state finished

Thread-363737::DEBUG::2013-10-15
19:24:43,374::resourceManager::830::ResourceManager.Owner::(releaseAll
) Owner.releaseAll requests {} resources {}

Thread-363737::DEBUG::2013-10-15
19:24:43,375::resourceManager::864::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}

Thread-363737::DEBUG::2013-10-15
19:24:43,375::task::957::TaskManager.Task::(_decref)
Task=`576f2cb3-5299-4c0e-a0d8-08f664ce6fdb`::ref 0 aborting False

VM Channels Listener::DEBUG::2013-10-15
19:24:48,129::vmChannels::61::vds::(_handle_timeouts) Timeout on fileno 93.







-----Original Message-----
From: Daniel Erez [mailto:de...@redhat.com]
Sent: Monday, October 14, 2013 2:44 PM
To: Aslam, Usman
Cc: users@ovirt.org
Subject: Re: [Users] Unable to remove Vdisk and Ovirt UI spams
finished messages







----- Original Message -----

From: "Usman Aslam"
<usman.as...@tufts.edu<mailto:usman.as...@tufts.edu>>

To: users@ovirt.org<mailto:users@ovirt.org>

Sent: Wednesday, October 9, 2013 2:28:05 AM

Subject: [Users] Unable to remove Vdisk and Ovirt UI spams finished

messages



So I removed a Vdisk from a powered off VM a few hours ago. The Disk

still shows it has a lock on it and the webUI keeps showing this

message every 10 seconds or so.



2013-Oct-08, 19:22:09 User <UNKNOWN> finished to remove the disk

tuskdb-dev-01_vdisk01_50gb from domain TSS-TUSK-DC_NFS-VM-Stor.

2013-Oct-08, 19:21:59 User <UNKNOWN> finished to remove the disk

tuskdb-dev-01_vdisk01_50gb from domain TSS-TUSK-DC_NFS-VM-Stor.

2013-Oct-08, 19:21:49 User <UNKNOWN> finished to remove the disk

tuskdb-dev-01_vdisk01_50gb from domain TSS-TUSK-DC_NFS-VM-Stor.

2013-Oct-08, 19:21:39 User <UNKNOWN> finished to remove the disk

tuskdb-dev-01_vdisk01_50gb from domain TSS-TUSK-DC_NFS-VM-Stor.

2013-Oct-08, 19:21:29 User <UNKNOWN> finished to remove the disk

tuskdb-dev-01_vdisk01_50gb from domain TSS-TUSK-DC_NFS-VM-Stor.



I've tried restarting the SPM Hypervisor and the Ovirt Engine. Still
no dice.

Which host would have the lock? Where should I look for log files?



The logs for vdsm/engine are located at /var/log/vdsm/ and
/var/log/ovirt-engine/ correspondingly.

Try to check if there's any non-cleared task at the SPM (vdsClient ->
getAllTasks).

For manually clearing the task, the async_task table in the DB can be
manipulated.

Disk's status resides at images tables -> imagestatus column ('1' for
OK/unlocked).

Please attach vdsm/engine logs for further investigation...





Thanks,

Usman

_______________________________________________

Users mailing list

Users@ovirt.org<mailto:Users@ovirt.org>

http://lists.ovirt.org/mailman/listinfo/users



_______________________________________________
Users mailing list
Users@ovirt.org
http://lists.ovirt.org/mailman/listinfo/users


_______________________________________________
Users mailing list
Users@ovirt.org
http://lists.ovirt.org/mailman/listinfo/users