Attachment 612038 Details for Bug 856499 – engine.log

engine.log

engine.log (text/x-log), 15.26 KB, created by Ondra Machacek on 2012-09-12 09:14:45 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Ondra Machacek

Created: 2012-09-12 09:14:45 UTC

Size: 15.26 KB

patch

obsolete

>2012-09-12 11:05:53,970 INFO  [org.ovirt.engine.core.bll.AddPermissionCommand] (pool-4-thread-46) [4a221bd8] Running command: AddPermissionCommand internal: false. Entities affected :  ID: 8242301f-b256-4de3-8a52-eab923c91148 Type: StoragePool
>2012-09-12 11:06:22,734 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) START, IsValidVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 4c71676d
>2012-09-12 11:06:22,735 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) FINISH, IsValidVDSCommand, return: true, log id: 4c71676d
>2012-09-12 11:06:22,742 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) START, IsValidVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 7dc75c8d
>2012-09-12 11:06:22,743 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) FINISH, IsValidVDSCommand, return: true, log id: 7dc75c8d
>2012-09-12 11:06:22,771 INFO  [org.ovirt.engine.core.bll.AddVmPoolWithVmsCommand] (pool-4-thread-46) [2e71acb0] Running command: AddVmPoolWithVmsCommand internal: false. Entities affected :  ID: 25573d48-fc05-11e1-b852-001a4a013f66 Type: VdsGroups,  ID: 0b898000-d01d-4b3e-8ef8-86fc8b327adb Type: VmTemplate
>2012-09-12 11:06:22,812 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [6ae2ffeb] START, IsValidVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 376c3f65
>2012-09-12 11:06:22,813 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [6ae2ffeb] FINISH, IsValidVDSCommand, return: true, log id: 376c3f65
>2012-09-12 11:06:22,825 INFO  [org.ovirt.engine.core.bll.AddVmAndAttachToPoolCommand] (pool-4-thread-46) [6ae2ffeb] Running command: AddVmAndAttachToPoolCommand internal: true. Entities affected :  ID: 25573d48-fc05-11e1-b852-001a4a013f66 Type: VdsGroups,  ID: 0b898000-d01d-4b3e-8ef8-86fc8b327adb Type: VmTemplate,  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
>2012-09-12 11:06:22,834 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (pool-4-thread-46) [496e46a4] Lock Acquired to object EngineLock [exclusiveLocks= key: newPool-1 value: VM_NAME
>, sharedLocks= ]
>2012-09-12 11:06:22,855 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [496e46a4] START, IsValidVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 3e684d35
>2012-09-12 11:06:22,856 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [496e46a4] FINISH, IsValidVDSCommand, return: true, log id: 3e684d35
>2012-09-12 11:06:22,858 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (pool-4-thread-46) [496e46a4] Running command: AddVmCommand internal: true. Entities affected :  ID: 25573d48-fc05-11e1-b852-001a4a013f66 Type: VdsGroups,  ID: 0b898000-d01d-4b3e-8ef8-86fc8b327adb Type: VmTemplate,  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
>2012-09-12 11:06:22,860 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [496e46a4] START, IsValidVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 5b424159
>2012-09-12 11:06:22,861 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (pool-4-thread-46) [496e46a4] FINISH, IsValidVDSCommand, return: true, log id: 5b424159
>2012-09-12 11:06:22,905 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (pool-4-thread-46) [496e46a4] Lock freed to object EngineLock [exclusiveLocks= key: newPool-1 value: VM_NAME
>, sharedLocks= ]
>2012-09-12 11:06:22,905 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-46) [496e46a4] START, SetVmStatusVDSCommand(vmId = 22b22134-d01f-4751-8f92-9e639a783239, status = ImageLocked), log id: 7cb59d78
>2012-09-12 11:06:22,910 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-46) [496e46a4] FINISH, SetVmStatusVDSCommand, log id: 7cb59d78
>2012-09-12 11:06:22,911 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (pool-4-thread-46) [449da20e] Running command: CreateSnapshotFromTemplateCommand internal: true. Entities affected :  ID: db6c2823-fb8f-42db-9960-fd62a6688c7c Type: Storage
>2012-09-12 11:06:22,913 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-46) [449da20e] START, GetImageInfoVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = db6c2823-fb8f-42db-9960-fd62a6688c7c, imageGroupId = 401132c9-7216-4169-ac24-acf06c37fca6, imageId = fc027b61-ee76-48e4-9eb3-a64a19fadc3e), log id: 5664de23
>2012-09-12 11:06:22,935 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-46) [449da20e] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@255dfd49, log id: 5664de23
>2012-09-12 11:06:22,938 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (pool-4-thread-46) [449da20e] START, CreateSnapshotVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = 3.0, storageDomainId = db6c2823-fb8f-42db-9960-fd62a6688c7c, imageGroupId = e037e0e4-138e-4d0c-882d-6e964ac8b32a, imageSizeInBytes = 10737418240, volumeFormat = COW, newImageId = eee098d2-d18c-4e25-b477-48e55f497e14, newImageDescription = , imageId = fc027b61-ee76-48e4-9eb3-a64a19fadc3e, sourceImageGroupId = 401132c9-7216-4169-ac24-acf06c37fca6), log id: 512524c
>2012-09-12 11:06:22,938 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (pool-4-thread-46) [449da20e] -- CreateSnapshotVDSCommand::ExecuteIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
>2012-09-12 11:06:22,938 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (pool-4-thread-46) [449da20e] -- createVolume parameters:
>                sdUUID=db6c2823-fb8f-42db-9960-fd62a6688c7c
>                spUUID=8242301f-b256-4de3-8a52-eab923c91148
>                imgGUID=e037e0e4-138e-4d0c-882d-6e964ac8b32a
>                size=10,737,418,240 bytes
>                volFormat=COW
>                volType=Sparse
>                volUUID=eee098d2-d18c-4e25-b477-48e55f497e14
>                descr=
>                srcImgGUID=401132c9-7216-4169-ac24-acf06c37fca6
>                srcVolUUID=fc027b61-ee76-48e4-9eb3-a64a19fadc3e
>                
>2012-09-12 11:06:22,991 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateSnapshotVDSCommand] (pool-4-thread-46) [449da20e] FINISH, CreateSnapshotVDSCommand, return: eee098d2-d18c-4e25-b477-48e55f497e14, log id: 512524c
>2012-09-12 11:06:22,996 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-46) [449da20e] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 22b22134-d01f-4751-8f92-9e639a783239
>2012-09-12 11:06:22,996 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (pool-4-thread-46) [449da20e] EntityMultiAsyncTasks::AttachTask: Attaching task 962b73d4-d31d-4646-9476-3afd455696be to entity 22b22134-d01f-4751-8f92-9e639a783239.
>2012-09-12 11:06:22,997 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (pool-4-thread-46) [449da20e] Adding task 962b73d4-d31d-4646-9476-3afd455696be to DataBase
>2012-09-12 11:06:23,020 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (pool-4-thread-46) [449da20e] Adding task 962b73d4-d31d-4646-9476-3afd455696be (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-12 11:06:23,137 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-46) [449da20e] BaseAsyncTask::StartPollingTask: Starting to poll task 962b73d4-d31d-4646-9476-3afd455696be.
>2012-09-12 11:06:23,137 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (pool-4-thread-46) [449da20e] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 22b22134-d01f-4751-8f92-9e639a783239 is AddVm (determined by task 962b73d4-d31d-4646-9476-3afd455696be)
>2012-09-12 11:06:23,154 INFO  [org.ovirt.engine.core.bll.AddVmToPoolCommand] (pool-4-thread-46) [19c63168] Running command: AddVmToPoolCommand internal: true. Entities affected :  ID: 1fa29870-fcb9-11e1-9789-001a4a013f66 Type: VmPool
>2012-09-12 11:06:27,337 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-45) Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
>2012-09-12 11:06:27,346 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-45) SPMAsyncTask::PollTask: Polling task 962b73d4-d31d-4646-9476-3afd455696be (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-12 11:06:27,350 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-45) BaseAsyncTask::OnTaskEndSuccess: Task 962b73d4-d31d-4646-9476-3afd455696be (Parent Command AddVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-12 11:06:27,351 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-45) EntityAsyncTask::EndActionIfNecessary: All tasks of entity 22b22134-d01f-4751-8f92-9e639a783239 has ended -> executing EndAction
>2012-09-12 11:06:27,351 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-45) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 22b22134-d01f-4751-8f92-9e639a783239): calling EndAction for action type AddVm.
>2012-09-12 11:06:27,351 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-46) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction AddVm
>2012-09-12 11:06:27,365 INFO  [org.ovirt.engine.core.bll.AddVmCommand] (pool-4-thread-46) [496e46a4] Ending command successfully: org.ovirt.engine.core.bll.AddVmCommand
>2012-09-12 11:06:27,365 INFO  [org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand] (pool-4-thread-46) [449da20e] Ending command successfully: org.ovirt.engine.core.bll.CreateSnapshotFromTemplateCommand
>2012-09-12 11:06:27,367 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-46) [449da20e] START, GetImageInfoVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = db6c2823-fb8f-42db-9960-fd62a6688c7c, imageGroupId = e037e0e4-138e-4d0c-882d-6e964ac8b32a, imageId = eee098d2-d18c-4e25-b477-48e55f497e14), log id: 38ec8146
>2012-09-12 11:06:27,390 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-46) [449da20e] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@44ff477e, log id: 38ec8146
>2012-09-12 11:06:27,406 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-46) START, SetVmStatusVDSCommand(vmId = 22b22134-d01f-4751-8f92-9e639a783239, status = Down), log id: 37044815
>2012-09-12 11:06:27,410 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-46) FINISH, SetVmStatusVDSCommand, log id: 37044815
>2012-09-12 11:06:27,425 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-46) START, UpdateVMVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, infoDictionary.size = 1), log id: 1128c3e5
>2012-09-12 11:06:27,439 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-46) FINISH, UpdateVMVDSCommand, log id: 1128c3e5
>2012-09-12 11:06:27,452 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-46) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddVm completed, handling the result.
>2012-09-12 11:06:27,452 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-46) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddVm succeeded, clearing tasks.
>2012-09-12 11:06:27,465 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-46) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 962b73d4-d31d-4646-9476-3afd455696be
>2012-09-12 11:06:27,466 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-46) START, SPMClearTaskVDSCommand(storagePoolId = 8242301f-b256-4de3-8a52-eab923c91148, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = 962b73d4-d31d-4646-9476-3afd455696be), log id: 90ed191
>2012-09-12 11:06:27,467 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-46) START, HSMClearTaskVDSCommand(vdsId = 0b94ffda-fc05-11e1-abab-001a4a013f66, taskId=962b73d4-d31d-4646-9476-3afd455696be), log id: 37edb490
>2012-09-12 11:06:27,481 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-46) FINISH, HSMClearTaskVDSCommand, log id: 37edb490
>2012-09-12 11:06:27,481 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-46) FINISH, SPMClearTaskVDSCommand, log id: 90ed191
>2012-09-12 11:06:27,484 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-46) BaseAsyncTask::RemoveTaskFromDB: Removed task 962b73d4-d31d-4646-9476-3afd455696be from DataBase
>2012-09-12 11:06:27,484 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-46) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 22b22134-d01f-4751-8f92-9e639a783239
>2012-09-12 11:06:51,174 ERROR [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-14) [2560d70] USER_FAILED_TO_AUTHENTICATE : portaluser2
>2012-09-12 11:06:51,174 WARN  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-14) [2560d70] CanDoAction of action LoginUser failed. Reasons:USER_FAILED_TO_AUTHENTICATE
>2012-09-12 11:06:55,928 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-16) [2b577e89] Checking if user portaluser2 is an admin, result false
>2012-09-12 11:06:55,928 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-16) [2b577e89] Running command: LoginUserCommand internal: false.
>2012-09-12 11:07:51,145 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-51) Setting new tasks map. The map contains now 0 tasks
>2012-09-12 11:07:51,145 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-51) Cleared all tasks of pool 8242301f-b256-4de3-8a52-eab923c91148.
>2012-09-12 11:07:51,148 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-51) Could not find vds that is spm and non-operational.
>2012-09-12 11:08:44,843 INFO  [org.ovirt.engine.core.bll.LogoutUserCommand] (ajp-/127.0.0.1:8009-16) [55a61801] Running command: LogoutUserCommand internal: false.
>2012-09-12 11:08:49,573 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-7) [675c046c] Checking if user portaluser2 is an admin, result false
>2012-09-12 11:08:49,573 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-7) [675c046c] Running command: LoginUserCommand internal: false.

Actions: View

Attachments on bug 856499: 612038