The log use to debug the function of ChangeTemplate

Posted 2020-06-28 li_Jiejun

2016-03-24 16:12:53,172 INFO  [org.ovirt.engine.core.bll.aaa.LoginUserCommand] (http--0.0.0.0-8080-2) Running command: LoginUserCommand internal: false.
2016-03-24 16:12:53,180 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-2) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User [email protected] logged in.
2016-03-24 16:12:53,220 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-2) 000000000000000--------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:12:53,284 WARN  [org.ovirt.engine.core.bll.ChangeVmTemplateCommand] (http--0.0.0.0-8080-2) [2542529e] CanDoAction of action ChangeVmTemplate failed for user [email protected] Reasons: VAR__ACTION__UPDATE,VAR__TYPE__VM,DONOT_NEED_TO_SWITCH_TO_SAME_TEMPLATE
2016-03-24 16:12:53,289 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (http--0.0.0.0-8080-2) Operation Failed: [Do not need to switch to the same template.]
2016-03-24 16:12:53,333 INFO  [org.ovirt.engine.core.bll.aaa.LogoutBySessionCommand] (http--0.0.0.0-8080-2) [1c030aff] Running command: LogoutBySessionCommand internal: false.
2016-03-24 16:12:53,339 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (http--0.0.0.0-8080-2) [27a103c3] Running command: LogoutUserCommand internal: false.
2016-03-24 16:12:53,355 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-2) [27a103c3] Correlation ID: 27a103c3, Call Stack: null, Custom Event ID: -1, Message: User [email protected] logged out.
2016-03-24 16:13:00,723 INFO  [org.ovirt.engine.core.bll.aaa.LoginUserCommand] (http--0.0.0.0-8080-1) Running command: LoginUserCommand internal: false.
2016-03-24 16:13:00,730 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User [email protected] logged in.
2016-03-24 16:13:00,732 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 000000000000000--------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:00,747 INFO  [org.ovirt.engine.core.bll.ChangeVmTemplateCommand] (http--0.0.0.0-8080-1) [251078ff] Running command: ChangeVmTemplateCommand internal: false. Entities affected :  ID: 0b940528-b486-405c-be8a-eb1d2a763d13 Type: VMAction group EDIT_VM_PROPERTIES with role type USER
2016-03-24 16:13:00,803 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [1e21185d] Lock Acquired to object EngineLock [exclusiveLocks= key: 0b940528-b486-405c-be8a-eb1d2a763d13 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:00,804 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [1e21185d] Running command: UpdateVmVersionCommand internal: true. Entities affected :  ID: 0b940528-b486-405c-be8a-eb1d2a763d13 Type: VM
2016-03-24 16:13:00,990 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (http--0.0.0.0-8080-1) [5d1c177f] Running command: RemoveVmCommand internal: true. Entities affected :  ID: 0b940528-b486-405c-be8a-eb1d2a763d13 Type: VMAction group DELETE_VM with role type USER
2016-03-24 16:13:01,011 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [5d1c177f] START, SetVmStatusVDSCommand( vmId = 0b940528-b486-405c-be8a-eb1d2a763d13, status = ImageLocked, exit status = Normal), log id: 75fc3111
2016-03-24 16:13:01,036 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [5d1c177f] FINISH, SetVmStatusVDSCommand, log id: 75fc3111
2016-03-24 16:13:01,055 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (http--0.0.0.0-8080-1) [5d1c177f] Lock freed to object EngineLock [exclusiveLocks= key: 0b940528-b486-405c-be8a-eb1d2a763d13 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:01,168 INFO  [org.ovirt.engine.core.bll.RemoveAllVmImagesCommand] (http--0.0.0.0-8080-1) [adcc3c2] Running command: RemoveAllVmImagesCommand internal: true. Entities affected :  ID: 0b940528-b486-405c-be8a-eb1d2a763d13 Type: VM
2016-03-24 16:13:01,185 INFO  [org.ovirt.engine.core.bll.RemoveImageCommand] (http--0.0.0.0-8080-1) [48cd3367] Running command: RemoveImageCommand internal: true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2016-03-24 16:13:01,494 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (http--0.0.0.0-8080-1) [48cd3367] START, DeleteImageGroupVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = 9407287d-79eb-407f-9cac-a52e2ffaaa55, postZeros = false, forceDelete = false), log id: 6cd900d2
2016-03-24 16:13:02,093 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (http--0.0.0.0-8080-1) [48cd3367] FINISH, DeleteImageGroupVDSCommand, log id: 6cd900d2
2016-03-24 16:13:02,099 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (http--0.0.0.0-8080-1) [48cd3367] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command b72ee249-fa39-4468-935d-378c01b579d1
2016-03-24 16:13:02,099 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (http--0.0.0.0-8080-1) [48cd3367] CommandMultiAsyncTasks::AttachTask: Attaching task f3e086ce-c44f-4ee7-82cc-8e23f7418441 to command b72ee249-fa39-4468-935d-378c01b579d1.
2016-03-24 16:13:02,147 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (http--0.0.0.0-8080-1) [48cd3367] Adding task f3e086ce-c44f-4ee7-82cc-8e23f7418441 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2016-03-24 16:13:02,322 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) [48cd3367] Correlation ID: 5d1c177f, Call Stack: null, Custom Event ID: -1, Message: VM changeTemplate was successfully removed.
2016-03-24 16:13:02,323 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (http--0.0.0.0-8080-1) [48cd3367] BaseAsyncTask::startPollingTask: Starting to poll task f3e086ce-c44f-4ee7-82cc-8e23f7418441.
2016-03-24 16:13:02,493 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (http--0.0.0.0-8080-1) [6ed9a9bb] Lock Acquired to object EngineLock [exclusiveLocks= key: changeTemplate value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:02,578 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (http--0.0.0.0-8080-1) [6ed9a9bb] Running command: AddVmCommand internal: true. Entities affected :  ID: 589888aa-baef-4311-8ed7-2ed8c0cf2e42 Type: VdsGroupsAction group CREATE_VM with role type USER,  ID: 8fef6b63-701d-400f-808f-42f73f6b7c24 Type: VmTemplateAction group CREATE_VM with role type USER,  ID: 4e7743c9-b31c-4959-b9d4-57b43439b46a Type: StorageAction group CREATE_DISK with role type USER
2016-03-24 16:13:02,665 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [6ed9a9bb] START, SetVmStatusVDSCommand( vmId = 0b940528-b486-405c-be8a-eb1d2a763d13, status = ImageLocked, exit status = Normal), log id: 2ff710c4
2016-03-24 16:13:02,682 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [6ed9a9bb] FINISH, SetVmStatusVDSCommand, log id: 2ff710c4
2016-03-24 16:13:02,756 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (http--0.0.0.0-8080-1) [15a6d88] Running command: CreateSnapshotFromTemplateCommand internal: true. Entities affected :  ID: 4e7743c9-b31c-4959-b9d4-57b43439b46a Type: Storage
2016-03-24 16:13:02,762 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [15a6d88] START, CreateSnapshotVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = c897e817-3f74-4b49-bc64-11345a29546d, imageSizeInBytes = 5368709120, volumeFormat = COW, newImageId = 60491c07-2670-4ada-b435-733588e732e1, newImageDescription = , imageId = 7e41ed63-618d-4a3d-a567-7e96901238bf, sourceImageGroupId = c654233a-195b-477e-8612-be58ffa2fccc), log id: 4caa11c2
2016-03-24 16:13:02,766 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [15a6d88] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
2016-03-24 16:13:03,322 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [15a6d88] FINISH, CreateSnapshotVDSCommand, return: 60491c07-2670-4ada-b435-733588e732e1, log id: 4caa11c2
2016-03-24 16:13:03,324 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (http--0.0.0.0-8080-1) [15a6d88] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command e0a3a275-e0ea-456f-b517-17df27f96419
2016-03-24 16:13:03,324 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (http--0.0.0.0-8080-1) [15a6d88] CommandMultiAsyncTasks::AttachTask: Attaching task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3 to command e0a3a275-e0ea-456f-b517-17df27f96419.
2016-03-24 16:13:03,398 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (http--0.0.0.0-8080-1) [15a6d88] Adding task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3 (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2016-03-24 16:13:03,598 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) [15a6d88] Correlation ID: 6ed9a9bb, Call Stack: null, Custom Event ID: -1, Message: VM changeTemplate creation was initiated by SYSTEM.
2016-03-24 16:13:03,599 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (http--0.0.0.0-8080-1) [15a6d88] BaseAsyncTask::startPollingTask: Starting to poll task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3.
2016-03-24 16:13:03,633 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (http--0.0.0.0-8080-1) [15a6d88] Trying to release exclusive lock which does not exist, lock key: 0b940528-b486-405c-be8a-eb1d2a763d13VM
2016-03-24 16:13:03,634 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [15a6d88] Lock freed to object EngineLock [exclusiveLocks= key: 0b940528-b486-405c-be8a-eb1d2a763d13 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:03,638 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 1111111111111111111111111111111-------200
2016-03-24 16:13:03,639 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 2222222222222222222222222222222-------0b940528-b486-405c-be8a-eb1d2a763d13
2016-03-24 16:13:03,639 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 000000000000000--------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:03,657 INFO  [org.ovirt.engine.core.bll.ChangeVmTemplateCommand] (http--0.0.0.0-8080-1) [4eb15395] Running command: ChangeVmTemplateCommand internal: false. Entities affected :  ID: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 Type: VMAction group EDIT_VM_PROPERTIES with role type USER
2016-03-24 16:13:03,675 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [641d1fa4] Lock Acquired to object EngineLock [exclusiveLocks= key: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:03,678 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [641d1fa4] Running command: UpdateVmVersionCommand internal: true. Entities affected :  ID: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 Type: VM
2016-03-24 16:13:03,718 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (http--0.0.0.0-8080-1) [5b3d4173] Running command: RemoveVmCommand internal: true. Entities affected :  ID: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 Type: VMAction group DELETE_VM with role type USER
2016-03-24 16:13:03,719 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [5b3d4173] START, SetVmStatusVDSCommand( vmId = 8c2de97c-28ff-4a10-8c06-f03398b16ec2, status = ImageLocked, exit status = Normal), log id: 776829ac
2016-03-24 16:13:03,723 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [5b3d4173] FINISH, SetVmStatusVDSCommand, log id: 776829ac
2016-03-24 16:13:03,732 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (http--0.0.0.0-8080-1) [5b3d4173] Lock freed to object EngineLock [exclusiveLocks= key: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:03,752 INFO  [org.ovirt.engine.core.bll.RemoveAllVmImagesCommand] (http--0.0.0.0-8080-1) [58ca2f73] Running command: RemoveAllVmImagesCommand internal: true. Entities affected :  ID: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 Type: VM
2016-03-24 16:13:03,756 INFO  [org.ovirt.engine.core.bll.RemoveImageCommand] (http--0.0.0.0-8080-1) [3456283d] Running command: RemoveImageCommand internal: true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
2016-03-24 16:13:03,800 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (http--0.0.0.0-8080-1) [3456283d] START, DeleteImageGroupVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = 7ef3dc3d-33d0-4220-9f93-4cd712a3c2ba, postZeros = false, forceDelete = false), log id: 2495d2ae
2016-03-24 16:13:04,750 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (http--0.0.0.0-8080-1) [3456283d] FINISH, DeleteImageGroupVDSCommand, log id: 2495d2ae
2016-03-24 16:13:04,753 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (http--0.0.0.0-8080-1) [3456283d] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command ae83fcea-fa20-4d0a-9bbb-1553a9d1f1ef
2016-03-24 16:13:04,754 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (http--0.0.0.0-8080-1) [3456283d] CommandMultiAsyncTasks::AttachTask: Attaching task 87cb44fb-6027-4d70-addf-a6a1c28e6a68 to command ae83fcea-fa20-4d0a-9bbb-1553a9d1f1ef.
2016-03-24 16:13:04,782 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (http--0.0.0.0-8080-1) [3456283d] Adding task 87cb44fb-6027-4d70-addf-a6a1c28e6a68 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2016-03-24 16:13:04,840 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) [3456283d] Correlation ID: 5b3d4173, Call Stack: null, Custom Event ID: -1, Message: VM 1111 was successfully removed.
2016-03-24 16:13:04,841 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (http--0.0.0.0-8080-1) [3456283d] BaseAsyncTask::startPollingTask: Starting to poll task 87cb44fb-6027-4d70-addf-a6a1c28e6a68.
2016-03-24 16:13:04,880 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (http--0.0.0.0-8080-1) [761350b6] Lock Acquired to object EngineLock [exclusiveLocks= key: 1111 value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:04,932 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (http--0.0.0.0-8080-1) [761350b6] Running command: AddVmCommand internal: true. Entities affected :  ID: 589888aa-baef-4311-8ed7-2ed8c0cf2e42 Type: VdsGroupsAction group CREATE_VM with role type USER,  ID: 8fef6b63-701d-400f-808f-42f73f6b7c24 Type: VmTemplateAction group CREATE_VM with role type USER,  ID: 4e7743c9-b31c-4959-b9d4-57b43439b46a Type: StorageAction group CREATE_DISK with role type USER
2016-03-24 16:13:04,954 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [761350b6] START, SetVmStatusVDSCommand( vmId = 8c2de97c-28ff-4a10-8c06-f03398b16ec2, status = ImageLocked, exit status = Normal), log id: 110deb19
2016-03-24 16:13:04,974 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (http--0.0.0.0-8080-1) [761350b6] FINISH, SetVmStatusVDSCommand, log id: 110deb19
2016-03-24 16:13:05,041 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (http--0.0.0.0-8080-1) [1e6540f2] Running command: CreateSnapshotFromTemplateCommand internal: true. Entities affected :  ID: 4e7743c9-b31c-4959-b9d4-57b43439b46a Type: Storage
2016-03-24 16:13:05,060 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [1e6540f2] START, CreateSnapshotVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = 4177f97e-3746-4b91-8af1-488e8871da57, imageSizeInBytes = 5368709120, volumeFormat = COW, newImageId = 84920c0a-be3f-48ba-9591-54168e91eb50, newImageDescription = , imageId = 7e41ed63-618d-4a3d-a567-7e96901238bf, sourceImageGroupId = c654233a-195b-477e-8612-be58ffa2fccc), log id: 56fbab38
2016-03-24 16:13:05,064 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [1e6540f2] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
2016-03-24 16:13:05,681 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (http--0.0.0.0-8080-1) [1e6540f2] FINISH, CreateSnapshotVDSCommand, return: 84920c0a-be3f-48ba-9591-54168e91eb50, log id: 56fbab38
2016-03-24 16:13:05,682 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (http--0.0.0.0-8080-1) [1e6540f2] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 7e6b01d1-dc94-49c2-b8d9-19a25674f7de
2016-03-24 16:13:05,683 INFO  [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (http--0.0.0.0-8080-1) [1e6540f2] CommandMultiAsyncTasks::AttachTask: Attaching task 1fa01cf5-8ab4-480b-ab09-155b57231bed to command 7e6b01d1-dc94-49c2-b8d9-19a25674f7de.
2016-03-24 16:13:05,707 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (http--0.0.0.0-8080-1) [1e6540f2] Adding task 1fa01cf5-8ab4-480b-ab09-155b57231bed (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2016-03-24 16:13:06,024 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) [1e6540f2] Correlation ID: 761350b6, Call Stack: null, Custom Event ID: -1, Message: VM 1111 creation was initiated by SYSTEM.
2016-03-24 16:13:06,025 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (http--0.0.0.0-8080-1) [1e6540f2] BaseAsyncTask::startPollingTask: Starting to poll task 1fa01cf5-8ab4-480b-ab09-155b57231bed.
2016-03-24 16:13:06,134 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (http--0.0.0.0-8080-1) [1e6540f2] Trying to release exclusive lock which does not exist, lock key: 8c2de97c-28ff-4a10-8c06-f03398b16ec2VM
2016-03-24 16:13:06,135 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (http--0.0.0.0-8080-1) [1e6540f2] Lock freed to object EngineLock [exclusiveLocks= key: 8c2de97c-28ff-4a10-8c06-f03398b16ec2 value: VM
, sharedLocks= key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:06,137 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 1111111111111111111111111111111-------200
2016-03-24 16:13:06,138 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 2222222222222222222222222222222-------8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:06,138 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 33333333333333333333333333333----------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:06,139 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 4444444444444444444444------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:06,140 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) 555555555555555555555-------0b940528-b486-405c-be8a-eb1d2a763d13,8c2de97c-28ff-4a10-8c06-f03398b16ec2
2016-03-24 16:13:06,141 INFO  [org.ovirt.engine.api.restapi.resource.BackendVmsResource] (http--0.0.0.0-8080-1) endddddddddddddddddddddddddddddddddddddddddddddddd
2016-03-24 16:13:06,152 INFO  [org.ovirt.engine.core.bll.aaa.LogoutBySessionCommand] (http--0.0.0.0-8080-1) [2301894e] Running command: LogoutBySessionCommand internal: false.
2016-03-24 16:13:06,160 INFO  [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (http--0.0.0.0-8080-1) [7282e553] Running command: LogoutUserCommand internal: false.
2016-03-24 16:13:06,174 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (http--0.0.0.0-8080-1) [7282e553] Correlation ID: 7282e553, Call Stack: null, Custom Event ID: -1, Message: User [email protected] logged out.
2016-03-24 16:13:12,170 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-22) Polling and updating Async Tasks: 4 tasks, 4 tasks to poll now
2016-03-24 16:13:12,193 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) SPMAsyncTask::PollTask: Polling task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3 (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2016-03-24 16:13:12,195 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) BaseAsyncTask::onTaskEndSuccess: Task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3 (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2016-03-24 16:13:12,197 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endActionIfNecessary: All tasks of command e0a3a275-e0ea-456f-b517-17df27f96419 has ended -> executing endAction
2016-03-24 16:13:12,198 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: e0a3a275-e0ea-456f-b517-17df27f96419): calling endAction .
2016-03-24 16:13:12,199 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) SPMAsyncTask::PollTask: Polling task 87cb44fb-6027-4d70-addf-a6a1c28e6a68 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2016-03-24 16:13:12,200 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-46) CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction AddVm, executionIndex: 0
2016-03-24 16:13:12,207 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) BaseAsyncTask::onTaskEndSuccess: Task 87cb44fb-6027-4d70-addf-a6a1c28e6a68 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2016-03-24 16:13:12,209 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endActionIfNecessary: All tasks of command ae83fcea-fa20-4d0a-9bbb-1553a9d1f1ef has ended -> executing endAction
2016-03-24 16:13:12,210 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: ae83fcea-fa20-4d0a-9bbb-1553a9d1f1ef): calling endAction .
2016-03-24 16:13:12,211 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) SPMAsyncTask::PollTask: Polling task 1fa01cf5-8ab4-480b-ab09-155b57231bed (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2016-03-24 16:13:12,211 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-47) CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction UpdateVmVersion, executionIndex: 0
2016-03-24 16:13:12,212 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) BaseAsyncTask::onTaskEndSuccess: Task 1fa01cf5-8ab4-480b-ab09-155b57231bed (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2016-03-24 16:13:12,219 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endActionIfNecessary: All tasks of command 7e6b01d1-dc94-49c2-b8d9-19a25674f7de has ended -> executing endAction
2016-03-24 16:13:12,220 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: 7e6b01d1-dc94-49c2-b8d9-19a25674f7de): calling endAction .
2016-03-24 16:13:12,220 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-49) CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction AddVm, executionIndex: 0
2016-03-24 16:13:12,221 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) SPMAsyncTask::PollTask: Polling task f3e086ce-c44f-4ee7-82cc-8e23f7418441 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2016-03-24 16:13:12,222 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-22) BaseAsyncTask::onTaskEndSuccess: Task f3e086ce-c44f-4ee7-82cc-8e23f7418441 (Parent Command UpdateVmVersion, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2016-03-24 16:13:12,223 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endActionIfNecessary: All tasks of command b72ee249-fa39-4468-935d-378c01b579d1 has ended -> executing endAction
2016-03-24 16:13:12,223 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-22) CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: b72ee249-fa39-4468-935d-378c01b579d1): calling endAction .
2016-03-24 16:13:12,225 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-50) CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction UpdateVmVersion, executionIndex: 0
2016-03-24 16:13:12,250 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (org.ovirt.thread.pool-8-thread-47) [641d1fa4] Ending command successfully: org.ovirt.engine.core.bll.UpdateVmVersionCommand
2016-03-24 16:13:12,258 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-49) [761350b6] Ending command successfully: org.ovirt.engine.core.bll.AddVmCommand
2016-03-24 16:13:12,267 INFO  [org.ovirt.engine.core.bll.UpdateVmVersionCommand] (org.ovirt.thread.pool-8-thread-50) [1e21185d] Ending command successfully: org.ovirt.engine.core.bll.UpdateVmVersionCommand
2016-03-24 16:13:12,286 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-46) [6ed9a9bb] Ending command successfully: org.ovirt.engine.core.bll.AddVmCommand
2016-03-24 16:13:12,279 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] Failed to Acquire Lock to object EngineLock [exclusiveLocks= key: 1111 value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:12,291 WARN  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] CanDoAction of action AddVm failed for user SYSTEM. Reasons: VAR__ACTION__ADD,VAR__TYPE__VM,ACTION_TYPE_FAILED_OBJECT_LOCKED
2016-03-24 16:13:12,291 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (org.ovirt.thread.pool-8-thread-49) [1e6540f2] Ending command successfully: org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand
2016-03-24 16:13:12,295 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-49) [1e6540f2] START, GetImageInfoVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = 4177f97e-3746-4b91-8af1-488e8871da57, imageId = 84920c0a-be3f-48ba-9591-54168e91eb50), log id: 70b73394
2016-03-24 16:13:12,313 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type UpdateVmVersion completed, handling the result.
2016-03-24 16:13:12,316 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type UpdateVmVersion succeeded, clearing tasks.
2016-03-24 16:13:12,317 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] SPMAsyncTask::ClearAsyncTask: Attempting to clear task 87cb44fb-6027-4d70-addf-a6a1c28e6a68
2016-03-24 16:13:12,324 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] START, SPMClearTaskVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, taskId = 87cb44fb-6027-4d70-addf-a6a1c28e6a68), log id: 19371726
2016-03-24 16:13:12,343 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] Failed to Acquire Lock to object EngineLock [exclusiveLocks= key: changeTemplate value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:12,344 WARN  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] CanDoAction of action AddVm failed for user SYSTEM. Reasons: VAR__ACTION__ADD,VAR__TYPE__VM,ACTION_TYPE_FAILED_OBJECT_LOCKED
2016-03-24 16:13:12,346 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-49) [1e6540f2] FINISH, GetImageInfoVDSCommand, return: [email protected], log id: 70b73394
2016-03-24 16:13:12,349 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-50) [5130ba78] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type UpdateVmVersion completed, handling the result.
2016-03-24 16:13:12,350 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-50) [5130ba78] CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type UpdateVmVersion succeeded, clearing tasks.
2016-03-24 16:13:12,350 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-50) [5130ba78] SPMAsyncTask::ClearAsyncTask: Attempting to clear task f3e086ce-c44f-4ee7-82cc-8e23f7418441
2016-03-24 16:13:12,351 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] START, SPMClearTaskVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, taskId = f3e086ce-c44f-4ee7-82cc-8e23f7418441), log id: 115105d4
2016-03-24 16:13:12,351 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] START, HSMClearTaskVDSCommand(HostName = 192.168.0.41, HostId = 355dd102-fd84-4945-b7f5-684550d9b572, taskId=87cb44fb-6027-4d70-addf-a6a1c28e6a68), log id: 6f4ec2e8
2016-03-24 16:13:12,375 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (org.ovirt.thread.pool-8-thread-49) START, SetVmStatusVDSCommand( vmId = 8c2de97c-28ff-4a10-8c06-f03398b16ec2, status = Down, exit status = Normal), log id: 12107c9c
2016-03-24 16:13:12,382 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (org.ovirt.thread.pool-8-thread-49) FINISH, SetVmStatusVDSCommand, log id: 12107c9c
2016-03-24 16:13:12,391 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (org.ovirt.thread.pool-8-thread-49) Trying to release a shared lock for key: 8fef6b63-701d-400f-808f-42f73f6b7c24TEMPLATE , but lock does not exist
2016-03-24 16:13:12,392 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-49) Lock freed to object EngineLock [exclusiveLocks= key: 1111 value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:12,399 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-49) Correlation ID: 761350b6, Call Stack: null, Custom Event ID: -1, Message: VM 1111 creation has been completed.
2016-03-24 16:13:12,400 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-49) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddVm completed, handling the result.
2016-03-24 16:13:12,401 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-49) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddVm succeeded, clearing tasks.
2016-03-24 16:13:12,401 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-49) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 1fa01cf5-8ab4-480b-ab09-155b57231bed
2016-03-24 16:13:12,402 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-49) START, SPMClearTaskVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, taskId = 1fa01cf5-8ab4-480b-ab09-155b57231bed), log id: 7717e089
2016-03-24 16:13:12,408 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] FINISH, HSMClearTaskVDSCommand, log id: 6f4ec2e8
2016-03-24 16:13:12,408 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] FINISH, SPMClearTaskVDSCommand, log id: 19371726
2016-03-24 16:13:12,409 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-49) START, HSMClearTaskVDSCommand(HostName = 192.168.0.41, HostId = 355dd102-fd84-4945-b7f5-684550d9b572, taskId=1fa01cf5-8ab4-480b-ab09-155b57231bed), log id: 29ed874d
2016-03-24 16:13:12,433 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] BaseAsyncTask::removeTaskFromDB: Removed task 87cb44fb-6027-4d70-addf-a6a1c28e6a68 from DataBase
2016-03-24 16:13:12,434 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-47) [1ee32e2e] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity ae83fcea-fa20-4d0a-9bbb-1553a9d1f1ef
2016-03-24 16:13:12,450 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (org.ovirt.thread.pool-8-thread-46) [15a6d88] Ending command successfully: org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand
2016-03-24 16:13:12,466 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-46) [15a6d88] START, GetImageInfoVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, storageDomainId = 4e7743c9-b31c-4959-b9d4-57b43439b46a, imageGroupId = c897e817-3f74-4b49-bc64-11345a29546d, imageId = 60491c07-2670-4ada-b435-733588e732e1), log id: fc80b25
2016-03-24 16:13:12,470 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-49) FINISH, HSMClearTaskVDSCommand, log id: 29ed874d
2016-03-24 16:13:12,470 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-49) FINISH, SPMClearTaskVDSCommand, log id: 7717e089
2016-03-24 16:13:12,475 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] START, HSMClearTaskVDSCommand(HostName = 192.168.0.41, HostId = 355dd102-fd84-4945-b7f5-684550d9b572, taskId=f3e086ce-c44f-4ee7-82cc-8e23f7418441), log id: 50da4af0
2016-03-24 16:13:12,491 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-49) BaseAsyncTask::removeTaskFromDB: Removed task 1fa01cf5-8ab4-480b-ab09-155b57231bed from DataBase
2016-03-24 16:13:12,492 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-49) CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 7e6b01d1-dc94-49c2-b8d9-19a25674f7de
2016-03-24 16:13:12,516 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] FINISH, HSMClearTaskVDSCommand, log id: 50da4af0
2016-03-24 16:13:12,516 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-50) [5130ba78] FINISH, SPMClearTaskVDSCommand, log id: 115105d4
2016-03-24 16:13:12,525 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-50) [5130ba78] BaseAsyncTask::removeTaskFromDB: Removed task f3e086ce-c44f-4ee7-82cc-8e23f7418441 from DataBase
2016-03-24 16:13:12,525 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-50) [5130ba78] CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity b72ee249-fa39-4468-935d-378c01b579d1
2016-03-24 16:13:12,552 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-46) [15a6d88] FINISH, GetImageInfoVDSCommand, return: [email protected], log id: fc80b25
2016-03-24 16:13:12,567 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (org.ovirt.thread.pool-8-thread-46) START, SetVmStatusVDSCommand( vmId = 0b940528-b486-405c-be8a-eb1d2a763d13, status = Down, exit status = Normal), log id: 75c191a7
2016-03-24 16:13:12,572 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (org.ovirt.thread.pool-8-thread-46) FINISH, SetVmStatusVDSCommand, log id: 75c191a7
2016-03-24 16:13:12,575 WARN  [org.ovirt.engine.core.bll.lock.InMemoryLockManager] (org.ovirt.thread.pool-8-thread-46) Trying to release a shared lock for key: 8fef6b63-701d-400f-808f-42f73f6b7c24TEMPLATE , but lock does not exist
2016-03-24 16:13:12,575 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (org.ovirt.thread.pool-8-thread-46) Lock freed to object EngineLock [exclusiveLocks= key: changeTemplate value: VM_NAME
, sharedLocks= key: c654233a-195b-477e-8612-be58ffa2fccc value: DISK
key: 8fef6b63-701d-400f-808f-42f73f6b7c24 value: TEMPLATE
]
2016-03-24 16:13:12,592 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-46) Correlation ID: 6ed9a9bb, Call Stack: null, Custom Event ID: -1, Message: VM changeTemplate creation has been completed.
2016-03-24 16:13:12,592 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-46) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddVm completed, handling the result.
2016-03-24 16:13:12,593 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-46) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddVm succeeded, clearing tasks.
2016-03-24 16:13:12,593 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-46) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3
2016-03-24 16:13:12,594 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-46) START, SPMClearTaskVDSCommand( storagePoolId = d2b85873-c8ed-4725-8230-09eb0aba54fc, ignoreFailoverLimit = false, taskId = 9d70d7b1-f0df-4342-ac67-9c42020e5cf3), log id: 1329de16
2016-03-24 16:13:12,596 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-46) START, HSMClearTaskVDSCommand(HostName = 192.168.0.41, HostId = 355dd102-fd84-4945-b7f5-684550d9b572, taskId=9d70d7b1-f0df-4342-ac67-9c42020e5cf3), log id: 21b3802e
2016-03-24 16:13:12,661 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-46) FINISH, HSMClearTaskVDSCommand, log id: 21b3802e
2016-03-24 16:13:12,661 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-46) FINISH, SPMClearTaskVDSCommand, log id: 1329de16
2016-03-24 16:13:12,675 INFO  [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-46) BaseAsyncTask::removeTaskFromDB: Removed task 9d70d7b1-f0df-4342-ac67-9c42020e5cf3 from DataBase
2016-03-24 16:13:12,675 INFO  [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-46) CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity e0a3a275-e0ea-456f-b517-17df27f96419