Attachment 609938 Details for Bug 854296 – engine log

engine log

engine.log (text/plain), 13.83 KB, created by Ondra Machacek on 2012-09-05 09:26:31 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Ondra Machacek

Created: 2012-09-05 09:26:31 UTC

Size: 13.83 KB

patch

obsolete

>2012-09-05 11:21:12,270 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] Lock Acquired to object EngineLock [exclusiveLocks= key: b value: VM_NAME
>, sharedLocks= ]
>2012-09-05 11:21:12,285 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] START, IsValidVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null), log id: a5452bf
>2012-09-05 11:21:12,286 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] FINISH, IsValidVDSCommand, return: true, log id: a5452bf
>2012-09-05 11:21:12,294 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] Running command: AddVmFromScratchCommand internal: false. Entities affected :  ID: 99408929-82cf-4dc7-a532-9d998063fa95 Type: VdsGroups
>2012-09-05 11:21:12,296 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] START, IsValidVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 46afa03c
>2012-09-05 11:21:12,297 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] FINISH, IsValidVDSCommand, return: true, log id: 46afa03c
>2012-09-05 11:21:12,353 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-4) [2b1b08ff] Lock freed to object EngineLock [exclusiveLocks= key: b value: VM_NAME
>, sharedLocks= ]
>2012-09-05 11:21:16,223 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-5) [19af58cc] Lock Acquired to object EngineLock [exclusiveLocks= key: d8514f75-76f3-4f4f-a657-d3e93132d4b2 value: VM_DISK_BOOT
>, sharedLocks= key: d8514f75-76f3-4f4f-a657-d3e93132d4b2 value: VM
>]
>2012-09-05 11:21:16,249 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [19af58cc] START, IsValidVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 7dc5b6a6
>2012-09-05 11:21:16,251 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [19af58cc] FINISH, IsValidVDSCommand, return: true, log id: 7dc5b6a6
>2012-09-05 11:21:16,262 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-5) [19af58cc] Running command: AddDiskCommand internal: false. Entities affected :  ID: d8514f75-76f3-4f4f-a657-d3e93132d4b2 Type: VM,  ID: 6dcb9597-55db-4826-8d14-1d0382f521cb Type: Storage
>2012-09-05 11:21:16,310 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] Running command: AddImageFromScratchCommand internal: true. Entities affected :  ID: 6dcb9597-55db-4826-8d14-1d0382f521cb Type: Storage
>2012-09-05 11:21:16,325 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] Lock freed to object EngineLock [exclusiveLocks= key: d8514f75-76f3-4f4f-a657-d3e93132d4b2 value: VM_DISK_BOOT
>, sharedLocks= key: d8514f75-76f3-4f4f-a657-d3e93132d4b2 value: VM
>]
>2012-09-05 11:21:16,327 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] START, CreateImageVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = 3.1, storageDomainId = 6dcb9597-55db-4826-8d14-1d0382f521cb, imageGroupId = d7a51f0c-4a19-481c-836b-9f05bc84e5dd, imageSizeInBytes = 10737418240, volumeFormat = RAW, newImageId = 8cb1e9a4-75d3-40c8-9bfe-7f5722537944, newImageDescription = ), log id: 375ab3d2
>2012-09-05 11:21:16,327 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] -- CreateImageVDSCommand::ExecuteIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
>2012-09-05 11:21:16,327 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] -- createVolume parameters:
>                sdUUID=6dcb9597-55db-4826-8d14-1d0382f521cb
>                spUUID=b267864c-f738-11e1-b17f-001a4a013f66
>                imgGUID=d7a51f0c-4a19-481c-836b-9f05bc84e5dd
>                size=10,737,418,240 bytes
>                volFormat=RAW
>                volType=Sparse
>                volUUID=8cb1e9a4-75d3-40c8-9bfe-7f5722537944
>                descr=
>                srcImgGUID=00000000-0000-0000-0000-000000000000
>                srcVolUUID=00000000-0000-0000-0000-000000000000
>                
>2012-09-05 11:21:16,399 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-5) [67f32a31] FINISH, CreateImageVDSCommand, return: 8cb1e9a4-75d3-40c8-9bfe-7f5722537944, log id: 375ab3d2
>2012-09-05 11:21:16,404 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (ajp-/127.0.0.1:8009-5) [67f32a31] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity d7a51f0c-4a19-481c-836b-9f05bc84e5dd
>2012-09-05 11:21:16,404 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [67f32a31] EntityMultiAsyncTasks::AttachTask: Attaching task 457d107e-bd1f-4288-8457-d195e4f9fcc0 to entity d7a51f0c-4a19-481c-836b-9f05bc84e5dd.
>2012-09-05 11:21:16,405 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (ajp-/127.0.0.1:8009-5) [67f32a31] Adding task 457d107e-bd1f-4288-8457-d195e4f9fcc0 to DataBase
>2012-09-05 11:21:16,432 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (ajp-/127.0.0.1:8009-5) [67f32a31] Adding task 457d107e-bd1f-4288-8457-d195e4f9fcc0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-05 11:21:16,472 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8009-5) [67f32a31] BaseAsyncTask::StartPollingTask: Starting to poll task 457d107e-bd1f-4288-8457-d195e4f9fcc0.
>2012-09-05 11:21:16,472 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [67f32a31] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity d7a51f0c-4a19-481c-836b-9f05bc84e5dd is AddDisk (determined by task 457d107e-bd1f-4288-8457-d195e4f9fcc0)
>2012-09-05 11:21:22,238 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-28) Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
>2012-09-05 11:21:22,255 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-28) SPMAsyncTask::PollTask: Polling task 457d107e-bd1f-4288-8457-d195e4f9fcc0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-05 11:21:22,262 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-28) BaseAsyncTask::OnTaskEndSuccess: Task 457d107e-bd1f-4288-8457-d195e4f9fcc0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-05 11:21:22,263 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-28) EntityAsyncTask::EndActionIfNecessary: All tasks of entity d7a51f0c-4a19-481c-836b-9f05bc84e5dd has ended -> executing EndAction
>2012-09-05 11:21:22,263 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-28) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: d7a51f0c-4a19-481c-836b-9f05bc84e5dd): calling EndAction for action type AddDisk.
>2012-09-05 11:21:22,266 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction AddDisk
>2012-09-05 11:21:22,277 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (pool-4-thread-50) [19af58cc] Ending command successfully: org.ovirt.engine.core.bll.AddDiskCommand
>2012-09-05 11:21:22,277 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (pool-4-thread-50) [67f32a31] Ending command successfully: org.ovirt.engine.core.bll.AddImageFromScratchCommand
>2012-09-05 11:21:22,284 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [67f32a31] START, GetImageInfoVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 6dcb9597-55db-4826-8d14-1d0382f521cb, imageGroupId = d7a51f0c-4a19-481c-836b-9f05bc84e5dd, imageId = 8cb1e9a4-75d3-40c8-9bfe-7f5722537944), log id: 83d14fc
>2012-09-05 11:21:22,316 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [67f32a31] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@b9def206, log id: 83d14fc
>2012-09-05 11:21:22,337 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) START, UpdateVMVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, infoDictionary.size = 1), log id: 3387239e
>2012-09-05 11:21:22,358 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) FINISH, UpdateVMVDSCommand, log id: 3387239e
>2012-09-05 11:21:22,373 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddDisk completed, handling the result.
>2012-09-05 11:21:22,373 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddDisk succeeded, clearing tasks.
>2012-09-05 11:21:22,377 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 457d107e-bd1f-4288-8457-d195e4f9fcc0
>2012-09-05 11:21:22,378 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) START, SPMClearTaskVDSCommand(storagePoolId = b267864c-f738-11e1-b17f-001a4a013f66, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = 457d107e-bd1f-4288-8457-d195e4f9fcc0), log id: 7a08d4a8
>2012-09-05 11:21:22,379 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) START, HSMClearTaskVDSCommand(vdsId = 2c685df4-f739-11e1-84f2-001a4a013f66, taskId=457d107e-bd1f-4288-8457-d195e4f9fcc0), log id: 122b6002
>2012-09-05 11:21:22,405 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) FINISH, HSMClearTaskVDSCommand, log id: 122b6002
>2012-09-05 11:21:22,405 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) FINISH, SPMClearTaskVDSCommand, log id: 7a08d4a8
>2012-09-05 11:21:22,409 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) BaseAsyncTask::RemoveTaskFromDB: Removed task 457d107e-bd1f-4288-8457-d195e4f9fcc0 from DataBase
>2012-09-05 11:21:22,409 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity d7a51f0c-4a19-481c-836b-9f05bc84e5dd
>2012-09-05 11:21:28,483 INFO  [org.ovirt.engine.core.bll.AddPermissionCommand] (pool-4-thread-50) [1bc4fa7] Running command: AddPermissionCommand internal: false. Entities affected :  ID: d8514f75-76f3-4f4f-a657-d3e93132d4b2 Type: VM
>2012-09-05 11:21:40,203 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-6) Checking if user portaluser2 is an admin, result false
>2012-09-05 11:21:40,203 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-6) Running command: LoginUserCommand internal: false.
>2012-09-05 11:21:40,216 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-6) calling GetConfigurationValueQuery (ApplicationMode) with null version, using default general for version
>2012-09-05 11:21:40,217 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-6) calling GetConfigurationValueQuery (VdcVersion) with null version, using default general for version
>2012-09-05 11:21:40,493 WARN  [org.ovirt.engine.core.bll.StopVmCommand] (ajp-/127.0.0.1:8009-4) [18a6c51c] CanDoAction of action StopVm failed. Reasons:ACTION_TYPE_FAILED_VM_IS_NOT_RUNNING,VAR__ACTION__STOP,VAR__TYPE__VM
>2012-09-05 11:21:40,498 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-4) Operation Failed: [Cannot stop VM. VM is not running.]
>2012-09-05 11:21:47,624 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-2) Checking if user portaluser2 is an admin, result false
>2012-09-05 11:21:47,625 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-2) Running command: LoginUserCommand internal: false.
>2012-09-05 11:21:47,639 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-2) calling GetConfigurationValueQuery (ApplicationMode) with null version, using default general for version
>2012-09-05 11:21:47,640 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-2) calling GetConfigurationValueQuery (VdcVersion) with null version, using default general for version
>2012-09-05 11:21:47,856 ERROR [org.ovirt.engine.core.bll.GetVmByVmIdQuery] (ajp-/127.0.0.1:8009-8) Query execution failed due to insufficient permissions.
>2012-09-05 11:21:47,858 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-8) Operation Failed: query execution failed due to insufficient permissions.
>2012-09-05 11:22:52,028 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-93) Setting new tasks map. The map contains now 0 tasks
>2012-09-05 11:22:52,028 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-93) Cleared all tasks of pool b267864c-f738-11e1-b17f-001a4a013f66.
>2012-09-05 11:22:52,031 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-93) Could not find vds that is spm and non-operational.

Actions: View

Attachments on bug 854296: 609938