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

From: "Usman Aslam" <Usman.Aslam(a)tufts.edu&gt; To: "Daniel Erez" <derez(a)redhat.com&gt; Cc: users(a)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!

###*** 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:derez@redhat.com] Sent: Monday, October 14, 2013 2:44 PM To: Aslam, Usman Cc: users(a)ovirt.org Subject: Re: [Users] Unable to remove Vdisk and Ovirt UI spams finished messages ----- Original Message ----- > From: "Usman Aslam" <Usman.Aslam@tufts.edu<mailto:Usman.Aslam@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 >