[ovirt-users] Problem Refreshing/Using ovirt-image-repository / 3.5 RC2
InterNetX - Juergen Gotteswinter
jg at internetx.com
Tue Sep 23 07:41:41 UTC 2014
Am 23.09.2014 um 09:32 schrieb Oved Ourfali:
>
>
> ----- Original Message -----
>> From: "InterNetX - Juergen Gotteswinter" <jg at internetx.com>
>> To: users at ovirt.org
>> Sent: Tuesday, September 23, 2014 10:29:07 AM
>> Subject: [ovirt-users] Problem Refreshing/Using ovirt-image-repository / 3.5 RC2
>>
>> Hi,
>>
>> when trying to refresh the ovirt glance repository i get a 500 Error Message
>>
>>
>> Operation Canceled
>>
>> Error while executing action: A Request to the Server failed with the
>> following Status Code: 500
>>
>>
>> engine.log says:
>>
>> 2014-09-23 09:23:08,960 INFO
>> [org.ovirt.engine.core.bll.provider.TestProviderConnectivityCommand]
>> (ajp--127.0.0.1-8702-10) [7fffb4bd] Running command:
>> TestProviderConnectivityCommand internal: false. Entities affected :
>> ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group
>> CREATE_STORAGE_POOL with role type ADMIN
>> 2014-09-23 09:23:08,975 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (ajp--127.0.0.1-8702-10) [7fffb4bd] Correlation ID: 7fffb4bd, Call
>> Stack: null, Custom Event ID: -1, Message: Unrecognized audit log type
>> has been used.
>> 2014-09-23 09:23:20,173 INFO
>> [org.ovirt.engine.core.bll.aaa.LogoutUserCommand]
>> (ajp--127.0.0.1-8702-11) [712895c3] Running command: LogoutUserCommand
>> internal: false.
>> 2014-09-23 09:23:20,184 INFO
>> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
>> (ajp--127.0.0.1-8702-11) [712895c3] Correlation ID: 712895c3, Call
>> Stack: null, Custom Event ID: -1, Message: User admin logged out.
>> 2014-09-23 09:23:20,262 INFO
>> [org.ovirt.engine.core.bll.aaa.LoginAdminUserCommand]
>> (ajp--127.0.0.1-8702-6) Running command: LoginAdminUserCommand internal:
>> false.
>>
>
> All these message are good... no error here.
> Can you attach the full engine log?
>
imho there is nothing else related to this :/ i attached the log
starting from today. except firing up a test vm nothing else happened
yet (and several tries refreshing the image repo)
>>
>> anyone got an idea what is causing this? Same Network Location, Ovirt
>> 3.4, the Repository works like expected.
>>
>> We also tried to start from scratch, after a engine-cleanup the error
>> still occours.
>>
>> Cheers,
>>
>> Juergen
>> _______________________________________________
>> Users mailing list
>> Users at ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/users
>>
-------------- next part --------------
2014-09-23 08:15:12,374 INFO [org.ovirt.engine.core.bll.aaa.SyncUsers] (DefaultQuartzScheduler_Worker-59) Principal admin::internal synchronized
2014-09-23 08:15:14,122 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] (DefaultQuartzScheduler_Worker-50) Attempting to update VMs/Templates Ovf.
2014-09-23 08:20:12,071 INFO [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-50) [38d67262] Finished automatic refresh process for Unknown file type with success, for storage domain id bc274695-51a9-4623-b305-797a94d42d94.
2014-09-23 09:15:12,389 INFO [org.ovirt.engine.core.bll.aaa.SyncUsers] (DefaultQuartzScheduler_Worker-13) Principal admin::internal synchronized
2014-09-23 09:15:14,151 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] (DefaultQuartzScheduler_Worker-45) [5c6bb1d0] Attempting to update VMs/Templates Ovf.
2014-09-23 09:20:12,088 INFO [org.ovirt.engine.core.bll.IsoDomainListSyncronizer] (org.ovirt.thread.pool-8-thread-38) Finished automatic refresh process for Unknown file type with success, for storage domain id bc274695-51a9-4623-b305-797a94d42d94.
2014-09-23 09:23:08,960 INFO [org.ovirt.engine.core.bll.provider.TestProviderConnectivityCommand] (ajp--127.0.0.1-8702-10) [7fffb4bd] Running command: TestProviderConnectivityCommand internal: false. Entities affected : ID: aaa00000-0000-0000-0000-123456789aaa Type: SystemAction group CREATE_STORAGE_POOL with role type ADMIN
2014-09-23 09:23:08,975 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-10) [7fffb4bd] Correlation ID: 7fffb4bd, Call Stack: null, Custom Event ID: -1, Message: Unrecognized audit log type has been used.
2014-09-23 09:23:20,173 INFO [org.ovirt.engine.core.bll.aaa.LogoutUserCommand] (ajp--127.0.0.1-8702-11) [712895c3] Running command: LogoutUserCommand internal: false.
2014-09-23 09:23:20,184 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-11) [712895c3] Correlation ID: 712895c3, Call Stack: null, Custom Event ID: -1, Message: User admin logged out.
2014-09-23 09:23:20,262 INFO [org.ovirt.engine.core.bll.aaa.LoginAdminUserCommand] (ajp--127.0.0.1-8702-6) Running command: LoginAdminUserCommand internal: false.
2014-09-23 09:23:20,268 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-6) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User admin logged in.
2014-09-23 09:23:20,271 INFO [org.ovirt.engine.core.bll.aaa.LoginAdminUserCommand] (ajp--127.0.0.1-8702-8) Running command: LoginAdminUserCommand internal: false.
2014-09-23 09:23:20,283 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-6) Invalid locale found in configuration:
2014-09-23 09:23:20,286 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-6) Invalid locale found in configuration:
2014-09-23 09:23:22,100 ERROR [org.ovirt.engine.core.utils.servlet.ServletUtils] (ajp--127.0.0.1-8702-2) Can't read file "/usr/share/ovirt-engine/files/spice/SpiceVersion.txt" for request "/ovirt-engine/services/files/spice/SpiceVersion.txt", will send a 404 error response.
2014-09-23 09:23:29,409 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-4) Invalid locale found in configuration:
2014-09-23 09:23:29,411 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-4) Invalid locale found in configuration:
2014-09-23 09:23:33,084 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-2) Invalid locale found in configuration:
2014-09-23 09:23:33,086 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-2) Invalid locale found in configuration:
2014-09-23 09:23:34,723 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-11) Invalid locale found in configuration:
2014-09-23 09:23:34,725 INFO [org.ovirt.engine.core.utils.servlet.UnsupportedLocaleHelper] (ajp--127.0.0.1-8702-11) Invalid locale found in configuration:
2014-09-23 09:23:36,507 ERROR [org.ovirt.engine.core.utils.servlet.ServletUtils] (ajp--127.0.0.1-8702-10) Can't read file "/usr/share/ovirt-engine/files/spice/SpiceVersion.txt" for request "/ovirt-engine/services/files/spice/SpiceVersion.txt", will send a 404 error response.
2014-09-23 09:28:38,922 INFO [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp--127.0.0.1-8702-7) [475b4a88] Lock Acquired to object EngineLock [exclusiveLocks= key: test01 value: VM_NAME
, sharedLocks= ]
2014-09-23 09:28:39,011 INFO [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp--127.0.0.1-8702-7) [475b4a88] Running command: AddVmFromScratchCommand internal: false. Entities affected : ID: 00000001-0001-0001-0001-00000000029b Type: VdsGroupsAction group CREATE_VM with role type USER
2014-09-23 09:28:39,490 INFO [org.ovirt.engine.core.bll.AddWatchdogCommand] (ajp--127.0.0.1-8702-7) [1121618b] Running command: AddWatchdogCommand internal: true. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group EDIT_VM_PROPERTIES with role type USER
2014-09-23 09:28:39,513 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-7) [1121618b] Correlation ID: 1121618b, Call Stack: null, Custom Event ID: -1, Message: Unrecognized audit log type has been used.
2014-09-23 09:28:39,537 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-7) [1121618b] Correlation ID: 475b4a88, Job ID: a60869d6-8adc-4672-8d6d-a5e84682c326, Call Stack: null, Custom Event ID: -1, Message: VM test01 was created by admin.
2014-09-23 09:28:39,548 INFO [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp--127.0.0.1-8702-7) [1121618b] Lock freed to object EngineLock [exclusiveLocks= key: test01 value: VM_NAME
, sharedLocks= ]
2014-09-23 09:28:41,404 INFO [org.ovirt.engine.core.bll.network.vm.AddVmInterfaceCommand] (ajp--127.0.0.1-8702-3) [15b3d5d9] Running command: AddVmInterfaceCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONFIGURE_VM_NETWORK with role type USER, ID: 0000000e-000e-000e-000e-0000000000bd Type: VnicProfileAction group CONFIGURE_VM_NETWORK with role type USER
2014-09-23 09:28:41,558 INFO [org.ovirt.engine.core.bll.network.vm.ActivateDeactivateVmNicCommand] (ajp--127.0.0.1-8702-3) [3bed18da] Running command: ActivateDeactivateVmNicCommand internal: true. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VM
2014-09-23 09:28:41,598 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-3) [3bed18da] Correlation ID: 3bed18da, Call Stack: null, Custom Event ID: -1, Message: Network Interface nic1 (VirtIO) was plugged to VM test01. (User: admin)
2014-09-23 09:28:41,618 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-3) [3bed18da] Correlation ID: 15b3d5d9, Call Stack: null, Custom Event ID: -1, Message: Interface nic1 (VirtIO) was added to VM test01. (User: admin)
2014-09-23 09:28:41,808 INFO [org.ovirt.engine.core.bll.network.vm.ReorderVmNicsCommand] (ajp--127.0.0.1-8702-7) [400da1d0] Running command: ReorderVmNicsCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CREATE_VM with role type USER
2014-09-23 09:28:41,836 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-7) [400da1d0] Correlation ID: 400da1d0, Call Stack: null, Custom Event ID: -1, Message: Unrecognized audit log type has been used.
2014-09-23 09:28:52,555 INFO [org.ovirt.engine.core.bll.AddDiskCommand] (ajp--127.0.0.1-8702-4) [45fada2f] Lock Acquired to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM_DISK_BOOT
, sharedLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
]
2014-09-23 09:28:52,696 INFO [org.ovirt.engine.core.bll.AddDiskCommand] (ajp--127.0.0.1-8702-4) [45fada2f] Running command: AddDiskCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONFIGURE_VM_STORAGE with role type USER, ID: 86cfbeb8-d4a3-43e7-98bf-e2865bb453ea Type: StorageAction group CREATE_DISK with role type USER
2014-09-23 09:28:52,774 INFO [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp--127.0.0.1-8702-4) [58a9adf5] Running command: AddImageFromScratchCommand internal: true. Entities affected : ID: 86cfbeb8-d4a3-43e7-98bf-e2865bb453ea Type: Storage
2014-09-23 09:28:52,795 INFO [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp--127.0.0.1-8702-4) [58a9adf5] Lock freed to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM_DISK_BOOT
, sharedLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
]
2014-09-23 09:28:52,798 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp--127.0.0.1-8702-4) [58a9adf5] START, CreateImageVDSCommand( storagePoolId = 00000002-0002-0002-0002-0000000002f7, ignoreFailoverLimit = false, storageDomainId = 86cfbeb8-d4a3-43e7-98bf-e2865bb453ea, imageGroupId = 2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb, imageSizeInBytes = 64424509440, volumeFormat = COW, newImageId = 4f7df1f6-a9fa-4b75-9013-538d0479ee20, newImageDescription = ), log id: 7bddd824
2014-09-23 09:28:52,807 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp--127.0.0.1-8702-4) [58a9adf5] -- executeIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
2014-09-23 09:28:52,918 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp--127.0.0.1-8702-4) [58a9adf5] FINISH, CreateImageVDSCommand, return: 4f7df1f6-a9fa-4b75-9013-538d0479ee20, log id: 7bddd824
2014-09-23 09:28:52,928 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (ajp--127.0.0.1-8702-4) [58a9adf5] CommandAsyncTask::Adding CommandMultiAsyncTasks object for command 17e3e9d2-e7e9-4c46-b5d7-ea94ca2b3f58
2014-09-23 09:28:52,930 INFO [org.ovirt.engine.core.bll.CommandMultiAsyncTasks] (ajp--127.0.0.1-8702-4) [58a9adf5] CommandMultiAsyncTasks::AttachTask: Attaching task 2d4a8bba-24d3-468a-94e4-17e858ee7476 to command 17e3e9d2-e7e9-4c46-b5d7-ea94ca2b3f58.
2014-09-23 09:28:52,949 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (ajp--127.0.0.1-8702-4) [58a9adf5] Adding task 2d4a8bba-24d3-468a-94e4-17e858ee7476 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
2014-09-23 09:28:53,040 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-4) [58a9adf5] Correlation ID: 45fada2f, Job ID: 1d78a99b-a9cc-41b4-8a08-049c04f3fc88, Call Stack: null, Custom Event ID: -1, Message: Add-Disk operation of test01_Disk1 was initiated on VM test01 by admin.
2014-09-23 09:28:53,044 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (ajp--127.0.0.1-8702-4) [58a9adf5] BaseAsyncTask::startPollingTask: Starting to poll task 2d4a8bba-24d3-468a-94e4-17e858ee7476.
2014-09-23 09:28:56,059 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-21) [9f77588] Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
2014-09-23 09:28:56,070 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-21) [9f77588] SPMAsyncTask::PollTask: Polling task 2d4a8bba-24d3-468a-94e4-17e858ee7476 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
2014-09-23 09:28:56,083 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (DefaultQuartzScheduler_Worker-21) [9f77588] BaseAsyncTask::onTaskEndSuccess: Task 2d4a8bba-24d3-468a-94e4-17e858ee7476 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
2014-09-23 09:28:56,092 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-21) [9f77588] CommandAsyncTask::endActionIfNecessary: All tasks of command 17e3e9d2-e7e9-4c46-b5d7-ea94ca2b3f58 has ended -> executing endAction
2014-09-23 09:28:56,095 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (DefaultQuartzScheduler_Worker-21) [9f77588] CommandAsyncTask::endAction: Ending action for 1 tasks (command ID: 17e3e9d2-e7e9-4c46-b5d7-ea94ca2b3f58): calling endAction .
2014-09-23 09:28:56,099 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-4) [9f77588] CommandAsyncTask::endCommandAction [within thread] context: Attempting to endAction AddDisk, executionIndex: 0
2014-09-23 09:28:56,138 INFO [org.ovirt.engine.core.bll.AddDiskCommand] (org.ovirt.thread.pool-8-thread-4) [45fada2f] Ending command successfully: org.ovirt.engine.core.bll.AddDiskCommand
2014-09-23 09:28:56,170 INFO [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (org.ovirt.thread.pool-8-thread-4) [58a9adf5] Ending command successfully: org.ovirt.engine.core.bll.AddImageFromScratchCommand
2014-09-23 09:28:56,210 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-4) [58a9adf5] START, GetImageInfoVDSCommand( storagePoolId = 00000002-0002-0002-0002-0000000002f7, ignoreFailoverLimit = false, storageDomainId = 86cfbeb8-d4a3-43e7-98bf-e2865bb453ea, imageGroupId = 2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb, imageId = 4f7df1f6-a9fa-4b75-9013-538d0479ee20), log id: 79db30bd
2014-09-23 09:28:56,309 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (org.ovirt.thread.pool-8-thread-4) [58a9adf5] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage at 8ea690c6, log id: 79db30bd
2014-09-23 09:28:56,353 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-4) Correlation ID: 45fada2f, Call Stack: null, Custom Event ID: -1, Message: The disk test01_Disk1 was successfully added to VM test01.
2014-09-23 09:28:56,356 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-4) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddDisk completed, handling the result.
2014-09-23 09:28:56,359 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-4) CommandAsyncTask::HandleEndActionResult [within thread]: endAction for action type AddDisk succeeded, clearing tasks.
2014-09-23 09:28:56,367 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-4) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 2d4a8bba-24d3-468a-94e4-17e858ee7476
2014-09-23 09:28:56,369 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-4) START, SPMClearTaskVDSCommand( storagePoolId = 00000002-0002-0002-0002-0000000002f7, ignoreFailoverLimit = false, taskId = 2d4a8bba-24d3-468a-94e4-17e858ee7476), log id: 112a14de
2014-09-23 09:28:56,442 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-4) START, HSMClearTaskVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, taskId=2d4a8bba-24d3-468a-94e4-17e858ee7476), log id: 61c0039f
2014-09-23 09:28:56,472 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-4) FINISH, HSMClearTaskVDSCommand, log id: 61c0039f
2014-09-23 09:28:56,474 INFO [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (org.ovirt.thread.pool-8-thread-4) FINISH, SPMClearTaskVDSCommand, log id: 112a14de
2014-09-23 09:28:56,484 INFO [org.ovirt.engine.core.bll.tasks.SPMAsyncTask] (org.ovirt.thread.pool-8-thread-4) BaseAsyncTask::removeTaskFromDB: Removed task 2d4a8bba-24d3-468a-94e4-17e858ee7476 from DataBase
2014-09-23 09:28:56,487 INFO [org.ovirt.engine.core.bll.tasks.CommandAsyncTask] (org.ovirt.thread.pool-8-thread-4) CommandAsyncTask::HandleEndActionResult [within thread]: Removing CommandMultiAsyncTasks object for entity 17e3e9d2-e7e9-4c46-b5d7-ea94ca2b3f58
2014-09-23 09:29:00,071 INFO [org.ovirt.engine.core.bll.RunVmCommand] (ajp--127.0.0.1-8702-2) [299e9b45] Lock Acquired to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
, sharedLocks= ]
2014-09-23 09:29:00,217 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-2) [299e9b45] START, IsVmDuringInitiatingVDSCommand( vmId = 1d0146ac-f829-42c6-ac16-4ab094f29f14), log id: 4bf12a67
2014-09-23 09:29:00,220 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-2) [299e9b45] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 4bf12a67
2014-09-23 09:29:00,628 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] Running command: RunVmCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:29:00,979 INFO [org.ovirt.engine.core.bll.scheduling.policyunits.HaReservationWeightPolicyUnit] (org.ovirt.thread.pool-8-thread-33) [299e9b45] Started HA reservation scoring method
2014-09-23 09:29:01,118 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] START, UpdateVmDynamicDataVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmDynamic=org.ovirt.engine.core.common.businessentities.VmDynamic at 1fd8e4a), log id: 49564b93
2014-09-23 09:29:01,124 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] FINISH, UpdateVmDynamicDataVDSCommand, log id: 49564b93
2014-09-23 09:29:01,172 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] START, CreateVmVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, vm=VM [test01]), log id: 2bd0ee8f
2014-09-23 09:29:01,236 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] START, CreateVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, vm=VM [test01]), log id: 200d2dc2
2014-09-23 09:29:01,327 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand kvmEnable=true,keyboardLayout=en-us,nice=0,pitReinjection=false,displayNetwork=ovirtmgmt,copyPasteEnable=true,timeOffset=0,transparentHugePages=true,vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14,acpiEnable=true,custom={device_00000000-0000-0000-0000-000000000000=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=00000000-0000-0000-0000-000000000000, device=watchdog, type=WATCHDOG, bootOrder=0, specParams={model=i6300esb, action=none}, address=, managed=false, plugged=false, readOnly=false, deviceAlias=, customProperties={}, snapshotId=null}},spiceSslCipherSuite=DEFAULT,memSize=8192,smp=2,emulatedMachine=rhel6.5.0,vmType=kvm,memGuaranteedSize=8192,display=qxl,smartcardEnable=false,bootMenuEnable=false,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,smpCoresPerSocket=1,numaTune={mode=preferred},maxVCpus=16,devices=[{specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=fe049c8b-65d9-4295-bc52-c8f03c7ccfe2}, {shared=false, iface=ide, index=2, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=a22ba8ef-b6e9-4eef-9fd1-88dacda3f422}, {shared=false, index=0, volumeID=4f7df1f6-a9fa-4b75-9013-538d0479ee20, propagateErrors=off, format=cow, type=disk, iface=virtio, bootOrder=1, domainID=86cfbeb8-d4a3-43e7-98bf-e2865bb453ea, imageID=2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb, specParams={}, optional=false, device=disk, poolID=00000002-0002-0002-0002-0000000002f7, readonly=false, deviceId=2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb}, {nicModel=pv, specParams={outbound={}, inbound={}}, macAddr=00:1a:4a:5e:43:00, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=ovirtmgmt, deviceId=d4577218-c39c-4161-b3b2-53370c9bf84a}, {specParams={model=virtio}, device=memballoon, type=balloon, deviceId=89e7c823-8553-41c9-bae0-e73bfae90929}, {specParams={model=i6300esb, action=none}, device=watchdog, type=watchdog, deviceId=00000000-0000-0000-0000-000000000000}, {specParams={}, device=virtio-serial, type=controller, deviceId=a84da734-237c-4353-a6c1-e6415a85f746}],vmName=test01,cpuType=Opteron_G4,fileTransferEnable=true
2014-09-23 09:29:01,407 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] FINISH, CreateVDSCommand, log id: 200d2dc2
2014-09-23 09:29:01,418 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 2bd0ee8f
2014-09-23 09:29:01,420 INFO [org.ovirt.engine.core.bll.RunVmCommand] (org.ovirt.thread.pool-8-thread-33) [299e9b45] Lock freed to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
, sharedLocks= ]
2014-09-23 09:29:01,428 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-33) [299e9b45] Correlation ID: 299e9b45, Job ID: 8c9c0562-9f8b-4405-a292-77a8f48cae4e, Call Stack: null, Custom Event ID: -1, Message: VM test01 was started by admin (Host: vm1.intern.xxx.eu).
2014-09-23 09:29:02,978 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-73) VM test01 1d0146ac-f829-42c6-ac16-4ab094f29f14 moved from WaitForLaunch --> PoweringUp
2014-09-23 09:29:02,989 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-73) START, FullListVdsCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vds=Host[vm1.intern.xxx.eu,aa4a6735-6e2e-47b0-9196-b52873152dd7], vmIds=[1d0146ac-f829-42c6-ac16-4ab094f29f14]), log id: 485b3d1f
2014-09-23 09:29:03,006 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-73) FINISH, FullListVdsCommand, return: [{displaySecurePort=5900, kvmEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, displayIp=192.168.210.80, pauseCode=NOERR, pitReinjection=false, nice=0, displayNetwork=ovirtmgmt, copyPasteEnable=true, timeOffset=0, transparentHugePages=true, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, acpiEnable=true, custom={device_00000000-0000-0000-0000-000000000000=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=00000000-0000-0000-0000-000000000000, device=watchdog, type=WATCHDOG, bootOrder=0, specParams={model=i6300esb, action=none}, address=, managed=false, plugged=false, readOnly=false, deviceAlias=, customProperties={}, snapshotId=null}}, spiceSslCipherSuite=DEFAULT, memSize=8192, smp=2, displayPort=-1, emulatedMachine=rhel6.5.0, vmType=kvm, status=Up, memGuaranteedSize=8192, display=qxl, pid=23576, smartcardEnable=false, bootMenuEnable=false, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, numaTune={mode=preferred}, smpCoresPerSocket=1, maxVCpus=16, clientIp=, devices=[Ljava.lang.Object;@5e09e355, vmName=test01, fileTransferEnable=true, cpuType=Opteron_G4}], log id: 485b3d1f
2014-09-23 09:29:03,022 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-73) Received a spice Device without an address when processing VM 1d0146ac-f829-42c6-ac16-4ab094f29f14 devices, skipping device: {specParams={spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, keyMap=en-us, displayNetwork=ovirtmgmt, copyPasteEnable=true, displayIp=192.168.210.80}, device=spice, tlsPort=5900, type=graphics}
2014-09-23 09:29:04,170 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (ajp--127.0.0.1-8702-7) [47778c25] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONNECT_TO_VM with role type USER
2014-09-23 09:29:04,317 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-7) [47778c25] START, SetVmTicketVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, ticket=xWbwtX0JPllB, validTime=120,m userName=admin, userId=fdfc627c-d875-11e0-90f0-83df133b58cc), log id: 5c3c6e43
2014-09-23 09:29:04,344 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-7) [47778c25] FINISH, SetVmTicketVDSCommand, log id: 5c3c6e43
2014-09-23 09:29:04,362 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-7) [47778c25] Correlation ID: 47778c25, Call Stack: null, Custom Event ID: -1, Message: user admin initiated console session for VM test01
2014-09-23 09:29:12,605 ERROR [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-16) [5619ee42] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: The Balloon device on VM test01 on host vm1.intern.xxx.eu is inflated but the device cannot be controlled (guest agent is down).
2014-09-23 09:30:02,621 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-64) [6c1d2199] VM test01 1d0146ac-f829-42c6-ac16-4ab094f29f14 moved from PoweringUp --> Up
2014-09-23 09:30:02,634 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-64) [6c1d2199] Correlation ID: 299e9b45, Job ID: 8c9c0562-9f8b-4405-a292-77a8f48cae4e, Call Stack: null, Custom Event ID: -1, Message: VM test01 started on Host vm1.intern.xxx.eu
2014-09-23 09:30:13,421 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-28) Setting new tasks map. The map contains now 0 tasks
2014-09-23 09:30:13,424 INFO [org.ovirt.engine.core.bll.tasks.AsyncTaskManager] (DefaultQuartzScheduler_Worker-28) Cleared all tasks of pool 00000002-0002-0002-0002-0000000002f7.
2014-09-23 09:32:02,281 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (ajp--127.0.0.1-8702-10) [2dac178b] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONNECT_TO_VM with role type USER
2014-09-23 09:32:02,427 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-10) [2dac178b] START, SetVmTicketVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, ticket=PDSxe9OInHkU, validTime=120,m userName=admin, userId=fdfc627c-d875-11e0-90f0-83df133b58cc), log id: 4bb2f3ea
2014-09-23 09:32:02,457 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-10) [2dac178b] FINISH, SetVmTicketVDSCommand, log id: 4bb2f3ea
2014-09-23 09:32:02,471 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-10) [2dac178b] Correlation ID: 2dac178b, Call Stack: null, Custom Event ID: -1, Message: user admin initiated console session for VM test01
2014-09-23 09:32:48,811 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (ajp--127.0.0.1-8702-8) [443fcb44] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONNECT_TO_VM with role type USER
2014-09-23 09:32:48,956 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-8) [443fcb44] START, SetVmTicketVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, ticket=NWhWqsc3il5g, validTime=120,m userName=admin, userId=fdfc627c-d875-11e0-90f0-83df133b58cc), log id: 1c7ac418
2014-09-23 09:32:48,984 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-8) [443fcb44] FINISH, SetVmTicketVDSCommand, log id: 1c7ac418
2014-09-23 09:32:48,998 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-8) [443fcb44] Correlation ID: 443fcb44, Call Stack: null, Custom Event ID: -1, Message: user admin initiated console session for VM test01
2014-09-23 09:33:21,481 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-92) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User admin is connected to VM test01.
2014-09-23 09:33:35,069 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] Running command: ShutdownVmCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:33:35,145 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] Entered (VM test01).
2014-09-23 09:33:35,147 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] Sending shutdown command for VM test01.
2014-09-23 09:33:35,222 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] START, DestroyVmVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=30, gracefully=true, reason=), log id: 4ea22e70
2014-09-23 09:33:35,304 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] START, DestroyVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=30, gracefully=true, reason=), log id: 4841180a
2014-09-23 09:33:35,320 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] FINISH, DestroyVDSCommand, log id: 4841180a
2014-09-23 09:33:35,335 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-5) [6150432a] FINISH, DestroyVmVDSCommand, return: PoweringDown, log id: 4ea22e70
2014-09-23 09:33:35,353 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-5) [6150432a] Correlation ID: 6150432a, Job ID: 970c7a74-be72-4862-8e6c-b3afcf63bcad, Call Stack: null, Custom Event ID: -1, Message: VM shutdown initiated by admin on VM test01 (Host: vm1.intern.xxx.eu) (Reason: Not Specified).
2014-09-23 09:33:36,986 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-67) START, FullListVdsCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vds=Host[vm1.intern.xxx.eu,aa4a6735-6e2e-47b0-9196-b52873152dd7], vmIds=[1d0146ac-f829-42c6-ac16-4ab094f29f14]), log id: 4dc00f54
2014-09-23 09:33:37,005 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-67) FINISH, FullListVdsCommand, return: [{displaySecurePort=5900, kvmEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, displayIp=192.168.210.80, pauseCode=NOERR, pitReinjection=false, nice=0, displayNetwork=ovirtmgmt, copyPasteEnable=true, timeOffset=0, transparentHugePages=true, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, acpiEnable=true, custom={device_00000000-0000-0000-0000-000000000000=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=00000000-0000-0000-0000-000000000000, device=watchdog, type=WATCHDOG, bootOrder=0, specParams={model=i6300esb, action=none}, address=, managed=false, plugged=false, readOnly=false, deviceAlias=, customProperties={}, snapshotId=null}}, spiceSslCipherSuite=DEFAULT, memSize=8192, smp=2, displayPort=-1, emulatedMachine=rhel6.5.0, vmType=kvm, status=Up, memGuaranteedSize=8192, display=qxl, pid=23576, smartcardEnable=false, bootMenuEnable=false, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, numaTune={mode=preferred}, smpCoresPerSocket=1, maxVCpus=16, clientIp=192.168.100.26, devices=[Ljava.lang.Object;@4fb998e5, vmName=test01, fileTransferEnable=true, cpuType=Opteron_G4}], log id: 4dc00f54
2014-09-23 09:33:37,024 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-67) Received a spice Device without an address when processing VM 1d0146ac-f829-42c6-ac16-4ab094f29f14 devices, skipping device: {specParams={spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, keyMap=en-us, displayNetwork=ovirtmgmt, copyPasteEnable=true, displayIp=192.168.210.80}, device=spice, tlsPort=5900, type=graphics}
2014-09-23 09:33:39,477 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-1) [72694cf9] Running command: ShutdownVmCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:33:39,551 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-1) [72694cf9] Entered (VM test01).
2014-09-23 09:33:39,552 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-1) [72694cf9] Cannot shutdown VM test01, status is not up. Stopping instead.
2014-09-23 09:33:39,581 INFO [org.ovirt.engine.core.bll.StopVmCommand] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] Running command: StopVmCommand internal: true. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:33:39,725 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] START, DestroyVmVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=0, gracefully=false, reason=), log id: 3e242ef3
2014-09-23 09:33:39,810 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] START, DestroyVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=0, gracefully=false, reason=), log id: 1497
2014-09-23 09:33:40,313 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] FINISH, DestroyVDSCommand, log id: 1497
2014-09-23 09:33:40,326 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] FINISH, DestroyVmVDSCommand, return: Down, log id: 3e242ef3
2014-09-23 09:33:40,340 INFO [org.ovirt.engine.core.bll.ProcessDownVmCommand] (org.ovirt.thread.pool-8-thread-28) [59ed17da] Running command: ProcessDownVmCommand internal: true.
2014-09-23 09:33:40,344 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-1) [23b9eec6] Correlation ID: 23b9eec6, Job ID: 31e51cb7-4cb5-4e33-be91-9232ecfffe20, Call Stack: null, Custom Event ID: -1, Message: VM test01 was powered off ungracefully by admin (Host: vm1.intern.xxx.eu) (Reason: Not Specified).
2014-09-23 09:33:49,963 INFO [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-9) [55602631] Lock Acquired to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
, sharedLocks= ]
2014-09-23 09:33:50,026 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] START, IsVmDuringInitiatingVDSCommand( vmId = 1d0146ac-f829-42c6-ac16-4ab094f29f14), log id: 1a64aea7
2014-09-23 09:33:50,030 INFO [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 1a64aea7
2014-09-23 09:33:50,370 INFO [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-9) [55602631] Running command: RunVmOnceCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:33:50,701 INFO [org.ovirt.engine.core.bll.scheduling.policyunits.HaReservationWeightPolicyUnit] (ajp--127.0.0.1-8702-9) [55602631] Started HA reservation scoring method
2014-09-23 09:33:50,851 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] START, UpdateVmDynamicDataVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmDynamic=org.ovirt.engine.core.common.businessentities.VmDynamic at a5d17a13), log id: 7a791a8c
2014-09-23 09:33:50,860 INFO [org.ovirt.engine.core.vdsbroker.UpdateVmDynamicDataVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] FINISH, UpdateVmDynamicDataVDSCommand, log id: 7a791a8c
2014-09-23 09:33:50,951 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] START, CreateVmVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, vm=VM [test01]), log id: b6282da
2014-09-23 09:33:51,038 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] START, CreateVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, vm=VM [test01]), log id: 3d48da08
2014-09-23 09:33:51,118 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand kvmEnable=true,keyboardLayout=en-us,nice=0,pitReinjection=false,displayNetwork=ovirtmgmt,copyPasteEnable=true,timeOffset=0,transparentHugePages=true,vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14,acpiEnable=true,custom={device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2device_233ea473-986b-4ad3-9dc6-ce8c1946946e=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=233ea473-986b-4ad3-9dc6-ce8c1946946e, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=74366c1c-0797-4477-9b16-c407473fbda2, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=00000000-0000-0000-0000-000000000000, device=watchdog, type=WATCHDOG, bootOrder=0, specParams={model=i6300esb, action=none}, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, managed=false, plugged=false, readOnly=false, deviceAlias=watchdog0, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2device_233ea473-986b-4ad3-9dc6-ce8c1946946edevice_05e9645e-c0f1-4766-bccf-dcc1f6c988cc=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=05e9645e-c0f1-4766-bccf-dcc1f6c988cc, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=cf515d98-8b49-4204-a420-6f17e9540088, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}},spiceSslCipherSuite=DEFAULT,memSize=8192,smp=2,emulatedMachine=rhel6.5.0,vmType=kvm,memGuaranteedSize=8192,display=qxl,smartcardEnable=false,bootMenuEnable=false,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard,smpCoresPerSocket=1,numaTune={mode=preferred},maxVCpus=16,devices=[{address={bus=0x00, domain=0x0000, slot=0x02, type=pci, function=0x0}, specParams={vram=32768, heads=1}, device=qxl, type=video, deviceId=fe049c8b-65d9-4295-bc52-c8f03c7ccfe2}, {shared=false, iface=ide, index=2, address={unit=0, bus=1, target=0, controller=0, type=drive}, specParams={path=}, path=, device=cdrom, type=disk, readonly=true, deviceId=a22ba8ef-b6e9-4eef-9fd1-88dacda3f422}, {shared=false, index=0, volumeID=4f7df1f6-a9fa-4b75-9013-538d0479ee20, propagateErrors=off, format=cow, type=disk, iface=virtio, bootOrder=2, address={bus=0x00, domain=0x0000, slot=0x05, type=pci, function=0x0}, domainID=86cfbeb8-d4a3-43e7-98bf-e2865bb453ea, imageID=2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb, specParams={}, optional=false, device=disk, poolID=00000002-0002-0002-0002-0000000002f7, readonly=false, deviceId=2fd4cb92-16e8-41ca-9c6f-f8a0f8822fdb}, {bootOrder=1, nicModel=pv, address={bus=0x00, domain=0x0000, slot=0x03, type=pci, function=0x0}, specParams={outbound={}, inbound={}}, macAddr=00:1a:4a:5e:43:00, device=bridge, linkActive=true, type=interface, filter=vdsm-no-mac-spoofing, network=ovirtmgmt, deviceId=d4577218-c39c-4161-b3b2-53370c9bf84a}, {address={bus=0x00, domain=0x0000, slot=0x06, type=pci, function=0x0}, specParams={model=virtio}, device=memballoon, type=balloon, deviceId=89e7c823-8553-41c9-bae0-e73bfae90929}, {specParams={model=i6300esb, action=none}, device=watchdog, type=watchdog, deviceId=00000000-0000-0000-0000-000000000000}, {address={bus=0x00, domain=0x0000, slot=0x04, type=pci, function=0x0}, specParams={}, device=virtio-serial, type=controller, deviceId=a84da734-237c-4353-a6c1-e6415a85f746}],vmName=test01,cpuType=Opteron_G4,fileTransferEnable=true
2014-09-23 09:33:51,247 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] FINISH, CreateVDSCommand, log id: 3d48da08
2014-09-23 09:33:51,257 INFO [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp--127.0.0.1-8702-9) [55602631] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: b6282da
2014-09-23 09:33:51,259 INFO [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp--127.0.0.1-8702-9) [55602631] Lock freed to object EngineLock [exclusiveLocks= key: 1d0146ac-f829-42c6-ac16-4ab094f29f14 value: VM
, sharedLocks= ]
2014-09-23 09:33:51,270 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-9) [55602631] Correlation ID: 55602631, Job ID: a79f8eb7-5862-4b4e-aae9-e7f325285374, Call Stack: null, Custom Event ID: -1, Message: VM test01 was started by admin (Host: vm1.intern.xxx.eu).
2014-09-23 09:33:52,940 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-27) [28440a7e] START, FullListVdsCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vds=Host[vm1.intern.xxx.eu,aa4a6735-6e2e-47b0-9196-b52873152dd7], vmIds=[1d0146ac-f829-42c6-ac16-4ab094f29f14]), log id: 54041bf8
2014-09-23 09:33:53,009 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (DefaultQuartzScheduler_Worker-27) [28440a7e] FINISH, FullListVdsCommand, return: [{displaySecurePort=5900, kvmEnable=true, nicModel=rtl8139,pv, keyboardLayout=en-us, displayIp=192.168.210.80, pitReinjection=false, nice=0, displayNetwork=ovirtmgmt, copyPasteEnable=true, timeOffset=0, transparentHugePages=true, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, acpiEnable=true, custom={device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2device_233ea473-986b-4ad3-9dc6-ce8c1946946e=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=233ea473-986b-4ad3-9dc6-ce8c1946946e, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=2, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel1, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=74366c1c-0797-4477-9b16-c407473fbda2, device=unix, type=CHANNEL, bootOrder=0, specParams={}, address={port=1, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel0, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=00000000-0000-0000-0000-000000000000, device=watchdog, type=WATCHDOG, bootOrder=0, specParams={model=i6300esb, action=none}, address={bus=0x00, domain=0x0000, type=pci, slot=0x07, function=0x0}, managed=false, plugged=false, readOnly=false, deviceAlias=watchdog0, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088device_74366c1c-0797-4477-9b16-c407473fbda2device_233ea473-986b-4ad3-9dc6-ce8c1946946edevice_05e9645e-c0f1-4766-bccf-dcc1f6c988cc=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=05e9645e-c0f1-4766-bccf-dcc1f6c988cc, device=spicevmc, type=CHANNEL, bootOrder=0, specParams={}, address={port=3, bus=0, controller=0, type=virtio-serial}, managed=false, plugged=true, readOnly=false, deviceAlias=channel2, customProperties={}, snapshotId=null}, device_00000000-0000-0000-0000-000000000000device_cf515d98-8b49-4204-a420-6f17e9540088=VmDevice {vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, deviceId=cf515d98-8b49-4204-a420-6f17e9540088, device=ide, type=CONTROLLER, bootOrder=0, specParams={}, address={bus=0x00, domain=0x0000, type=pci, slot=0x01, function=0x1}, managed=false, plugged=true, readOnly=false, deviceAlias=ide0, customProperties={}, snapshotId=null}}, spiceSslCipherSuite=DEFAULT, memSize=8192, smp=2, displayPort=-1, vmType=kvm, emulatedMachine=rhel6.5.0, status=WaitForLaunch, memGuaranteedSize=8192, display=qxl, pid=0, smartcardEnable=false, bootMenuEnable=false, numaTune={mode=preferred}, smpCoresPerSocket=1, spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, maxVCpus=16, clientIp=, devices=[Ljava.lang.Object;@4d5be11, vmName=test01, fileTransferEnable=true, cpuType=Opteron_G4}], log id: 54041bf8
2014-09-23 09:33:53,045 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-27) [28440a7e] Received a spice Device without an address when processing VM 1d0146ac-f829-42c6-ac16-4ab094f29f14 devices, skipping device: {specParams={spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard, keyMap=en-us, displayNetwork=ovirtmgmt, copyPasteEnable=true, displayIp=192.168.210.80}, device=spice, tlsPort=5900, type=graphics}
2014-09-23 09:33:53,050 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-27) [28440a7e] Received a watchdog Device without an address when processing VM 1d0146ac-f829-42c6-ac16-4ab094f29f14 devices, skipping device: {specParams={model=i6300esb, action=none}, device=watchdog, type=watchdog, deviceId=00000000-0000-0000-0000-000000000000}
2014-09-23 09:33:56,217 INFO [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (DefaultQuartzScheduler_Worker-22) [23fada16] VM test01 1d0146ac-f829-42c6-ac16-4ab094f29f14 moved from WaitForLaunch --> PoweringUp
2014-09-23 09:34:04,628 INFO [org.ovirt.engine.core.bll.SetVmTicketCommand] (ajp--127.0.0.1-8702-7) [6582a5de] Running command: SetVmTicketCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group CONNECT_TO_VM with role type USER
2014-09-23 09:34:04,773 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-7) [6582a5de] START, SetVmTicketVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, ticket=H6oAntnBe2fc, validTime=120,m userName=admin, userId=fdfc627c-d875-11e0-90f0-83df133b58cc), log id: e5f2f09
2014-09-23 09:34:04,806 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.SetVmTicketVDSCommand] (ajp--127.0.0.1-8702-7) [6582a5de] FINISH, SetVmTicketVDSCommand, log id: e5f2f09
2014-09-23 09:34:04,822 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp--127.0.0.1-8702-7) [6582a5de] Correlation ID: 6582a5de, Call Stack: null, Custom Event ID: -1, Message: user admin initiated console session for VM test01
2014-09-23 09:34:12,011 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (DefaultQuartzScheduler_Worker-88) Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: User admin is connected to VM test01.
2014-09-23 09:34:27,903 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-50) [356a8230] Running command: ShutdownVmCommand internal: false. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:34:27,977 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-50) [356a8230] Entered (VM test01).
2014-09-23 09:34:27,979 INFO [org.ovirt.engine.core.bll.ShutdownVmCommand] (org.ovirt.thread.pool-8-thread-50) [356a8230] Cannot shutdown VM test01, status is not up. Stopping instead.
2014-09-23 09:34:28,003 INFO [org.ovirt.engine.core.bll.StopVmCommand] (org.ovirt.thread.pool-8-thread-50) [780b4525] Running command: StopVmCommand internal: true. Entities affected : ID: 1d0146ac-f829-42c6-ac16-4ab094f29f14 Type: VMAction group VM_BASIC_OPERATIONS with role type USER
2014-09-23 09:34:28,148 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-50) [780b4525] START, DestroyVmVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=0, gracefully=false, reason=), log id: 912070
2014-09-23 09:34:28,233 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-50) [780b4525] START, DestroyVDSCommand(HostName = vm1.intern.xxx.eu, HostId = aa4a6735-6e2e-47b0-9196-b52873152dd7, vmId=1d0146ac-f829-42c6-ac16-4ab094f29f14, force=false, secondsToWait=0, gracefully=false, reason=), log id: 2034eeb7
2014-09-23 09:34:28,804 INFO [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (org.ovirt.thread.pool-8-thread-50) [780b4525] FINISH, DestroyVDSCommand, log id: 2034eeb7
2014-09-23 09:34:28,820 INFO [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (org.ovirt.thread.pool-8-thread-50) [780b4525] FINISH, DestroyVmVDSCommand, return: Down, log id: 912070
2014-09-23 09:34:28,830 INFO [org.ovirt.engine.core.bll.ProcessDownVmCommand] (org.ovirt.thread.pool-8-thread-33) [72018e0d] Running command: ProcessDownVmCommand internal: true.
2014-09-23 09:34:28,838 INFO [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-8-thread-50) [780b4525] Correlation ID: 780b4525, Job ID: ba943a10-7381-4269-aad9-7ceed13a41c8, Call Stack: null, Custom Event ID: -1, Message: VM test01 was powered off ungracefully by admin (Host: vm1.intern.xxx.eu) (Reason: Not Specified).
[root at portal ovirt-engine]#
More information about the Users
mailing list