Attachment 616389 Details for Bug 854141 – Engine log

Engine log

engine.log (text/x-log), 193.42 KB, created by Jakub Libosvar on 2012-09-24 07:31:25 UTC

(hide)

Description:

Filename:

MIME Type:

Creator: Jakub Libosvar

Created: 2012-09-24 07:31:25 UTC

Size: 193.42 KB

patch

obsolete

>2012-09-24 08:58:10,284 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) Start time: 9/24/12 8:58 AM
>2012-09-24 08:58:10,454 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: CbcCheckOnVdsChange
>2012-09-24 08:58:10,479 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: CAEngineKey
>2012-09-24 08:58:10,512 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: MinimalETLVersion
>2012-09-24 08:58:10,861 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: ScriptsPath
>2012-09-24 08:58:10,866 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: SQLServerI18NPrefix
>2012-09-24 08:58:10,988 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (MSC service thread 1-1) Failed to decrypt Data must start with zero
>2012-09-24 08:58:10,988 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (MSC service thread 1-1) Failed to decrypt value for property TruststorePass will be used encrypted value
>2012-09-24 08:58:11,004 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-1) Could not find enum value for option: ENGINEEARLib
>2012-09-24 08:58:11,115 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) VDSBrokerFrontend: 9/24/12 8:58 AM
>2012-09-24 08:58:11,130 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) CpuFlagsManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,131 INFO  [org.ovirt.engine.core.bll.AuditLogCleanupManager] (MSC service thread 1-1) Setting audit clean up manager to run at: 35 35 3 * * ?
>2012-09-24 08:58:11,169 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) AuditLogCleanupManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,172 INFO  [org.ovirt.engine.core.bll.TagsDirector] (MSC service thread 1-1) TagsDirector initialization
>2012-09-24 08:58:11,218 INFO  [org.ovirt.engine.core.bll.TagsDirector] (MSC service thread 1-1) Tag root added to tree
>2012-09-24 08:58:11,247 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) TagsDirector: 9/24/12 8:58 AM
>2012-09-24 08:58:11,259 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) IsoDomainListSyncronizer: 9/24/12 8:58 AM
>2012-09-24 08:58:11,288 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) InitHandlers: 9/24/12 8:58 AM
>2012-09-24 08:58:11,320 WARN  [org.ovirt.engine.core.utils.ErrorTranslatorImpl] (MSC service thread 1-1) Code VDS_FENCING_OPERATION_FAILED appears more then once in string table.
>2012-09-24 08:58:11,323 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) ErrorTranslator: 9/24/12 8:58 AM
>2012-09-24 08:58:11,325 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) VdsErrorTranslator: 9/24/12 8:58 AM
>2012-09-24 08:58:11,325 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) Mark uncompleted jobs as UNKNOWN: 9/24/12 8:58 AM
>2012-09-24 08:58:11,371 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) JobRepositoryCleanupManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,378 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) AutoRecoveryManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,383 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-1) ExecutionMessageDirector: 9/24/12 8:58 AM
>2012-09-24 08:58:11,868 INFO  [org.ovirt.engine.core.bll.adbroker.UsersDomainsCacheManagerService] (MSC service thread 1-2) UsersDomainsCacheManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,872 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) InitResourceManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,874 INFO  [org.ovirt.engine.core.vdsbroker.ResourceManager] (MSC service thread 1-3) ResourceManager::ResourceManager::Entered
>2012-09-24 08:58:11,960 INFO  [org.ovirt.engine.core.bll.adbroker.UsersDomainsCacheManagerService] (MSC service thread 1-2) DbUserCacheManager: 9/24/12 8:58 AM
>2012-09-24 08:58:11,996 INFO  [org.ovirt.engine.core.bll.DbUserCacheManager] (QuartzScheduler_Worker-1) DbUserCacheManager::refreshAllUserData() - entered
>2012-09-24 08:58:12,120 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (MSC service thread 1-3) AsyncTaskManager: Initialization of AsyncTaskManager completed successfully.
>2012-09-24 08:58:12,121 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) AsyncTaskManager: 9/24/12 8:58 AM
>2012-09-24 08:58:12,128 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) VdsLoadBalancer: 9/24/12 8:58 AM
>2012-09-24 08:58:12,146 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (pool-4-thread-1) MacPoolManager started: 9/24/12 8:58 AM
>2012-09-24 08:58:12,161 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (pool-4-thread-1) MacPoolManager finished: 9/24/12 8:58 AM
>2012-09-24 08:58:52,402 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) Start time: 9/24/12 8:58 AM
>2012-09-24 08:58:52,458 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: CbcCheckOnVdsChange
>2012-09-24 08:58:52,469 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: CAEngineKey
>2012-09-24 08:58:52,561 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (MSC service thread 1-3) Failed to decrypt Data must start with zero
>2012-09-24 08:58:52,573 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: MinimalETLVersion
>2012-09-24 08:58:52,765 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: ScriptsPath
>2012-09-24 08:58:52,766 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: SQLServerI18NPrefix
>2012-09-24 08:58:52,803 ERROR [org.ovirt.engine.core.engineencryptutils.EncryptionUtils] (MSC service thread 1-3) Failed to decrypt Data must start with zero
>2012-09-24 08:58:52,804 ERROR [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (MSC service thread 1-3) Failed to decrypt value for property TruststorePass will be used encrypted value
>2012-09-24 08:58:52,813 WARN  [org.ovirt.engine.core.utils.ConfigUtilsBase] (MSC service thread 1-3) Could not find enum value for option: ENGINEEARLib
>2012-09-24 08:58:52,878 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) VDSBrokerFrontend: 9/24/12 8:58 AM
>2012-09-24 08:58:52,887 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) CpuFlagsManager: 9/24/12 8:58 AM
>2012-09-24 08:58:52,888 INFO  [org.ovirt.engine.core.bll.AuditLogCleanupManager] (MSC service thread 1-3) Setting audit clean up manager to run at: 35 35 3 * * ?
>2012-09-24 08:58:52,908 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) AuditLogCleanupManager: 9/24/12 8:58 AM
>2012-09-24 08:58:52,914 INFO  [org.ovirt.engine.core.bll.TagsDirector] (MSC service thread 1-3) TagsDirector initialization
>2012-09-24 08:58:52,936 INFO  [org.ovirt.engine.core.bll.TagsDirector] (MSC service thread 1-3) Tag root added to tree
>2012-09-24 08:58:52,954 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) TagsDirector: 9/24/12 8:58 AM
>2012-09-24 08:58:52,964 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) IsoDomainListSyncronizer: 9/24/12 8:58 AM
>2012-09-24 08:58:52,990 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) InitHandlers: 9/24/12 8:58 AM
>2012-09-24 08:58:53,004 WARN  [org.ovirt.engine.core.utils.ErrorTranslatorImpl] (MSC service thread 1-3) Code VDS_FENCING_OPERATION_FAILED appears more then once in string table.
>2012-09-24 08:58:53,006 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) ErrorTranslator: 9/24/12 8:58 AM
>2012-09-24 08:58:53,007 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) VdsErrorTranslator: 9/24/12 8:58 AM
>2012-09-24 08:58:53,008 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) Mark uncompleted jobs as UNKNOWN: 9/24/12 8:58 AM
>2012-09-24 08:58:53,041 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) JobRepositoryCleanupManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,042 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) AutoRecoveryManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,045 INFO  [org.ovirt.engine.core.bll.Backend] (MSC service thread 1-3) ExecutionMessageDirector: 9/24/12 8:58 AM
>2012-09-24 08:58:53,571 INFO  [org.ovirt.engine.core.bll.adbroker.UsersDomainsCacheManagerService] (MSC service thread 1-1) UsersDomainsCacheManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,569 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) InitResourceManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,577 INFO  [org.ovirt.engine.core.vdsbroker.ResourceManager] (MSC service thread 1-3) ResourceManager::ResourceManager::Entered
>2012-09-24 08:58:53,762 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (MSC service thread 1-3) AsyncTaskManager: Initialization of AsyncTaskManager completed successfully.
>2012-09-24 08:58:53,763 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) AsyncTaskManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,764 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (MSC service thread 1-3) VdsLoadBalancer: 9/24/12 8:58 AM
>2012-09-24 08:58:53,769 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (pool-4-thread-1) MacPoolManager started: 9/24/12 8:58 AM
>2012-09-24 08:58:53,848 INFO  [org.ovirt.engine.core.bll.InitBackendServicesOnStartupBean] (pool-4-thread-1) MacPoolManager finished: 9/24/12 8:58 AM
>2012-09-24 08:58:53,906 INFO  [org.ovirt.engine.core.bll.adbroker.UsersDomainsCacheManagerService] (MSC service thread 1-1) DbUserCacheManager: 9/24/12 8:58 AM
>2012-09-24 08:58:53,952 INFO  [org.ovirt.engine.core.bll.DbUserCacheManager] (QuartzScheduler_Worker-1) DbUserCacheManager::refreshAllUserData() - entered
>2012-09-24 08:59:11,112 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-2) Checking if user admin@internal is an admin, result true
>2012-09-24 08:59:11,116 INFO  [org.ovirt.engine.core.bll.LoginUserCommand] (ajp-/127.0.0.1:8009-2) Running command: LoginUserCommand internal: false.
>2012-09-24 08:59:11,199 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: UNASSIGNED not exist in string table
>2012-09-24 08:59:11,200 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: VDS_NETWORK_MTU_DIFFER_FROM_LOGICAL_NETWORK not exist in string table
>2012-09-24 08:59:11,200 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: STORAGE_ACTIVATE_ASYNC not exist in string table
>2012-09-24 08:59:11,201 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: DWH_STOPPED not exist in string table
>2012-09-24 08:59:11,201 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: DWH_STARTED not exist in string table
>2012-09-24 08:59:11,201 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: DWH_ERROR not exist in string table
>2012-09-24 08:59:11,205 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: USER_ATTACH_DISK_TO_VM not have severity. Assumed Normal
>2012-09-24 08:59:11,205 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: USER_FAILED_ATTACH_DISK_TO_VM not have severity. Assumed Normal
>2012-09-24 08:59:11,205 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: USER_DETACH_DISK_FROM_VM not have severity. Assumed Normal
>2012-09-24 08:59:11,205 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: USER_FAILED_DETACH_DISK_FROM_VM not have severity. Assumed Normal
>2012-09-24 08:59:11,205 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: VM_MIGRATION_START_SYSTEM_INITIATED not have severity. Assumed Normal
>2012-09-24 08:59:11,206 WARN  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-2) AuditLogType: VDS_NETWORK_MTU_DIFFER_FROM_LOGICAL_NETWORK not have severity. Assumed Normal
>2012-09-24 08:59:12,602 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-24 08:59:13,439 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-4) calling GetConfigurationValueQuery (SupportedClusterLevels) with null version, using default general for version
>2012-09-24 08:59:13,448 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-4) Didnt find the value of VdsFenceOptionMapping in DB for version 3.1 - using default: alom:secure=secure,port=ipport;apc:secure=secure,port=ipport,slot=port;bladecenter:secure=secure,port=ipport,slot=port;drac5:secure=secure,port=ipport;eps:slot=port;ilo:secure=ssl,port=ipport;ipmilan:;rsa:secure=secure,port=ipport;rsb:;wti:secure=secure,port=ipport,slot=port
>2012-09-24 08:59:13,449 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-4) Didnt find the value of VdsFenceOptionTypes in DB for version 3.1 - using default: secure=bool,port=int,slot=int
>2012-09-24 08:59:13,458 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-4) calling GetConfigurationValueQuery (VdcVersion) with null version, using default general for version
>2012-09-24 08:59:13,462 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-4) Didnt find the value of VdsFenceOptionMapping in DB for version 3.0 - using default: alom:secure=secure,port=ipport;apc:secure=secure,port=ipport,slot=port;bladecenter:secure=secure,port=ipport,slot=port;drac5:secure=secure,port=ipport;eps:slot=port;ilo:secure=ssl,port=ipport;ipmilan:;rsa:secure=secure,port=ipport;rsb:;wti:secure=secure,port=ipport,slot=port
>2012-09-24 08:59:13,462 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-4) Didnt find the value of VdsFenceOptionTypes in DB for version 3.0 - using default: secure=bool,port=int,slot=int
>2012-09-24 08:59:31,574 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-5) calling GetConfigurationValueQuery (SupportedClusterLevels) with null version, using default general for version
>2012-09-24 08:59:34,540 WARN  [org.ovirt.engine.core.bll.GetConfigurationValueQuery] (ajp-/127.0.0.1:8009-1) calling GetConfigurationValueQuery (SupportedClusterLevels) with null version, using default general for version
>2012-09-24 08:59:36,457 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Adding new value to configuration cache.
>2012-09-24 08:59:36,457 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Didnt find the value of DBPagingType in DB for version general - using default: Offset
>2012-09-24 08:59:36,459 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Adding new value to configuration cache.
>2012-09-24 08:59:36,459 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Didnt find the value of DBPagingSyntax in DB for version general - using default: OFFSET (%1$s -1) LIMIT %2$s
>2012-09-24 08:59:36,459 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Adding new value to configuration cache.
>2012-09-24 08:59:36,459 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Didnt find the value of DBSearchTemplate in DB for version general - using default: SELECT * FROM (%2$s) %1$s) as T1 %3$s
>2012-09-24 08:59:37,251 INFO  [org.ovirt.engine.core.bll.storage.AddEmptyStoragePoolCommand] (ajp-/127.0.0.1:8009-7) [5ce07cc8] Running command: AddEmptyStoragePoolCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
>2012-09-24 08:59:38,418 INFO  [org.ovirt.engine.core.bll.AddVdsGroupCommand] (ajp-/127.0.0.1:8009-6) [7ba02eb5] Running command: AddVdsGroupCommand internal: false. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 08:59:40,913 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-2) [6c2b0b9] Adding new value to configuration cache.
>2012-09-24 08:59:40,914 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-2) [6c2b0b9] Didnt find the value of BootstrapNodeIDCommand in DB for version general - using default: dmidecode | awk ' /UUID/{ print $2; } ' | tr '
>' '_' && cat /sys/class/net/*/address | sed -e '/00:00:00:00/d' -e '/^$/d' | sort -u | head -n 1
>2012-09-24 08:59:40,914 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (ajp-/127.0.0.1:8009-2) SSH execute 10.35.160.133 'dmidecode | awk ' /UUID/{ print $2; } ' | tr '
>' '_' && cat /sys/class/net/*/address | sed -e '/00:00:00:00/d' -e '/^$/d' | sort -u | head -n 1'
>2012-09-24 08:59:41,156 INFO  [org.ovirt.engine.core.bll.AddVdsCommand] (ajp-/127.0.0.1:8009-2) [6c2b0b9] Running command: AddVdsCommand internal: false. Entities affected :  ID: 680cba18-0615-11e2-bbbc-001a4a169754 Type: VdsGroups
>2012-09-24 08:59:41,283 INFO  [org.ovirt.engine.core.bll.AddVdsSpmIdCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] Running command: AddVdsSpmIdCommand internal: true. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 08:59:41,321 INFO  [org.ovirt.engine.core.bll.AddVdsSpmIdCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] Lock freed to object EngineLock [exclusiveLocks= key: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a value: REGISTER_VDS
>, sharedLocks= ]
>2012-09-24 08:59:41,327 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8009-2) [3eba917c] Cannot get vdsManager for vdsid=69add5fa-0615-11e2-b3af-001a4a169754
>2012-09-24 08:59:41,327 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] START, RemoveVdsVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754), log id: 966579c
>2012-09-24 08:59:41,328 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8009-2) [3eba917c] Cannot get vdsManager for vdsid=69add5fa-0615-11e2-b3af-001a4a169754
>2012-09-24 08:59:41,328 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] FINISH, RemoveVdsVDSCommand, log id: 966579c
>2012-09-24 08:59:41,329 ERROR [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8009-2) [3eba917c] Cannot get vdsManager for vdsid=69add5fa-0615-11e2-b3af-001a4a169754
>2012-09-24 08:59:41,329 INFO  [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] START, AddVdsVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754), log id: 3db91395
>2012-09-24 08:59:41,330 INFO  [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] AddVds - entered , starting logic to add VDS 69add5fa-0615-11e2-b3af-001a4a169754
>2012-09-24 08:59:41,335 INFO  [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] AddVds - VDS 69add5fa-0615-11e2-b3af-001a4a169754 was added, will try to add it to the resource manager
>2012-09-24 08:59:41,343 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp-/127.0.0.1:8009-2) [3eba917c] Eneterd VdsManager:constructor
>2012-09-24 08:59:41,344 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp-/127.0.0.1:8009-2) [3eba917c] vdsBroker(10.35.160.133,54,321)
>2012-09-24 08:59:41,409 INFO  [org.ovirt.engine.core.vdsbroker.ResourceManager] (ajp-/127.0.0.1:8009-2) [3eba917c] ResourceManager::AddVds - VDS 69add5fa-0615-11e2-b3af-001a4a169754 was added to the Resource Manager
>2012-09-24 08:59:41,409 INFO  [org.ovirt.engine.core.vdsbroker.AddVdsVDSCommand] (ajp-/127.0.0.1:8009-2) [3eba917c] FINISH, AddVdsVDSCommand, log id: 3db91395
>2012-09-24 08:59:41,595 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Adding new value to configuration cache.
>2012-09-24 08:59:41,596 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-6) Didnt find the value of DBI18NPrefix in DB for version general - using default: 
>2012-09-24 08:59:42,898 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-4-thread-3) [8a07b6c] Running command: InstallVdsCommand internal: true. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 08:59:42,905 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Adding new value to configuration cache.
>2012-09-24 08:59:42,906 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Didnt find the value of BootstrapCommand in DB for version general - using default: umask 0077; MYTMP="$(mktemp -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; rm -fr "${MYTMP}" && mkdir "${MYTMP}" && tar -C "${MYTMP}" --no-same-permissions -o -x && "${MYTMP}"/setup -c 'ssl={server_SSL_enabled};management_port={management_port}' -O '{OrganizationName}' -t {utc_time} {OverrideFirewall} -S {SSHKey} {EnginePort} -b {virt-placeholder} {gluster-placeholder} {URL1} {URL1} {vds-server} {GUID} {RunFlag}
>2012-09-24 08:59:42,907 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Adding new value to configuration cache.
>2012-09-24 08:59:42,908 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Didnt find the value of BootstrapPackageName in DB for version general - using default: vdsm-bootstrap-2.tar
>2012-09-24 08:59:42,908 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Adding new value to configuration cache.
>2012-09-24 08:59:42,908 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Didnt find the value of BootstrapPackageDirectory in DB for version general - using default: /usr/share/vdsm-bootstrap/interface-2
>2012-09-24 08:59:42,908 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Adding new value to configuration cache.
>2012-09-24 08:59:42,908 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Didnt find the value of BootstrapCacheRefreshInterval in DB for version general - using default: 10,000
>2012-09-24 08:59:42,915 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-4-thread-3) [8a07b6c] Before Installation pool-4-thread-3
>2012-09-24 08:59:42,915 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Starting Host installation)
>2012-09-24 08:59:42,915 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Connecting to Host)
>2012-09-24 08:59:42,990 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Received message: <BSTRAP component='RHEV_INSTALL' status='OK' message='Connected to Host 10.35.160.133 with SSH key fingerprint: 65:3c:5c:c9:8f:74:ea:c9:d6:5d:c9:b6:18:d2:b6:00'/>. FYI. (Stage: Connecting to Host)
>2012-09-24 08:59:43,025 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Successfully connected to server ssh. (Stage: Connecting to Host)
>2012-09-24 08:59:43,025 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Get the unique vds id)
>2012-09-24 08:59:43,025 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (pool-4-thread-3) SSH execute 10.35.160.133 'dmidecode | awk ' /UUID/{ print $2; } ' | tr '
>' '_' && cat /sys/class/net/*/address | sed -e '/00:00:00:00/d' -e '/^$/d' | sort -u | head -n 1'
>2012-09-24 08:59:43,139 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: 4C4C4544-004A-4410-804C-B5C04F39354A_00:8c:fa:02:91:0a. FYI. (Stage: Get the unique vds id)
>2012-09-24 08:59:43,150 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Assigning unique id 4C4C4544-004A-4410-804C-B5C04F39354A_00:8c:fa:02:91:0a to Host. (Stage: Get the unique vds id)
>2012-09-24 08:59:43,166 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Upload Installation script to Host)
>2012-09-24 08:59:43,168 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Adding new value to configuration cache.
>2012-09-24 08:59:43,168 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (pool-4-thread-3) [8a07b6c] Didnt find the value of SSHKeyAlias in DB for version general - using default: ovirt-engine
>2012-09-24 08:59:43,168 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (pool-4-thread-3) SSH execute 10.35.160.133 'cat > '/tmp/ovirt-id_rsa_c846874e-0e21-4675-9e7b-b09e8baddd0d''
>2012-09-24 08:59:43,254 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Running first installation script on Host)
>2012-09-24 08:59:43,254 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Sending SSH Command umask 0077; MYTMP="$(mktemp -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; rm -fr "${MYTMP}" && mkdir "${MYTMP}" && tar -C "${MYTMP}" --no-same-permissions -o -x && "${MYTMP}"/setup -c 'ssl=true;management_port=54321' -O 'Red Hat' -t 2012-09-24T06:59:43  -S /tmp/ovirt-id_rsa_c846874e-0e21-4675-9e7b-b09e8baddd0d -p 80 -b   http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ 10.35.160.133 c846874e-0e21-4675-9e7b-b09e8baddd0d False < /var/cache/ovirt-engine/vdsm-bootstrap-2.tar. (Stage: Running first installation script on Host)
>2012-09-24 08:59:43,256 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (pool-4-thread-3) SSH execute 10.35.160.133 'umask 0077; MYTMP="$(mktemp -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; rm -fr "${MYTMP}" && mkdir "${MYTMP}" && tar -C "${MYTMP}" --no-same-permissions -o -x && "${MYTMP}"/setup -c 'ssl=true;management_port=54321' -O 'Red Hat' -t 2012-09-24T06:59:43  -S /tmp/ovirt-id_rsa_c846874e-0e21-4675-9e7b-b09e8baddd0d -p 80 -b   http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ 10.35.160.133 c846874e-0e21-4675-9e7b-b09e8baddd0d False'
>2012-09-24 08:59:43,376 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='INSTALLER' status='OK' message='Test platform succeeded'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:43,413 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (QuartzScheduler_Worker-11) Initializing Host: 10.35.160.133
>2012-09-24 08:59:44,612 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='SET_SYSTEM_TIME' status='OK' message='setSystemTime ended successfully'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:50,631 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='RHN_REGISTRATION' status='OK' message='Host properly registered with RHN/Satellite.'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:50,811 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDSM_MAJOR_VER' status='OK' message='Available VDSM matches requirements'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:50,837 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VT_SVM' status='OK' processor='AMD' message='Server supports virtualization'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:50,949 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='OS' status='OK' type='RHEL6' message='Supported platform version'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:50,995 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='KERNEL' status='OK' version='279' message='Supported kernel version: 279'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,021 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='SDL.x86_64' message='SDL-1.2.14-3.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,081 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='bridge-utils.x86_64' message='bridge-utils-1.2-9.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,100 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='mesa-libGLU.x86_64' message='mesa-libGLU-7.11-5.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,207 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='openssl.x86_64' message='openssl-1.0.0-25.el6_3.1.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,236 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='m2crypto.x86_64' message='m2crypto-0.20.2-9.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,288 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='REQ PACKAGES' status='OK' result='rsync.x86_64' message='rsync-3.0.6-9.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,522 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='WARN' result='qemu-kvm' message='package qemu-kvm is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,573 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='WARN' result='qemu-kvm-tools' message='package qemu-kvm-tools is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,580 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='vdsm' message='vdsm-4.9.6-34.0.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,616 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='vdsm-cli' message='vdsm-cli-4.9.6-34.0.el6_3.noarch '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,637 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='libjpeg' message='libjpeg-6b-46.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,790 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='spice-server' message='spice-server-0.10.1-10.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,819 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='pixman' message='pixman-0.18.4-1.el6_0.1.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,862 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='seabios' message='seabios-0.6.1.2-19.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,891 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='WARN' result='qemu-img' message='package qemu-img is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,897 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='fence-agents' message='fence-agents-3.1.5-17.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,921 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='libselinux-python' message='libselinux-python-2.0.94-5.3.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,947 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='sanlock' message='sanlock-2.3-3.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 08:59:51,971 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='sanlock-python' message='sanlock-python-2.3-3.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:00:00,002 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-26) Autorecovering hosts is disabled, skipping
>2012-09-24 09:00:00,003 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-26) Autorecovering storage domains is disabled, skipping
>2012-09-24 09:01:00,773 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='vdsm' message='vdsm-4.9.6-34.0.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:03,215 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='vdsm-cli' message='vdsm-cli-4.9.6-34.0.el6_3.noarch '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:05,576 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='libjpeg' message='libjpeg-6b-46.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:08,058 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='spice-server' message='spice-server-0.10.1-10.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:10,895 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='pixman' message='pixman-0.18.4-1.el6_0.1.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:14,225 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='seabios' message='seabios-0.6.1.2-19.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:17,746 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='fence-agents' message='fence-agents-3.1.5-17.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:20,979 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='libselinux-python' message='libselinux-python-2.0.94-5.3.el6.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:23,948 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='sanlock' message='sanlock-2.3-3.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:27,163 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='sanlock-python' message='sanlock-python-2.3-3.el6_3.x86_64 '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:31,663 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='qemu-img' message='package qemu-img is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:34,133 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='qemu-kvm-tools' message='package qemu-kvm-tools is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:36,561 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS PACKAGES' status='OK' result='qemu-kvm' message='package qemu-kvm is not installed '/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:36,910 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='CreateConf' status='OK' message='Basic configuration found, skipping this step'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:36,994 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='CheckLocalHostname' status='OK' message='Local hostname is correct.'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:37,022 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='SetNetworking' status='OK' message='Bridge management already exists. Skipping bridge creation.'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:37,558 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='SetSSHAccess' status='OK' message='SUCCESS'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:37,591 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VerifyServices' status='OK' message='Needed services set'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:48,328 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='Encryption setup' status='OK' message='Ended successfully'/>. FYI. (Stage: Running first installation script on Host)
>2012-09-24 09:01:48,351 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='RHEV_INSTALL' status='OK'/>. Stage completed. (Stage: Running first installation script on Host)
>2012-09-24 09:01:48,397 ERROR [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Error: Repository epel is listed more than once in the configuration
>Repository jboss is listed more than once in the configuration
>Repository rhel-source is listed more than once in the configuration
>Repository rhel-source-beta is listed more than once in the configuration
>Repository rhevm is listed more than once in the configuration
>Repository rhevm_old is listed more than once in the configuration
>Repository epel is listed more than once in the configuration
>Repository jboss is listed more than once in the configuration
>Repository rhel-source is listed more than once in the configuration
>Repository rhel-source-beta is listed more than once in the configuration
>Repository rhevm is listed more than once in the configuration
>Repository rhevm_old is listed more than once in the configuration
>. (Stage: Downloading certificate request from Host)
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository epel is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository jboss is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhel-source is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhel-source-beta is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhevm is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhevm_old is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository epel is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository jboss is listed more than once in the configuration
>2012-09-24 09:01:48,398 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhel-source is listed more than once in the configuration
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhel-source-beta is listed more than once in the configuration
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhevm is listed more than once in the configuration
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.bll.InstallerMessages] (pool-4-thread-3) [8a07b6c] VDS message: Repository rhevm_old is listed more than once in the configuration
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Script ended, result is {1}
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Downloading certificate request from Host)
>2012-09-24 09:01:48,399 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (pool-4-thread-3) SSH receive 10.35.160.133:'/tmp/cert_c846874e-0e21-4675-9e7b-b09e8baddd0d.req' '/etc/pki/ovirt-engine/requests/cert_c846874e-0e21-4675-9e7b-b09e8baddd0d.req')
>2012-09-24 09:01:48,482 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. successfully done sftp operation ( Stage: Downloading certificate request from Host)
>2012-09-24 09:01:48,482 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c]  DownloadCertificateRequest ended:true
>2012-09-24 09:01:48,482 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Sign certificate request and generate certificate)
>2012-09-24 09:01:49,498 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c]  SignCertificateRequest ended:true
>2012-09-24 09:01:49,498 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Upload signed sertificate to Host)
>2012-09-24 09:01:49,529 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. successfully done sftp operation ( Stage: Upload signed sertificate to Host)
>2012-09-24 09:01:49,529 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c]  UploadSignedCertificate ended:true
>2012-09-24 09:01:49,529 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Upload Cerficate Autority to Host)
>2012-09-24 09:01:49,585 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. successfully done sftp operation ( Stage: Upload Cerficate Autority to Host)
>2012-09-24 09:01:49,585 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Executing installation stage. (Stage: Running second installation script on Host)
>2012-09-24 09:01:49,585 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Installation of 10.35.160.133. Sending SSH Command umask 0077; MYTMP="$(mktemp -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; rm -fr "${MYTMP}" && mkdir "${MYTMP}" && tar -C "${MYTMP}" --no-same-permissions -o -x && "${MYTMP}"/setup -c 'ssl=true;management_port=54321' -O 'Red Hat' -t 2012-09-24T06:59:43  -S /tmp/ovirt-id_rsa_c846874e-0e21-4675-9e7b-b09e8baddd0d -p 80 -b   http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ 10.35.160.133 c846874e-0e21-4675-9e7b-b09e8baddd0d True < /var/cache/ovirt-engine/vdsm-bootstrap-2.tar. (Stage: Running second installation script on Host)
>2012-09-24 09:01:49,586 INFO  [org.ovirt.engine.core.utils.hostinstall.VdsInstallerSSH] (pool-4-thread-3) SSH execute 10.35.160.133 'umask 0077; MYTMP="$(mktemp -t ovirt-XXXXXXXXXX)"; trap "chmod -R u+rwX \"${MYTMP}\" > /dev/null 2>&1; rm -fr \"${MYTMP}\" > /dev/null 2>&1" 0; rm -fr "${MYTMP}" && mkdir "${MYTMP}" && tar -C "${MYTMP}" --no-same-permissions -o -x && "${MYTMP}"/setup -c 'ssl=true;management_port=54321' -O 'Red Hat' -t 2012-09-24T06:59:43  -S /tmp/ovirt-id_rsa_c846874e-0e21-4675-9e7b-b09e8baddd0d -p 80 -b   http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ http://jenkins-vm-02.qa.lab.tlv.redhat.com:80/Components/vds/ 10.35.160.133 c846874e-0e21-4675-9e7b-b09e8baddd0d True'
>2012-09-24 09:01:49,685 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='INSTALLER' status='OK' message='Test platform succeeded'/>. FYI. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,889 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='instCert' status='OK'/>. FYI. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,928 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='CoreDump' status='OK'/>. FYI. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,940 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='cleanAll' status='OK'/>. FYI. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,959 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='VDS Configuration' status='OK'/>. FYI. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,976 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='RHEV_INSTALL' status='OK'/>. Stage completed. (Stage: Running second installation script on Host)
>2012-09-24 09:02:34,992 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (NioProcessor-6) Installation of 10.35.160.133. Received message: <BSTRAP component='Reboot' status='OK' message='Rebooting machine' />. FYI. (Stage: Host installation complete)
>2012-09-24 09:02:35,013 INFO  [org.ovirt.engine.core.bll.VdsInstaller] (pool-4-thread-3) [8a07b6c] Script ended, result is {1}
>2012-09-24 09:02:35,013 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-4-thread-3) [8a07b6c] After Installation pool-4-thread-3
>2012-09-24 09:02:35,018 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-4-thread-3) [8a07b6c] START, SetVdsStatusVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, status=Reboot, nonOperationalReason=NONE), log id: 3edd14b8
>2012-09-24 09:02:35,116 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-4-thread-3) [8a07b6c] FINISH, SetVdsStatusVDSCommand, log id: 3edd14b8
>2012-09-24 09:02:35,122 INFO  [org.ovirt.engine.core.bll.InstallVdsCommand] (pool-4-thread-4) [8a07b6c] Waiting 150 seconds, for server to finish reboot process.
>2012-09-24 09:05:00,002 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-53) Autorecovering hosts is disabled, skipping
>2012-09-24 09:05:00,002 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-53) Autorecovering storage domains is disabled, skipping
>2012-09-24 09:05:05,124 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-4-thread-4) [8a07b6c] START, SetVdsStatusVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, status=NonResponsive, nonOperationalReason=NONE), log id: 5ea2ad27
>2012-09-24 09:05:05,417 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (pool-4-thread-4) [8a07b6c] FINISH, SetVdsStatusVDSCommand, log id: 5ea2ad27
>2012-09-24 09:06:12,028 INFO  [org.ovirt.engine.core.bll.InitVdsOnUpCommand] (QuartzScheduler_Worker-59) [b32aa12] Running command: InitVdsOnUpCommand internal: true.
>2012-09-24 09:06:12,046 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (QuartzScheduler_Worker-59) [b32aa12] No string for UNASSIGNED type. Use default Log
>2012-09-24 09:06:12,064 INFO  [org.ovirt.engine.core.bll.MultipleActionsRunner] (pool-4-thread-8) [b32aa12] MultipleActionsRunner of type MigrateVmToServer invoked with no actions
>2012-09-24 09:06:12,097 INFO  [org.ovirt.engine.core.bll.HandleVdsCpuFlagsOrClusterChangedCommand] (QuartzScheduler_Worker-59) [38c85a2a] Running command: HandleVdsCpuFlagsOrClusterChangedCommand internal: true. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 09:06:12,125 INFO  [org.ovirt.engine.core.bll.HandleVdsVersionCommand] (QuartzScheduler_Worker-59) [4e16fa07] Running command: HandleVdsVersionCommand internal: true. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 09:06:13,613 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp-/127.0.0.1:8009-2) START, DiscoverSendTargetsVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, connection={ id: null, connection: 10.35.64.102, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };), log id: 274ec4b
>2012-09-24 09:06:13,827 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DiscoverSendTargetsVDSCommand] (ajp-/127.0.0.1:8009-2) FINISH, DiscoverSendTargetsVDSCommand, return: [{ id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:10.35.113.8532714274026317, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:ad-setup21111859938468, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:aqua-rhel19229335845050, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:aqua-rhel52285459312696, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:aqua52085333829701, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:awinter201208051834921035, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:base-iscsi-virtio122154754301875, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:base-iscsi112218558728900, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:baseiscsi, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:blue525123712267378, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:bronze2627141554409479, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:corruption1226233225801029, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:dafna72164841209562, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:dhcp-3-152329172158349426, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:emerald127182228639302, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:fire-vdc20120905125520607800, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:gadi-rhevm20120828161112942139, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:gena-upstream611173110751397, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:gena-zeus61411236914936, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:ilia-setup52917158929470, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:indigo62234946167288, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-automation-rhel63-vm0151514132309211, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-012012082718458641615, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-032012082712611320517, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0420120910132238500081, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0520120920155832461948, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-062012082616046628253, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-072012091683411791846, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-1220120828102822978617, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-1320120828172411462377, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-142012082994856242654, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-1520120918142641953575, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-1620120828115337561581, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-1720120829115053484177, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:lb-setup130202743148044, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:lilach-rhel565171887881502, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:main-test3710460948229, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:main-test4211348817624, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:master-rhevm-3724145624690635, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:meni-testvm529153835483141, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:meni-zstream624133525414291, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:monique20120909114238174492, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:navy11810111985529, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:none20120911123522634472, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:omri-setup125145356358151, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:rest-rhel671393516902326, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:rest261493858698976, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:stam122516743297678, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:stsanity-525135633331170, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:stsanity525114829711696, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:violet-rhel12345, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:violet-rhel529102028517878, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:violet-test327124348409838, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:violet517173122508881, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:wheat20120715122514601100, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:zeus12161223672205, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.1994-05.com.redhat:meni-jumbo-target1, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.2011-05.com.redhat:meni-iscsi, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.2011-05.com.redhat:meni-jf-31-iscsi, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.2011-05.com.redhat:meni-rhevm31-iscsi, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };, { id: null, connection: 10.35.64.102, iqn: iqn.2011-09.com.redhat:lesik1, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };], log id: 274ec4b
>2012-09-24 09:06:14,009 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-4) [230356f1] START, ValidateStorageServerConnectionVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 78b1fbba
>2012-09-24 09:06:14,047 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-4) [230356f1] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 78b1fbba
>2012-09-24 09:06:14,076 INFO  [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (ajp-/127.0.0.1:8009-4) [230356f1] Running command: ConnectStorageToVdsCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
>2012-09-24 09:06:14,079 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-4) [230356f1] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 7ec706f4
>2012-09-24 09:06:14,970 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-4) [230356f1] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 7ec706f4
>2012-09-24 09:06:15,943 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-2) [3c6f3a9e] START, ValidateStorageServerConnectionVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 6cddc80f
>2012-09-24 09:06:15,970 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ValidateStorageServerConnectionVDSCommand] (ajp-/127.0.0.1:8009-2) [3c6f3a9e] FINISH, ValidateStorageServerConnectionVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: 6cddc80f
>2012-09-24 09:06:16,010 INFO  [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (ajp-/127.0.0.1:8009-2) [3c6f3a9e] Running command: ConnectStorageToVdsCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
>2012-09-24 09:06:16,014 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-2) [3c6f3a9e] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: null, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: c57b2be
>2012-09-24 09:06:16,103 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-2) [3c6f3a9e] FINISH, ConnectStorageServerVDSCommand, return: {00000000-0000-0000-0000-000000000000=0}, log id: c57b2be
>2012-09-24 09:06:16,127 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8009-2) START, GetDeviceListVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storageType=ISCSI), log id: 35b6352b
>2012-09-24 09:06:17,996 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetDeviceListVDSCommand] (ajp-/127.0.0.1:8009-2) FINISH, GetDeviceListVDSCommand, return: [org.ovirt.engine.core.common.businessentities.LUNs@db380d75, org.ovirt.engine.core.common.businessentities.LUNs@4488b651, org.ovirt.engine.core.common.businessentities.LUNs@cd45e49, org.ovirt.engine.core.common.businessentities.LUNs@527178ba, org.ovirt.engine.core.common.businessentities.LUNs@5f1fc9bc, org.ovirt.engine.core.common.businessentities.LUNs@7070f1ea], log id: 35b6352b
>2012-09-24 09:06:18,180 INFO  [org.ovirt.engine.core.bll.storage.AddSANStorageDomainCommand] (ajp-/127.0.0.1:8009-2) [664dc809] Running command: AddSANStorageDomainCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
>2012-09-24 09:06:18,267 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] START, CreateVGVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storageDomainId=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, deviceList=[3600144f0bdc38d000000506004c40016], force=false), log id: 443a547d
>2012-09-24 09:06:19,981 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVGVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] FINISH, CreateVGVDSCommand, return: tahh9R-s7qH-oKLj-Wx3Z-qvit-qoe7-DNT0Fy, log id: 443a547d
>2012-09-24 09:06:19,985 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] START, CreateStorageDomainVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storageDomain=org.ovirt.engine.core.common.businessentities.storage_domain_static@ffe5b5f6, args=tahh9R-s7qH-oKLj-Wx3Z-qvit-qoe7-DNT0Fy), log id: 7eb719e6
>2012-09-24 09:06:29,235 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] FINISH, CreateStorageDomainVDSCommand, log id: 7eb719e6
>2012-09-24 09:06:29,243 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetStorageDomainStatsVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] START, GetStorageDomainStatsVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storageDomainId=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842), log id: 6ef82514
>2012-09-24 09:06:29,618 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetStorageDomainStatsVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] FINISH, GetStorageDomainStatsVDSCommand, return: org.ovirt.engine.core.common.businessentities.storage_domains@1634e739, log id: 6ef82514
>2012-09-24 09:06:29,660 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVGInfoVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] START, GetVGInfoVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, VGID=tahh9R-s7qH-oKLj-Wx3Z-qvit-qoe7-DNT0Fy), log id: 171fdeff
>2012-09-24 09:06:29,717 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.GetVGInfoVDSCommand] (ajp-/127.0.0.1:8009-2) [664dc809] FINISH, GetVGInfoVDSCommand, return: [org.ovirt.engine.core.common.businessentities.LUNs@d845d295], log id: 171fdeff
>2012-09-24 09:06:32,882 INFO  [org.ovirt.engine.core.bll.storage.AttachStorageDomainToPoolCommand] (ajp-/127.0.0.1:8009-7) [9620807] Running command: AttachStorageDomainToPoolCommand internal: false. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:06:32,897 INFO  [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] Lock Acquired to object EngineLock [exclusiveLocks= key: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a value: POOL
>, sharedLocks= ]
>2012-09-24 09:06:32,913 INFO  [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] Running command: AddStoragePoolWithStoragesCommand internal: true. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 09:06:33,151 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 7c41cd45
>2012-09-24 09:06:33,230 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] FINISH, ConnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 7c41cd45
>2012-09-24 09:06:33,235 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] START, CreateStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId=344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType=ISCSI, storagePoolName=iscsiStorageTest, masterDomainId=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, domainsIdList=[0b3bfe3a-1bf1-456c-bdfe-e545c72e5842], masterVersion=1), log id: 6e073b12
>2012-09-24 09:07:03,568 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] FINISH, CreateStoragePoolVDSCommand, log id: 6e073b12
>2012-09-24 09:07:03,589 INFO  [org.ovirt.engine.core.bll.storage.AddStoragePoolWithStoragesCommand] (ajp-/127.0.0.1:8009-7) [7a8b93cc] Lock freed to object EngineLock [exclusiveLocks= key: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a value: POOL
>, sharedLocks= ]
>2012-09-24 09:07:03,592 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [44658d55] Lock Acquired to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>, sharedLocks= ]
>2012-09-24 09:07:03,618 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [44658d55] Running command: ActivateStorageDomainCommand internal: true. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:07:03,656 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [44658d55] Lock freed to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>, sharedLocks= ]
>2012-09-24 09:07:03,657 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [44658d55] ActivateStorage Domain. Before Connect all hosts to pool. Time:9/24/12 9:07 AM
>2012-09-24 09:07:03,675 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-4-thread-50) [44658d55] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 3bf1fc4f
>2012-09-24 09:07:03,752 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-4-thread-50) [44658d55] FINISH, ConnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 3bf1fc4f
>2012-09-24 09:07:03,753 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [44658d55] ActivateStorage Domain. After Connect all hosts to pool. Time:9/24/12 9:07 AM
>2012-09-24 09:07:03,755 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-7) [44658d55] START, ActivateStorageDomainVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842), log id: 7555b86b
>2012-09-24 09:07:03,779 INFO  [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 09:07:03,894 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] hostFromVds::selectedVds - 10.35.160.133, spmStatus Unknown_Pool, storage pool iscsiStorageTest
>2012-09-24 09:07:04,434 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] START, ConnectStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, vds_spm_id = 1, masterDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, masterVersion = 1), log id: 3c9a0dc5
>2012-09-24 09:07:08,196 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] FINISH, ConnectStoragePoolVDSCommand, log id: 3c9a0dc5
>2012-09-24 09:07:08,227 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] hostFromVds::Connected host to pool - selectedVds - 10.35.160.133, spmStatus Free, storage pool iscsiStorageTest
>2012-09-24 09:07:08,464 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] starting spm on vds 10.35.160.133, storage pool iscsiStorageTest, prevId -1, LVER -1
>2012-09-24 09:07:08,469 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] START, SpmStartVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, prevId=-1, prevLVER=-1, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 50af52d2
>2012-09-24 09:07:08,499 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] spmStart polling started: taskId = f9a95ae7-1c40-4282-8653-1fec9538ba28
>2012-09-24 09:07:31,141 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] spmStart polling ended: taskId = f9a95ae7-1c40-4282-8653-1fec9538ba28 task status = finished
>2012-09-24 09:07:31,162 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] spmStart polling ended. spm status: SPM
>2012-09-24 09:07:31,165 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=f9a95ae7-1c40-4282-8653-1fec9538ba28), log id: 72e02618
>2012-09-24 09:07:31,186 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] FINISH, HSMClearTaskVDSCommand, log id: 72e02618
>2012-09-24 09:07:31,186 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@6e376d13, log id: 50af52d2
>2012-09-24 09:07:31,640 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] Initialize Irs proxy from vds: 10.35.160.133
>2012-09-24 09:07:31,746 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] FINISH, ActivateStorageDomainVDSCommand, log id: 7555b86b
>2012-09-24 09:07:31,747 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] ActivateStorage Domain. After Activate storage domain in vds. Time:9/24/12 9:07 AM
>2012-09-24 09:07:31,778 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-4-thread-50) [177b30c8] START, ConnectStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, vds_spm_id = 1, masterDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, masterVersion = 1), log id: 756994bf
>2012-09-24 09:07:31,812 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-4-thread-50) [177b30c8] FINISH, ConnectStoragePoolVDSCommand, log id: 756994bf
>2012-09-24 09:07:31,813 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] ActivateStorage Domain. After Refresh all pools . Time:9/24/12 9:07 AM
>2012-09-24 09:07:31,846 INFO  [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp-/127.0.0.1:8009-7) [177b30c8] ActivateStorage Domain. After change storage pool status in vds. Time:9/24/12 9:07 AM
>2012-09-24 09:07:33,964 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] Lock Acquired to object EngineLock [exclusiveLocks= key: iscsiTestVm value: VM_NAME
>, sharedLocks= ]
>2012-09-24 09:07:34,035 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 5739676e
>2012-09-24 09:07:34,039 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] FINISH, IsValidVDSCommand, return: true, log id: 5739676e
>2012-09-24 09:07:34,086 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] Running command: AddVmFromScratchCommand internal: false. Entities affected :  ID: 680cba18-0615-11e2-bbbc-001a4a169754 Type: VdsGroups
>2012-09-24 09:07:34,088 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 6f6a3cb2
>2012-09-24 09:07:34,090 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] FINISH, IsValidVDSCommand, return: true, log id: 6f6a3cb2
>2012-09-24 09:07:34,180 INFO  [org.ovirt.engine.core.bll.AddVmFromScratchCommand] (ajp-/127.0.0.1:8009-7) [6e09f785] Lock freed to object EngineLock [exclusiveLocks= key: iscsiTestVm value: VM_NAME
>, sharedLocks= ]
>2012-09-24 09:07:35,332 INFO  [org.ovirt.engine.core.bll.AddVmInterfaceCommand] (ajp-/127.0.0.1:8009-4) [6d2c5694] Running command: AddVmInterfaceCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:07:35,333 INFO  [org.ovirt.engine.core.bll.MacPoolManager] (ajp-/127.0.0.1:8009-4) [6d2c5694] MacPoolManager::allocateNewMac entered
>2012-09-24 09:07:35,333 INFO  [org.ovirt.engine.core.bll.MacPoolManager] (ajp-/127.0.0.1:8009-4) [6d2c5694] MacPoolManager::allocateNewMac allocated mac = 00:1a:4a:16:81:11
>2012-09-24 09:07:35,490 INFO  [org.ovirt.engine.core.bll.ActivateDeactivateVmNicCommand] (ajp-/127.0.0.1:8009-4) [76b30075] Running command: ActivateDeactivateVmNicCommand internal: true. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:07:36,637 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-4) [76b30075] No string for UNASSIGNED type. Use default Log
>2012-09-24 09:07:38,800 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-2) [131a515a] Lock Acquired to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM_DISK_BOOT
>, sharedLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>]
>2012-09-24 09:07:38,807 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) [131a515a] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 978f268
>2012-09-24 09:07:38,809 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) [131a515a] FINISH, IsValidVDSCommand, return: true, log id: 978f268
>2012-09-24 09:07:38,844 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-2) [131a515a] Running command: AddDiskCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM,  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:07:38,844 INFO  [org.ovirt.engine.core.bll.ImagesHandler] (ajp-/127.0.0.1:8009-2) [131a515a] Disk alias retrieved from the client is null or empty, the suggested default disk alias to be used is iscsiTestVm_Disk1
>2012-09-24 09:07:39,315 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] Running command: AddImageFromScratchCommand internal: true. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:07:39,415 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] Lock freed to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM_DISK_BOOT
>, sharedLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>]
>2012-09-24 09:07:39,421 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] START, CreateImageVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = 3.1, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, imageSizeInBytes = 21474836480, volumeFormat = COW, newImageId = 5ed98adb-220b-431c-a60c-0afeeaa7405a, newImageDescription = ), log id: 7a4140ba
>2012-09-24 09:07:39,421 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] -- CreateImageVDSCommand::ExecuteIrsBrokerCommand: calling 'createVolume' with two new parameters: description and UUID
>2012-09-24 09:07:39,421 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] -- createVolume parameters:
>                sdUUID=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842
>                spUUID=344227b0-e5d3-4f88-91a5-bb8ba6b0769a
>                imgGUID=b12ff3bd-aa50-4ec5-aa3e-a681795a3507
>                size=21,474,836,480 bytes
>                volFormat=COW
>                volType=Sparse
>                volUUID=5ed98adb-220b-431c-a60c-0afeeaa7405a
>                descr=
>                srcImgGUID=00000000-0000-0000-0000-000000000000
>                srcVolUUID=00000000-0000-0000-0000-000000000000
>                
>2012-09-24 09:07:40,269 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CreateImageVDSCommand] (ajp-/127.0.0.1:8009-2) [66aa9be5] FINISH, CreateImageVDSCommand, return: 5ed98adb-220b-431c-a60c-0afeeaa7405a, log id: 7a4140ba
>2012-09-24 09:07:40,869 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (ajp-/127.0.0.1:8009-2) [66aa9be5] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity b12ff3bd-aa50-4ec5-aa3e-a681795a3507
>2012-09-24 09:07:40,871 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-2) [66aa9be5] EntityMultiAsyncTasks::AttachTask: Attaching task 11e38019-e094-45e7-9691-1a8a009717c0 to entity b12ff3bd-aa50-4ec5-aa3e-a681795a3507.
>2012-09-24 09:07:40,879 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (ajp-/127.0.0.1:8009-2) [66aa9be5] Adding task 11e38019-e094-45e7-9691-1a8a009717c0 to DataBase
>2012-09-24 09:07:42,031 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (ajp-/127.0.0.1:8009-2) [66aa9be5] Adding task 11e38019-e094-45e7-9691-1a8a009717c0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-24 09:07:43,216 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8009-2) [66aa9be5] BaseAsyncTask::StartPollingTask: Starting to poll task 11e38019-e094-45e7-9691-1a8a009717c0.
>2012-09-24 09:07:43,217 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-2) [66aa9be5] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity b12ff3bd-aa50-4ec5-aa3e-a681795a3507 is AddDisk (determined by task 11e38019-e094-45e7-9691-1a8a009717c0)
>2012-09-24 09:07:43,797 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-44) Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
>2012-09-24 09:07:43,829 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-44) SPMAsyncTask::PollTask: Polling task 11e38019-e094-45e7-9691-1a8a009717c0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status running.
>2012-09-24 09:07:43,830 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-44) Finished polling Tasks, will poll again in 10 seconds.
>2012-09-24 09:07:53,861 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-54) SPMAsyncTask::PollTask: Polling task 11e38019-e094-45e7-9691-1a8a009717c0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-24 09:07:54,019 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-54) BaseAsyncTask::OnTaskEndSuccess: Task 11e38019-e094-45e7-9691-1a8a009717c0 (Parent Command AddDisk, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-24 09:07:54,020 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-54) EntityAsyncTask::EndActionIfNecessary: All tasks of entity b12ff3bd-aa50-4ec5-aa3e-a681795a3507 has ended -> executing EndAction
>2012-09-24 09:07:54,020 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-54) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: b12ff3bd-aa50-4ec5-aa3e-a681795a3507): calling EndAction for action type AddDisk.
>2012-09-24 09:07:54,022 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction AddDisk
>2012-09-24 09:07:54,068 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (pool-4-thread-50) [131a515a] Ending command successfully: org.ovirt.engine.core.bll.AddDiskCommand
>2012-09-24 09:07:54,069 INFO  [org.ovirt.engine.core.bll.AddImageFromScratchCommand] (pool-4-thread-50) [66aa9be5] Ending command successfully: org.ovirt.engine.core.bll.AddImageFromScratchCommand
>2012-09-24 09:07:54,081 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [66aa9be5] START, GetImageInfoVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, imageId = 5ed98adb-220b-431c-a60c-0afeeaa7405a), log id: 1e579219
>2012-09-24 09:07:54,778 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [66aa9be5] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@249d52ce, log id: 1e579219
>2012-09-24 09:07:54,897 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) START, UpdateVMVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, infoDictionary.size = 1), log id: 571cf53
>2012-09-24 09:07:54,936 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) FINISH, UpdateVMVDSCommand, log id: 571cf53
>2012-09-24 09:07:55,002 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-24 09:07:55,004 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-24 09:07:55,018 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 11e38019-e094-45e7-9691-1a8a009717c0
>2012-09-24 09:07:55,020 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) START, SPMClearTaskVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = 11e38019-e094-45e7-9691-1a8a009717c0), log id: 6d277d11
>2012-09-24 09:07:55,022 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=11e38019-e094-45e7-9691-1a8a009717c0), log id: 3b6c99ac
>2012-09-24 09:07:55,045 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) FINISH, HSMClearTaskVDSCommand, log id: 3b6c99ac
>2012-09-24 09:07:55,046 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) FINISH, SPMClearTaskVDSCommand, log id: 6d277d11
>2012-09-24 09:07:55,056 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) BaseAsyncTask::RemoveTaskFromDB: Removed task 11e38019-e094-45e7-9691-1a8a009717c0 from DataBase
>2012-09-24 09:07:55,057 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity b12ff3bd-aa50-4ec5-aa3e-a681795a3507
>2012-09-24 09:08:03,817 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 24505b2
>2012-09-24 09:08:03,818 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] FINISH, IsValidVDSCommand, return: true, log id: 24505b2
>2012-09-24 09:08:03,849 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] START, IsVmDuringInitiatingVDSCommand(vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397), log id: 2a849940
>2012-09-24 09:08:03,849 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 2a849940
>2012-09-24 09:08:03,875 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-2) [16816dec] Error during CanDoActionFailure.: java.lang.NullPointerException
>	at org.ovirt.engine.core.bll.RunVmOnceCommand.validateAndSetQuota(RunVmOnceCommand.java:69) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.InternalCanDoAction(CommandBase.java:504) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:268) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:335) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:293) [engine-bll.jar:]
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
>	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) [:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:210) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:362) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:193) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:176) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view7.RunAction(Unknown Source) [engine-common.jar:]
>	at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:190)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:36)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:63)
>	at org.ovirt.engine.api.restapi.resource.BackendVmResource.start(BackendVmResource.java:229)
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invokeOnTargetObject(ResourceLocator.java:152) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invoke(ResourceLocator.java:91) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.1.Final-redhat-1]
>	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
>	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
>	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
>	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
>	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489)
>	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
>	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
>	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
>	at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466)
>	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
>	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
>	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505)
>	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:452)
>	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931)
>	at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_05-icedtea]
>
>2012-09-24 09:08:03,919 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-2) [16816dec] Running command: RunVmOnceCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:08:03,949 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] START, CreateVmVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vmId=13a85351-114b-44ed-b5e9-6af37ebe7397, vm=org.ovirt.engine.core.common.businessentities.VM@10654cd8), log id: 225d2208
>2012-09-24 09:08:03,976 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] START, CreateVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vmId=13a85351-114b-44ed-b5e9-6af37ebe7397, vm=org.ovirt.engine.core.common.businessentities.VM@10654cd8), log id: 6eb6cf09
>2012-09-24 09:08:04,079 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand spiceSslCipherSuite=DEFAULT,memSize=1024,kvmEnable=true,smp=1,emulatedMachine=rhel6.3.0,vmType=kvm,keyboardLayout=en-us,pitReinjection=false,nice=0,display=qxl,smpCoresPerSocket=1,spiceSecureChannels=smain,sinputs,scursor,splayback,srecord,sdisplay,timeOffset=0,transparentHugePages=true,vmId=13a85351-114b-44ed-b5e9-6af37ebe7397,devices=[Ljava.util.Map;@11f8ab6c,acpiEnable=true,vmName=iscsiTestVm,cpuType=Opteron_G3,custom={}
>2012-09-24 09:08:04,080 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.CreateVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] FINISH, CreateVDSCommand, log id: 6eb6cf09
>2012-09-24 09:08:04,087 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] IncreasePendingVms::CreateVmIncreasing vds 10.35.160.133 pending vcpu count, now 1. Vm: iscsiTestVm
>2012-09-24 09:08:04,922 INFO  [org.ovirt.engine.core.vdsbroker.CreateVmVDSCommand] (ajp-/127.0.0.1:8009-2) [16816dec] FINISH, CreateVmVDSCommand, return: WaitForLaunch, log id: 225d2208
>2012-09-24 09:08:07,824 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-68) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from WaitForLaunch --> PoweringUp
>2012-09-24 09:08:07,835 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-68) START, FullListVdsCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vds=null, vmIds=[13a85351-114b-44ed-b5e9-6af37ebe7397]), log id: e26cb00
>2012-09-24 09:08:07,858 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FullListVdsCommand] (QuartzScheduler_Worker-68) FINISH, FullListVdsCommand, return: [Lorg.ovirt.engine.core.vdsbroker.xmlrpc.XmlRpcStruct;@505fa3bf, log id: e26cb00
>2012-09-24 09:09:04,404 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-15) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from PoweringUp --> Up
>2012-09-24 09:09:05,101 INFO  [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (QuartzScheduler_Worker-15) START, UpdateVdsDynamicDataVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vdsDynamic=org.ovirt.engine.core.common.businessentities.VdsDynamic@10b0618e), log id: 453471d9
>2012-09-24 09:09:05,192 INFO  [org.ovirt.engine.core.vdsbroker.UpdateVdsDynamicDataVDSCommand] (QuartzScheduler_Worker-15) FINISH, UpdateVdsDynamicDataVDSCommand, log id: 453471d9
>2012-09-24 09:09:23,780 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-29) Setting new tasks map. The map contains now 0 tasks
>2012-09-24 09:09:23,780 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-29) Cleared all tasks of pool 344227b0-e5d3-4f88-91a5-bb8ba6b0769a.
>2012-09-24 09:09:23,784 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-29) Could not find vds that is spm and non-operational.
>2012-09-24 09:09:36,991 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-41) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from Up --> Paused
>2012-09-24 09:09:39,067 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-42) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from Paused --> Up
>2012-09-24 09:10:00,001 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-61) Autorecovering hosts is disabled, skipping
>2012-09-24 09:10:00,001 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-61) Autorecovering storage domains is disabled, skipping
>2012-09-24 09:13:59,220 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-54) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from Up --> RebootInProgress
>2012-09-24 09:14:41,093 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-86) VM iscsiTestVm 13a85351-114b-44ed-b5e9-6af37ebe7397 moved from RebootInProgress --> Up
>2012-09-24 09:15:00,001 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-100) Autorecovering hosts is disabled, skipping
>2012-09-24 09:15:00,001 INFO  [org.ovirt.engine.core.bll.AutoRecoveryManager] (QuartzScheduler_Worker-100) Autorecovering storage domains is disabled, skipping
>2012-09-24 09:15:16,614 INFO  [org.ovirt.engine.core.bll.StopVmCommand] (ajp-/127.0.0.1:8009-3) [4c0f618c] Running command: StopVmCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:15:16,618 INFO  [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (ajp-/127.0.0.1:8009-3) [4c0f618c] START, DestroyVmVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vmId=13a85351-114b-44ed-b5e9-6af37ebe7397, force=false, secondsToWait=0, gracefully=false), log id: ad2ac29
>2012-09-24 09:15:16,624 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ajp-/127.0.0.1:8009-3) [4c0f618c] START, DestroyVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, vmId=13a85351-114b-44ed-b5e9-6af37ebe7397, force=false, secondsToWait=0, gracefully=false), log id: 60fb2e90
>2012-09-24 09:15:17,438 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (ajp-/127.0.0.1:8009-3) [4c0f618c] FINISH, DestroyVDSCommand, log id: 60fb2e90
>2012-09-24 09:15:17,497 INFO  [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (ajp-/127.0.0.1:8009-3) [4c0f618c] FINISH, DestroyVmVDSCommand, return: Down, log id: ad2ac29
>2012-09-24 09:15:18,410 INFO  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-8) [21aa9682] Running command: AddDiskCommand internal: false. Entities affected :  ID: aaa00000-0000-0000-0000-123456789aaa Type: System
>2012-09-24 09:15:19,005 INFO  [org.ovirt.engine.core.bll.AttachDiskToVmCommand] (ajp-/127.0.0.1:8009-6) [727b186] Lock Acquired to object EngineLock [exclusiveLocks= key: 2c410849-25d9-45ed-a76f-4dd625ba40b1 value: DISK
>, sharedLocks= ]
>2012-09-24 09:15:19,012 INFO  [org.ovirt.engine.core.bll.AttachDiskToVmCommand] (ajp-/127.0.0.1:8009-6) [727b186] Running command: AttachDiskToVmCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM,  ID: 2c410849-25d9-45ed-a76f-4dd625ba40b1 Type: Disk
>2012-09-24 09:15:19,074 INFO  [org.ovirt.engine.core.bll.AttachDiskToVmCommand] (ajp-/127.0.0.1:8009-6) [727b186] Lock freed to object EngineLock [exclusiveLocks= key: 2c410849-25d9-45ed-a76f-4dd625ba40b1 value: DISK
>, sharedLocks= ]
>2012-09-24 09:15:19,080 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-6) [727b186] No severity for USER_ATTACH_DISK_TO_VM type
>2012-09-24 09:15:19,606 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 725b219
>2012-09-24 09:15:19,607 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] FINISH, IsValidVDSCommand, return: true, log id: 725b219
>2012-09-24 09:15:19,647 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] START, IsVmDuringInitiatingVDSCommand(vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397), log id: 7ad129a1
>2012-09-24 09:15:19,647 INFO  [org.ovirt.engine.core.vdsbroker.IsVmDuringInitiatingVDSCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] FINISH, IsVmDuringInitiatingVDSCommand, return: false, log id: 7ad129a1
>2012-09-24 09:15:19,873 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] Error during CanDoActionFailure.: java.lang.NullPointerException
>	at org.ovirt.engine.core.bll.RunVmOnceCommand.validateAndSetQuota(RunVmOnceCommand.java:69) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.InternalCanDoAction(CommandBase.java:504) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:268) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:335) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:293) [engine-bll.jar:]
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
>	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) [:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:210) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:362) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:193) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:176) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view7.RunAction(Unknown Source) [engine-common.jar:]
>	at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:190)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:36)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:63)
>	at org.ovirt.engine.api.restapi.resource.BackendVmResource.start(BackendVmResource.java:229)
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invokeOnTargetObject(ResourceLocator.java:152) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invoke(ResourceLocator.java:91) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.1.Final-redhat-1]
>	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
>	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
>	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
>	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
>	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489)
>	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
>	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
>	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
>	at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466)
>	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
>	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
>	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505)
>	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:452)
>	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931)
>	at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_05-icedtea]
>
>2012-09-24 09:15:19,903 INFO  [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] Running command: RunVmOnceCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:15:19,929 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] Command org.ovirt.engine.core.bll.RunVmOnceCommand throw exception: java.lang.NullPointerException
>	at org.ovirt.engine.core.bll.RunVmCommandBase.connectLunDisks(RunVmCommandBase.java:354) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.RunVmCommand.RunVm(RunVmCommand.java:221) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.RunVmCommand.ExecuteVmCommand(RunVmCommand.java:276) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.VmCommand.executeCommand(VmCommand.java:83) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteWithoutTransaction(CommandBase.java:819) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:910) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1269) [engine-bll.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:204) [engine-utils.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInRequired(TransactionSupport.java:142) [engine-utils.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:109) [engine-utils.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.Execute(CommandBase.java:925) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:275) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:335) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:293) [engine-bll.jar:]
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
>	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) [:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:210) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:362) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:193) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:176) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view7.RunAction(Unknown Source) [engine-common.jar:]
>	at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:190)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:36)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendActionableResource.doAction(AbstractBackendActionableResource.java:63)
>	at org.ovirt.engine.api.restapi.resource.BackendVmResource.start(BackendVmResource.java:229)
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invokeOnTargetObject(ResourceLocator.java:152) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceLocator.invoke(ResourceLocator.java:91) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.1.Final-redhat-1]
>	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
>	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
>	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
>	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
>	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489)
>	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
>	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
>	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
>	at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466)
>	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
>	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
>	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505)
>	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:452)
>	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931)
>	at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_05-icedtea]
>
>2012-09-24 09:15:19,939 ERROR [org.ovirt.engine.core.bll.RunVmOnceCommand] (ajp-/127.0.0.1:8009-8) [357d0f7c] Transaction rolled-back for command: org.ovirt.engine.core.bll.RunVmOnceCommand.
>2012-09-24 09:15:19,988 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-8) Operation Failed: []
>2012-09-24 09:15:26,489 WARN  [org.ovirt.engine.core.bll.StopVmCommand] (ajp-/127.0.0.1:8009-2) [34ee18ad] CanDoAction of action StopVm failed. Reasons:ACTION_TYPE_FAILED_VM_IS_NOT_RUNNING,VAR__ACTION__STOP,VAR__TYPE__VM
>2012-09-24 09:15:26,509 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-2) Operation Failed: [Cannot stop VM. VM is not running.]
>2012-09-24 09:15:27,492 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 66736dcc
>2012-09-24 09:15:27,493 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] FINISH, IsValidVDSCommand, return: true, log id: 66736dcc
>2012-09-24 09:15:27,506 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] START, GetImageInfoVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, imageId = 5ed98adb-220b-431c-a60c-0afeeaa7405a), log id: 28e1cdc6
>2012-09-24 09:15:28,238 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@e49d52ce, log id: 28e1cdc6
>2012-09-24 09:15:28,427 INFO  [org.ovirt.engine.core.bll.AddVmTemplateCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] Running command: AddVmTemplateCommand internal: false. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 09:15:28,438 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] START, SetVmStatusVDSCommand(vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397, status = ImageLocked), log id: 697a1fcd
>2012-09-24 09:15:28,452 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (ajp-/127.0.0.1:8009-5) [20b7cde4] FINISH, SetVmStatusVDSCommand, log id: 697a1fcd
>2012-09-24 09:15:28,488 INFO  [org.ovirt.engine.core.bll.CreateImageTemplateCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] Running command: CreateImageTemplateCommand internal: true. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:15:28,495 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] START, GetImageInfoVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, imageId = 5ed98adb-220b-431c-a60c-0afeeaa7405a), log id: 157413bf
>2012-09-24 09:15:28,885 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@e49d52ce, log id: 157413bf
>2012-09-24 09:15:28,908 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] START, CopyImageVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = 3.1, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, imageId = 5ed98adb-220b-431c-a60c-0afeeaa7405a, dstImageGroupId = 0309150d-e3bf-4f57-bc05-e997acd10832, vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397, dstImageId = f6a3904d-5e2f-4f1f-81ed-e299a0c6340d, imageDescription = Active VM, dstStorageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, copyVolumeType = SharedVol, volumeFormat = COW, preallocate = Sparse, postZero = false, force = false), log id: 46f57578
>2012-09-24 09:15:28,909 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] -- CopyImageVDSCommand::ExecuteIrsBrokerCommand: calling 'copyImage' with two new parameters: description and UUID
>2012-09-24 09:15:28,909 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] -- copyImage parameters:
>                sdUUID=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842
>                spUUID=344227b0-e5d3-4f88-91a5-bb8ba6b0769a
>                vmGUID=13a85351-114b-44ed-b5e9-6af37ebe7397
>                srcImageGUID=b12ff3bd-aa50-4ec5-aa3e-a681795a3507
>                srcVolUUID=5ed98adb-220b-431c-a60c-0afeeaa7405a
>                dstImageGUID=0309150d-e3bf-4f57-bc05-e997acd10832
>                dstVolUUID=f6a3904d-5e2f-4f1f-81ed-e299a0c6340d
>                descr=Active VM
>                
>2012-09-24 09:15:30,564 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.CopyImageVDSCommand] (ajp-/127.0.0.1:8009-5) [33a68e09] FINISH, CopyImageVDSCommand, return: 00000000-0000-0000-0000-000000000000, log id: 46f57578
>2012-09-24 09:15:30,615 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (ajp-/127.0.0.1:8009-5) [33a68e09] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 530387c8-9133-4506-a82d-ccad8ece2dff
>2012-09-24 09:15:30,616 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [33a68e09] EntityMultiAsyncTasks::AttachTask: Attaching task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a to entity 530387c8-9133-4506-a82d-ccad8ece2dff.
>2012-09-24 09:15:30,618 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (ajp-/127.0.0.1:8009-5) [33a68e09] Adding task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a to DataBase
>2012-09-24 09:15:30,654 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (ajp-/127.0.0.1:8009-5) [33a68e09] Adding task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a (Parent Command AddVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-24 09:15:30,776 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8009-5) [33a68e09] BaseAsyncTask::StartPollingTask: Starting to poll task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a.
>2012-09-24 09:15:30,777 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [33a68e09] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 530387c8-9133-4506-a82d-ccad8ece2dff is AddVmTemplate (determined by task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a)
>2012-09-24 09:15:34,076 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-32) Polling and updating Async Tasks: 1 tasks, 1 tasks to poll now
>2012-09-24 09:15:34,103 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-32) SPMAsyncTask::PollTask: Polling task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a (Parent Command AddVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status running.
>2012-09-24 09:15:34,103 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-32) Finished polling Tasks, will poll again in 10 seconds.
>2012-09-24 09:16:34,526 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-83) SPMAsyncTask::PollTask: Polling task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a (Parent Command AddVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-24 09:16:34,545 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-83) BaseAsyncTask::OnTaskEndSuccess: Task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a (Parent Command AddVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-24 09:16:34,546 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-83) EntityAsyncTask::EndActionIfNecessary: All tasks of entity 530387c8-9133-4506-a82d-ccad8ece2dff has ended -> executing EndAction
>2012-09-24 09:16:34,546 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-83) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 530387c8-9133-4506-a82d-ccad8ece2dff): calling EndAction for action type AddVmTemplate.
>2012-09-24 09:16:34,547 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction AddVmTemplate
>2012-09-24 09:16:34,605 INFO  [org.ovirt.engine.core.bll.AddVmTemplateCommand] (pool-4-thread-50) [20b7cde4] Ending command successfully: org.ovirt.engine.core.bll.AddVmTemplateCommand
>2012-09-24 09:16:34,606 INFO  [org.ovirt.engine.core.bll.CreateImageTemplateCommand] (pool-4-thread-50) [33a68e09] Ending command successfully: org.ovirt.engine.core.bll.CreateImageTemplateCommand
>2012-09-24 09:16:34,609 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [33a68e09] START, GetImageInfoVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = 0309150d-e3bf-4f57-bc05-e997acd10832, imageId = f6a3904d-5e2f-4f1f-81ed-e299a0c6340d), log id: 3bf26c80
>2012-09-24 09:16:35,119 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.GetImageInfoVDSCommand] (pool-4-thread-50) [33a68e09] FINISH, GetImageInfoVDSCommand, return: org.ovirt.engine.core.common.businessentities.DiskImage@108eb521, log id: 3bf26c80
>2012-09-24 09:16:35,150 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) START, UpdateVMVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, infoDictionary.size = 1), log id: 247a8a4e
>2012-09-24 09:16:35,178 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.UpdateVMVDSCommand] (pool-4-thread-50) FINISH, UpdateVMVDSCommand, log id: 247a8a4e
>2012-09-24 09:16:35,179 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-50) START, SetVmStatusVDSCommand(vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397, status = Down), log id: 690e1997
>2012-09-24 09:16:35,184 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (pool-4-thread-50) FINISH, SetVmStatusVDSCommand, log id: 690e1997
>2012-09-24 09:16:35,218 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddVmTemplate completed, handling the result.
>2012-09-24 09:16:35,218 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type AddVmTemplate succeeded, clearing tasks.
>2012-09-24 09:16:35,229 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a
>2012-09-24 09:16:35,229 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) START, SPMClearTaskVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = 3a071f5e-4aeb-4416-a3fa-437d25f9e26a), log id: 169bde7c
>2012-09-24 09:16:35,231 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=3a071f5e-4aeb-4416-a3fa-437d25f9e26a), log id: 740aebb6
>2012-09-24 09:16:35,253 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) FINISH, HSMClearTaskVDSCommand, log id: 740aebb6
>2012-09-24 09:16:35,253 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) FINISH, SPMClearTaskVDSCommand, log id: 169bde7c
>2012-09-24 09:16:35,264 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) BaseAsyncTask::RemoveTaskFromDB: Removed task 3a071f5e-4aeb-4416-a3fa-437d25f9e26a from DataBase
>2012-09-24 09:16:35,264 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 530387c8-9133-4506-a82d-ccad8ece2dff
>2012-09-24 09:16:44,036 INFO  [org.ovirt.engine.core.bll.DetachDiskFromVmCommand] (ajp-/127.0.0.1:8009-5) [6ab45b36] Running command: DetachDiskFromVmCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:16:44,110 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (ajp-/127.0.0.1:8009-5) [6ab45b36] No severity for USER_DETACH_DISK_FROM_VM type
>2012-09-24 09:16:44,511 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource] (ajp-/127.0.0.1:8009-8) Could not find sub-resource in the collection resource
>2012-09-24 09:16:45,811 INFO  [org.ovirt.engine.core.bll.RemoveDiskCommand] (ajp-/127.0.0.1:8009-8) [47bb296c] Lock Acquired to object EngineLock [exclusiveLocks= key: 2c410849-25d9-45ed-a76f-4dd625ba40b1 value: DISK
>, sharedLocks= ]
>2012-09-24 09:16:45,856 INFO  [org.ovirt.engine.core.bll.RemoveDiskCommand] (ajp-/127.0.0.1:8009-8) [47bb296c] Running command: RemoveDiskCommand internal: false. Entities affected :  ID: 2c410849-25d9-45ed-a76f-4dd625ba40b1 Type: Disk
>2012-09-24 09:16:45,873 INFO  [org.ovirt.engine.core.utils.transaction.TransactionSupport] (ajp-/127.0.0.1:8009-8) [47bb296c] transaction rolled back
>2012-09-24 09:16:45,876 ERROR [org.ovirt.engine.core.bll.RemoveDiskCommand] (ajp-/127.0.0.1:8009-8) [47bb296c] Command org.ovirt.engine.core.bll.RemoveDiskCommand throw exception: java.lang.NullPointerException
>	at org.ovirt.engine.core.bll.ImagesHandler.removeLunDisk(ImagesHandler.java:665) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.RemoveDiskCommand$1.runInTransaction(RemoveDiskCommand.java:295) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.RemoveDiskCommand$1.runInTransaction(RemoveDiskCommand.java:292) [engine-bll.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInNewTransaction(TransactionSupport.java:204) [engine-utils.jar:]
>	at org.ovirt.engine.core.bll.RemoveDiskCommand.removeLunDisk(RemoveDiskCommand.java:292) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.RemoveDiskCommand.executeCommand(RemoveDiskCommand.java:287) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteWithoutTransaction(CommandBase.java:819) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.executeActionInTransactionScope(CommandBase.java:910) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.runInTransaction(CommandBase.java:1269) [engine-bll.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInSuppressed(TransactionSupport.java:168) [engine-utils.jar:]
>	at org.ovirt.engine.core.utils.transaction.TransactionSupport.executeInScope(TransactionSupport.java:107) [engine-utils.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.Execute(CommandBase.java:925) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.CommandBase.ExecuteAction(CommandBase.java:275) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.runActionImpl(Backend.java:335) [engine-bll.jar:]
>	at org.ovirt.engine.core.bll.Backend.RunAction(Backend.java:293) [engine-bll.jar:]
>	at sun.reflect.GeneratedMethodAccessor184.invoke(Unknown Source) [:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceMethodInterceptorFactory$ManagedReferenceMethodInterceptor.processInvocation(ManagedReferenceMethodInterceptorFactory.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext$Invocation.proceed(InterceptorContext.java:374) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.ovirt.engine.core.utils.ThreadLocalSessionCleanerInterceptor.injectWebContextToThreadLocal(ThreadLocalSessionCleanerInterceptor.java:11) [engine-utils.jar:]
>	at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source) [:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.as.ee.component.ManagedReferenceLifecycleMethodInterceptorFactory$ManagedReferenceLifecycleMethodInterceptor.processInvocation(ManagedReferenceLifecycleMethodInterceptorFactory.java:123) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.WeavedInterceptor.processInvocation(WeavedInterceptor.java:53) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.UserInterceptorFactory$1.processInvocation(UserInterceptorFactory.java:36) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.invocationmetrics.ExecutionTimeInterceptor.processInvocation(ExecutionTimeInterceptor.java:43) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InitialInterceptor.processInvocation(InitialInterceptor.java:21) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.interceptors.ComponentDispatcherInterceptor.processInvocation(ComponentDispatcherInterceptor.java:53) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.singleton.SingletonComponentInstanceAssociationInterceptor.processInvocation(SingletonComponentInstanceAssociationInterceptor.java:53) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.invokeInNoTx(CMTTxInterceptor.java:210) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.supports(CMTTxInterceptor.java:362) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ejb3.tx.CMTTxInterceptor.processInvocation(CMTTxInterceptor.java:193) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.CurrentInvocationContextInterceptor.processInvocation(CurrentInvocationContextInterceptor.java:41) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.ShutDownInterceptorFactory$1.processInvocation(ShutDownInterceptorFactory.java:42) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ejb3.component.interceptors.LoggingInterceptor.processInvocation(LoggingInterceptor.java:59) [jboss-as-ejb3.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.NamespaceContextInterceptor.processInvocation(NamespaceContextInterceptor.java:50) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.TCCLInterceptor.processInvocation(TCCLInterceptor.java:45) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewService$View.invoke(ViewService.java:165) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.as.ee.component.ViewDescription$1.processInvocation(ViewDescription.java:176) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.jboss.invocation.InterceptorContext.proceed(InterceptorContext.java:288) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.invocation.ChainedInterceptor.processInvocation(ChainedInterceptor.java:61) [jboss-invocation.jar:1.1.1.Final-redhat-1]
>	at org.jboss.as.ee.component.ProxyInvocationHandler.invoke(ProxyInvocationHandler.java:72) [jboss-as-ee.jar:7.1.2.Final-redhat-1]
>	at org.ovirt.engine.core.common.interfaces.BackendLocal$$$view7.RunAction(Unknown Source) [engine-common.jar:]
>	at org.ovirt.engine.api.restapi.resource.BackendResource.doAction(BackendResource.java:190)
>	at org.ovirt.engine.api.restapi.resource.BackendResource.performAction(BackendResource.java:144)
>	at org.ovirt.engine.api.restapi.resource.BackendResource.performAction(BackendResource.java:134)
>	at org.ovirt.engine.api.restapi.resource.BackendDisksResource.performRemove(BackendDisksResource.java:57)
>	at org.ovirt.engine.api.restapi.resource.AbstractBackendCollectionResource.remove(AbstractBackendCollectionResource.java:44)
>	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57) [rt.jar:1.7.0_05-icedtea]
>	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) [rt.jar:1.7.0_05-icedtea]
>	at java.lang.reflect.Method.invoke(Method.java:601) [rt.jar:1.7.0_05-icedtea]
>	at org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:257) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:222) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:211) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:525) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:502) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:119) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50) [resteasy-jaxrs.jar:2.3.3.Final-redhat-1]
>	at javax.servlet.http.HttpServlet.service(HttpServlet.java:847) [jboss-servlet-api_3.0_spec.jar:1.0.1.Final-redhat-1]
>	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:329)
>	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:248)
>	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:275)
>	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:161)
>	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:489)
>	at org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:153)
>	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:155)
>	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:102)
>	at org.jboss.web.rewrite.RewriteValve.invoke(RewriteValve.java:466)
>	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109)
>	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:368)
>	at org.apache.coyote.ajp.AjpProcessor.process(AjpProcessor.java:505)
>	at org.apache.coyote.ajp.AjpProtocol$AjpConnectionHandler.process(AjpProtocol.java:452)
>	at org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:931)
>	at java.lang.Thread.run(Thread.java:722) [rt.jar:1.7.0_05-icedtea]
>
>2012-09-24 09:16:45,888 INFO  [org.ovirt.engine.core.bll.RemoveDiskCommand] (ajp-/127.0.0.1:8009-8) [47bb296c] Lock freed to object EngineLock [exclusiveLocks= key: 2c410849-25d9-45ed-a76f-4dd625ba40b1 value: DISK
>, sharedLocks= ]
>2012-09-24 09:16:45,912 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-8) Operation Failed: []
>2012-09-24 09:16:46,892 WARN  [org.ovirt.engine.core.bll.AddDiskCommand] (ajp-/127.0.0.1:8009-2) [3c41f0d2] CanDoAction of action AddDisk failed. Reasons:VAR__ACTION__ADD,VAR__TYPE__VM_DISK,ACTION_TYPE_FAILED_DISK_LUN_IS_ALREADY_IN_USE
>2012-09-24 09:16:46,904 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-2) Operation Failed: [Cannot add Virtual Machine Disk. The provided lun is used by another disk.]
>2012-09-24 09:16:48,055 WARN  [org.ovirt.engine.core.bll.StopVmCommand] (ajp-/127.0.0.1:8009-6) [5db15a34] CanDoAction of action StopVm failed. Reasons:ACTION_TYPE_FAILED_VM_IS_NOT_RUNNING,VAR__ACTION__STOP,VAR__TYPE__VM
>2012-09-24 09:16:48,080 ERROR [org.ovirt.engine.api.restapi.resource.AbstractBackendResource] (ajp-/127.0.0.1:8009-6) Operation Failed: [Cannot stop VM. VM is not running.]
>2012-09-24 09:16:48,309 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8009-1) [33c03682] Lock Acquired to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>, sharedLocks= ]
>2012-09-24 09:16:48,315 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 3a069bf2
>2012-09-24 09:16:48,317 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] FINISH, IsValidVDSCommand, return: true, log id: 3a069bf2
>2012-09-24 09:16:48,366 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8009-1) [33c03682] Running command: RemoveVmCommand internal: false. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:16:48,368 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] START, SetVmStatusVDSCommand(vmId = 13a85351-114b-44ed-b5e9-6af37ebe7397, status = ImageLocked), log id: 10ccfcca
>2012-09-24 09:16:48,373 INFO  [org.ovirt.engine.core.vdsbroker.SetVmStatusVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] FINISH, SetVmStatusVDSCommand, log id: 10ccfcca
>2012-09-24 09:16:48,395 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (ajp-/127.0.0.1:8009-1) [33c03682] Lock freed to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>, sharedLocks= ]
>2012-09-24 09:16:48,397 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] START, RemoveVMVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, vmGuid = 13a85351-114b-44ed-b5e9-6af37ebe7397), log id: 80cfca1
>2012-09-24 09:16:48,423 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand] (ajp-/127.0.0.1:8009-1) [33c03682] FINISH, RemoveVMVDSCommand, log id: 80cfca1
>2012-09-24 09:16:48,431 INFO  [org.ovirt.engine.core.bll.RemoveAllVmImagesCommand] (ajp-/127.0.0.1:8009-1) [c9db228] Running command: RemoveAllVmImagesCommand internal: true. Entities affected :  ID: 13a85351-114b-44ed-b5e9-6af37ebe7397 Type: VM
>2012-09-24 09:16:48,452 INFO  [org.ovirt.engine.core.bll.RemoveImageCommand] (ajp-/127.0.0.1:8009-1) [6bc15c1b] Running command: RemoveImageCommand internal: true. Entities affected :  ID: 00000000-0000-0000-0000-000000000000 Type: Storage
>2012-09-24 09:16:48,469 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (ajp-/127.0.0.1:8009-1) [6bc15c1b] START, DeleteImageGroupVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = 3.1, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = b12ff3bd-aa50-4ec5-aa3e-a681795a3507, postZeros = false, forceDelete = false), log id: 3ea5edac
>2012-09-24 09:16:51,135 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (ajp-/127.0.0.1:8009-1) [6bc15c1b] FINISH, DeleteImageGroupVDSCommand, log id: 3ea5edac
>2012-09-24 09:16:51,162 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (ajp-/127.0.0.1:8009-1) [6bc15c1b] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 13a85351-114b-44ed-b5e9-6af37ebe7397
>2012-09-24 09:16:51,162 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-1) [6bc15c1b] EntityMultiAsyncTasks::AttachTask: Attaching task ff9453bf-35cf-46b8-a673-52dd48459d11 to entity 13a85351-114b-44ed-b5e9-6af37ebe7397.
>2012-09-24 09:16:51,163 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (ajp-/127.0.0.1:8009-1) [6bc15c1b] Adding task ff9453bf-35cf-46b8-a673-52dd48459d11 to DataBase
>2012-09-24 09:16:51,204 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (ajp-/127.0.0.1:8009-1) [6bc15c1b] Adding task ff9453bf-35cf-46b8-a673-52dd48459d11 (Parent Command RemoveVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-24 09:16:52,202 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8009-1) [6bc15c1b] BaseAsyncTask::StartPollingTask: Starting to poll task ff9453bf-35cf-46b8-a673-52dd48459d11.
>2012-09-24 09:16:52,202 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-1) [6bc15c1b] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 13a85351-114b-44ed-b5e9-6af37ebe7397 is RemoveVm (determined by task ff9453bf-35cf-46b8-a673-52dd48459d11)
>2012-09-24 09:16:54,548 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-98) Polling and updating Async Tasks: 2 tasks, 1 tasks to poll now
>2012-09-24 09:16:54,573 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-98) SPMAsyncTask::PollTask: Polling task ff9453bf-35cf-46b8-a673-52dd48459d11 (Parent Command RemoveVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-24 09:16:54,593 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-98) BaseAsyncTask::OnTaskEndSuccess: Task ff9453bf-35cf-46b8-a673-52dd48459d11 (Parent Command RemoveVm, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-24 09:16:54,594 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-98) EntityAsyncTask::EndActionIfNecessary: All tasks of entity 13a85351-114b-44ed-b5e9-6af37ebe7397 has ended -> executing EndAction
>2012-09-24 09:16:54,594 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-98) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 13a85351-114b-44ed-b5e9-6af37ebe7397): calling EndAction for action type RemoveVm.
>2012-09-24 09:16:54,595 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction RemoveVm
>2012-09-24 09:16:54,612 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (pool-4-thread-50) [33c03682] Ending command successfully: org.ovirt.engine.core.bll.RemoveVmCommand
>2012-09-24 09:16:54,613 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (pool-4-thread-50) [33c03682] Lock Acquired to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>, sharedLocks= ]
>2012-09-24 09:16:54,623 INFO  [org.ovirt.engine.core.bll.MacPoolManager] (pool-4-thread-50) [33c03682] MacPoolManager::freeMac(mac = 00:1a:4a:16:81:11) - entered
>2012-09-24 09:16:54,633 INFO  [org.ovirt.engine.core.bll.RemoveVmCommand] (pool-4-thread-50) [33c03682] Lock freed to object EngineLock [exclusiveLocks= key: 13a85351-114b-44ed-b5e9-6af37ebe7397 value: VM
>, sharedLocks= ]
>2012-09-24 09:16:54,652 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveVm completed, handling the result.
>2012-09-24 09:16:54,653 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveVm succeeded, clearing tasks.
>2012-09-24 09:16:54,661 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) SPMAsyncTask::ClearAsyncTask: Attempting to clear task ff9453bf-35cf-46b8-a673-52dd48459d11
>2012-09-24 09:16:54,662 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) START, SPMClearTaskVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = ff9453bf-35cf-46b8-a673-52dd48459d11), log id: 39f0854a
>2012-09-24 09:16:54,663 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=ff9453bf-35cf-46b8-a673-52dd48459d11), log id: 639a4627
>2012-09-24 09:16:54,685 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) FINISH, HSMClearTaskVDSCommand, log id: 639a4627
>2012-09-24 09:16:54,686 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) FINISH, SPMClearTaskVDSCommand, log id: 39f0854a
>2012-09-24 09:16:54,712 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) BaseAsyncTask::RemoveTaskFromDB: Removed task ff9453bf-35cf-46b8-a673-52dd48459d11 from DataBase
>2012-09-24 09:16:54,712 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 13a85351-114b-44ed-b5e9-6af37ebe7397
>2012-09-24 09:17:02,677 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] START, IsValidVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 283e4040
>2012-09-24 09:17:02,679 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IsValidVDSCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] FINISH, IsValidVDSCommand, return: true, log id: 283e4040
>2012-09-24 09:17:03,224 INFO  [org.ovirt.engine.core.bll.RemoveVmTemplateCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] Running command: RemoveVmTemplateCommand internal: false. Entities affected :  ID: 530387c8-9133-4506-a82d-ccad8ece2dff Type: VmTemplate
>2012-09-24 09:17:03,253 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] START, RemoveVMVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 00000000-0000-0000-0000-000000000000, vmGuid = 530387c8-9133-4506-a82d-ccad8ece2dff), log id: 4856d6dd
>2012-09-24 09:17:03,280 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.RemoveVMVDSCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] FINISH, RemoveVMVDSCommand, log id: 4856d6dd
>2012-09-24 09:17:03,288 INFO  [org.ovirt.engine.core.bll.RemoveAllVmTemplateImageTemplatesCommand] (ajp-/127.0.0.1:8009-5) [74a945ad] Running command: RemoveAllVmTemplateImageTemplatesCommand internal: true. Entities affected :  ID: 530387c8-9133-4506-a82d-ccad8ece2dff Type: VmTemplate
>2012-09-24 09:17:03,296 INFO  [org.ovirt.engine.core.bll.RemoveTemplateSnapshotCommand] (ajp-/127.0.0.1:8009-5) [3fcb80] Running command: RemoveTemplateSnapshotCommand internal: true. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:17:03,297 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (ajp-/127.0.0.1:8009-5) [3fcb80] START, DeleteImageGroupVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = 3.1, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, imageGroupId = 0309150d-e3bf-4f57-bc05-e997acd10832, postZeros = false, forceDelete = false), log id: 8e88139
>2012-09-24 09:17:07,343 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeleteImageGroupVDSCommand] (ajp-/127.0.0.1:8009-5) [3fcb80] FINISH, DeleteImageGroupVDSCommand, log id: 8e88139
>2012-09-24 09:17:07,592 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (ajp-/127.0.0.1:8009-5) [3fcb80] EntityAsyncTask::Adding EntityMultiAsyncTasks object for entity 530387c8-9133-4506-a82d-ccad8ece2dff
>2012-09-24 09:17:07,592 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [3fcb80] EntityMultiAsyncTasks::AttachTask: Attaching task 0381207a-eabe-400a-a56f-197d239f500a to entity 530387c8-9133-4506-a82d-ccad8ece2dff.
>2012-09-24 09:17:07,593 INFO  [org.ovirt.engine.core.bll.tasks.AsyncTaskUtils] (ajp-/127.0.0.1:8009-5) [3fcb80] Adding task 0381207a-eabe-400a-a56f-197d239f500a to DataBase
>2012-09-24 09:17:07,624 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (ajp-/127.0.0.1:8009-5) [3fcb80] Adding task 0381207a-eabe-400a-a56f-197d239f500a (Parent Command RemoveVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters), polling hasn't started yet..
>2012-09-24 09:17:07,692 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (ajp-/127.0.0.1:8009-5) [3fcb80] BaseAsyncTask::StartPollingTask: Starting to poll task 0381207a-eabe-400a-a56f-197d239f500a.
>2012-09-24 09:17:07,692 INFO  [org.ovirt.engine.core.bll.EntityMultiAsyncTasks] (ajp-/127.0.0.1:8009-5) [3fcb80] EntityMultiAsyncTasks::StartPollingTask: Current Action Type for entity 530387c8-9133-4506-a82d-ccad8ece2dff is RemoveVmTemplate (determined by task 0381207a-eabe-400a-a56f-197d239f500a)
>2012-09-24 09:17:14,595 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-15) Polling and updating Async Tasks: 3 tasks, 1 tasks to poll now
>2012-09-24 09:17:14,626 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-15) SPMAsyncTask::PollTask: Polling task 0381207a-eabe-400a-a56f-197d239f500a (Parent Command RemoveVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) returned status finished, result 'success'.
>2012-09-24 09:17:14,639 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (QuartzScheduler_Worker-15) BaseAsyncTask::OnTaskEndSuccess: Task 0381207a-eabe-400a-a56f-197d239f500a (Parent Command RemoveVmTemplate, Parameters Type org.ovirt.engine.core.common.asynctasks.AsyncTaskParameters) ended successfully.
>2012-09-24 09:17:14,640 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-15) EntityAsyncTask::EndActionIfNecessary: All tasks of entity 530387c8-9133-4506-a82d-ccad8ece2dff has ended -> executing EndAction
>2012-09-24 09:17:14,641 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (QuartzScheduler_Worker-15) EntityAsyncTask::EndAction: Ending action for 1 tasks (entity ID: 530387c8-9133-4506-a82d-ccad8ece2dff): calling EndAction for action type RemoveVmTemplate.
>2012-09-24 09:17:14,641 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::EndCommandAction [within thread]context: Attempting to EndAction RemoveVmTemplate
>2012-09-24 09:17:14,660 INFO  [org.ovirt.engine.core.bll.RemoveVmTemplateCommand] (pool-4-thread-50) [74a945ad] Ending command successfully: org.ovirt.engine.core.bll.RemoveVmTemplateCommand
>2012-09-24 09:17:14,700 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveVmTemplate completed, handling the result.
>2012-09-24 09:17:14,701 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: EndAction for action type RemoveVmTemplate succeeded, clearing tasks.
>2012-09-24 09:17:14,711 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) SPMAsyncTask::ClearAsyncTask: Attempting to clear task 0381207a-eabe-400a-a56f-197d239f500a
>2012-09-24 09:17:14,711 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) START, SPMClearTaskVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, taskId = 0381207a-eabe-400a-a56f-197d239f500a), log id: 3b0c1e05
>2012-09-24 09:17:14,713 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=0381207a-eabe-400a-a56f-197d239f500a), log id: 38032b2b
>2012-09-24 09:17:14,741 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (pool-4-thread-50) FINISH, HSMClearTaskVDSCommand, log id: 38032b2b
>2012-09-24 09:17:14,741 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SPMClearTaskVDSCommand] (pool-4-thread-50) FINISH, SPMClearTaskVDSCommand, log id: 3b0c1e05
>2012-09-24 09:17:14,751 INFO  [org.ovirt.engine.core.bll.SPMAsyncTask] (pool-4-thread-50) BaseAsyncTask::RemoveTaskFromDB: Removed task 0381207a-eabe-400a-a56f-197d239f500a from DataBase
>2012-09-24 09:17:14,752 INFO  [org.ovirt.engine.core.bll.EntityAsyncTask] (pool-4-thread-50) EntityAsyncTask::HandleEndActionResult [within thread]: Removing EntityMultiAsyncTasks object for entity 530387c8-9133-4506-a82d-ccad8ece2dff
>2012-09-24 09:17:48,512 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8009-3) [407abb0] Lock Acquired to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>key: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a value: POOL
>, sharedLocks= ]
>2012-09-24 09:17:48,620 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8009-3) [407abb0] Running command: DeactivateStorageDomainCommand internal: false. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:17:48,753 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeactivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, DeactivateStorageDomainVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, storageDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, masterDomainId = 00000000-0000-0000-0000-000000000000, masterVersion = 1), log id: 49512011
>2012-09-24 09:17:48,783 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DeactivateStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, DeactivateStorageDomainVDSCommand, log id: 49512011
>2012-09-24 09:17:48,783 INFO  [org.ovirt.engine.core.bll.storage.DeactivateStorageDomainCommand] (ajp-/127.0.0.1:8009-3) [407abb0] Lock freed to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>key: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a value: POOL
>, sharedLocks= ]
>2012-09-24 09:17:48,797 INFO  [org.ovirt.engine.core.bll.storage.AfterDeactivateSingleAsyncOperation] (pool-4-thread-50) [407abb0] After deactivate treatment vds: 10.35.160.133,pool iscsiStorageTest
>2012-09-24 09:17:48,798 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, SpmStopOnIrsVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 7881ba2
>2012-09-24 09:17:48,799 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, ResetIrsVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null, hostName = 10.35.160.133, vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, ignoreStopFailed = false), log id: 6d31080e
>2012-09-24 09:17:48,802 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, SpmStopVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a), log id: 56494403
>2012-09-24 09:17:48,824 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] SpmStopVDSCommand::Stopping SPM on vds 10.35.160.133, pool id 344227b0-e5d3-4f88-91a5-bb8ba6b0769a
>2012-09-24 09:17:49,737 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, SpmStopVDSCommand, log id: 56494403
>2012-09-24 09:17:49,756 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.ResetIrsVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, ResetIrsVDSCommand, log id: 6d31080e
>2012-09-24 09:17:49,756 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.SpmStopOnIrsVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, SpmStopOnIrsVDSCommand, log id: 7881ba2
>2012-09-24 09:17:49,760 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, DisconnectStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, vds_spm_id = 1, masterDomainId = 00000000-0000-0000-0000-000000000000, masterVersion = 0), log id: 2e3c7cb
>2012-09-24 09:17:53,795 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-45) Setting new tasks map. The map contains now 2 tasks
>2012-09-24 09:17:55,205 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, DisconnectStoragePoolVDSCommand, log id: 2e3c7cb
>2012-09-24 09:17:55,222 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] START, DisconnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 5f074107
>2012-09-24 09:17:56,165 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-3) [407abb0] FINISH, DisconnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 5f074107
>2012-09-24 09:17:56,547 INFO  [org.ovirt.engine.core.bll.storage.RemoveStoragePoolCommand] (ajp-/127.0.0.1:8009-8) [13bbf6b6] Running command: RemoveStoragePoolCommand internal: false. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 09:17:56,674 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-4-thread-50) [13bbf6b6] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 7ee43074
>2012-09-24 09:17:56,769 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (pool-4-thread-50) [13bbf6b6] FINISH, ConnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 7ee43074
>2012-09-24 09:17:56,774 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-4-thread-50) [13bbf6b6] START, ConnectStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, vds_spm_id = 1, masterDomainId = 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842, masterVersion = 1), log id: 53a56eaa
>2012-09-24 09:18:00,691 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStoragePoolVDSCommand] (pool-4-thread-50) [13bbf6b6] FINISH, ConnectStoragePoolVDSCommand, log id: 53a56eaa
>2012-09-24 09:18:00,734 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-8) [13bbf6b6] START, DestroyStoragePoolVDSCommand(storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, ignoreFailoverLimit = false, compatabilityVersion = null), log id: 5b48f733
>2012-09-24 09:18:00,743 INFO  [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :  ID: 344227b0-e5d3-4f88-91a5-bb8ba6b0769a Type: StoragePool
>2012-09-24 09:18:00,789 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] hostFromVds::selectedVds - 10.35.160.133, spmStatus Free, storage pool iscsiStorageTest
>2012-09-24 09:18:00,803 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] starting spm on vds 10.35.160.133, storage pool iscsiStorageTest, prevId -1, LVER 0
>2012-09-24 09:18:00,805 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] START, SpmStartVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, prevId=-1, prevLVER=0, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false), log id: 75d2d4d9
>2012-09-24 09:18:00,837 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] spmStart polling started: taskId = f7b74ccb-1569-4f1e-8cc1-915b4ee9b596
>2012-09-24 09:18:23,796 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-70) Setting new tasks map. The map contains now 0 tasks
>2012-09-24 09:18:23,796 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-70) Cleared all tasks of pool 344227b0-e5d3-4f88-91a5-bb8ba6b0769a.
>2012-09-24 09:18:23,799 INFO  [org.ovirt.engine.core.bll.AsyncTaskManager] (QuartzScheduler_Worker-70) Could not find vds that is spm and non-operational.
>2012-09-24 09:18:25,116 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] spmStart polling ended: taskId = f7b74ccb-1569-4f1e-8cc1-915b4ee9b596 task status = finished
>2012-09-24 09:18:25,136 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] spmStart polling ended. spm status: SPM
>2012-09-24 09:18:25,138 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] START, HSMClearTaskVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, taskId=f7b74ccb-1569-4f1e-8cc1-915b4ee9b596), log id: 3850360
>2012-09-24 09:18:25,158 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] FINISH, HSMClearTaskVDSCommand, log id: 3850360
>2012-09-24 09:18:25,159 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@45b271cc, log id: 75d2d4d9
>2012-09-24 09:18:25,178 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] Initialize Irs proxy from vds: 10.35.160.133
>2012-09-24 09:18:32,667 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] IrsProxyData::disposing
>2012-09-24 09:18:32,673 INFO  [org.ovirt.engine.core.vdsbroker.irsbroker.DestroyStoragePoolVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] FINISH, DestroyStoragePoolVDSCommand, log id: 5b48f733
>2012-09-24 09:18:32,995 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] START, DisconnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 223588a
>2012-09-24 09:18:33,935 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-8) [7fcdf4b6] FINISH, DisconnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 223588a
>2012-09-24 09:18:33,951 INFO  [org.ovirt.engine.core.bll.storage.DisconnectStoragePoolAsyncOperation] (pool-4-thread-50) [7fcdf4b6] Disconnect storage pool treatment vds: 10.35.160.133,pool iscsiStorageTest
>2012-09-24 09:18:33,959 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStoragePoolVDSCommand] (pool-4-thread-50) [7fcdf4b6] START, DisconnectStoragePoolVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 344227b0-e5d3-4f88-91a5-bb8ba6b0769a, vds_spm_id = 1, masterDomainId = 00000000-0000-0000-0000-000000000000, masterVersion = 0), log id: 76710ab8
>2012-09-24 09:18:33,981 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStoragePoolVDSCommand] (pool-4-thread-50) [7fcdf4b6] FINISH, DisconnectStoragePoolVDSCommand, log id: 76710ab8
>2012-09-24 09:18:34,463 INFO  [org.ovirt.engine.core.bll.storage.RemoveStorageDomainCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] Lock Acquired to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>, sharedLocks= ]
>2012-09-24 09:18:34,485 INFO  [org.ovirt.engine.core.bll.storage.RemoveStorageDomainCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] Running command: RemoveStorageDomainCommand internal: false. Entities affected :  ID: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 Type: Storage
>2012-09-24 09:18:34,488 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] START, ConnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 46ffffe3
>2012-09-24 09:18:34,575 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] FINISH, ConnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 46ffffe3
>2012-09-24 09:18:34,578 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FormatStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] START, FormatStorageDomainVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storageDomainId=0b3bfe3a-1bf1-456c-bdfe-e545c72e5842), log id: 285c918f
>2012-09-24 09:18:39,951 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.FormatStorageDomainVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] FINISH, FormatStorageDomainVDSCommand, log id: 285c918f
>2012-09-24 09:18:39,952 WARN  [org.ovirt.engine.core.dal.dbbroker.generic.DBConfigUtils] (ajp-/127.0.0.1:8009-5) [2b1a168a] Didnt find the value of IsNeedSupportForOldVgAPI in DB for version 3.1 - using default: false
>2012-09-24 09:18:39,958 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] START, DisconnectStorageServerVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = ISCSI, connectionList = [{ id: cde332ec-669a-48cd-babd-610c58e00263, connection: 10.35.64.102, iqn: iqn.1986-03.com.sun:02:jenkins-vm-0220120827222239551310, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 16ad1d14
>2012-09-24 09:18:40,870 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DisconnectStorageServerVDSCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] FINISH, DisconnectStorageServerVDSCommand, return: {cde332ec-669a-48cd-babd-610c58e00263=0}, log id: 16ad1d14
>2012-09-24 09:18:40,910 INFO  [org.ovirt.engine.core.bll.storage.RemoveStorageDomainCommand] (ajp-/127.0.0.1:8009-5) [2b1a168a] Lock freed to object EngineLock [exclusiveLocks= key: 0b3bfe3a-1bf1-456c-bdfe-e545c72e5842 value: STORAGE
>, sharedLocks= ]
>2012-09-24 09:18:41,598 INFO  [org.ovirt.engine.core.bll.MaintananceNumberOfVdssCommand] (ajp-/127.0.0.1:8009-1) [5375a1f5] Running command: MaintananceNumberOfVdssCommand internal: false. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 09:18:41,602 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-1) [5375a1f5] START, SetVdsStatusVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754, status=PreparingForMaintenance, nonOperationalReason=NONE), log id: 6a42ca37
>2012-09-24 09:18:41,626 INFO  [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] (ajp-/127.0.0.1:8009-1) [5375a1f5] FINISH, SetVdsStatusVDSCommand, log id: 6a42ca37
>2012-09-24 09:18:41,688 INFO  [org.ovirt.engine.core.bll.MaintananceVdsCommand] (ajp-/127.0.0.1:8009-1) [5375a1f5] Running command: MaintananceVdsCommand internal: true. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 09:18:42,252 INFO  [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] (QuartzScheduler_Worker-85) vds::Updated vds status from Preparing for Maintenance to Maintenance in database,  vds = 69add5fa-0615-11e2-b3af-001a4a169754 : 10.35.160.133
>2012-09-24 09:18:51,915 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-5) [36b3a26b] Lock Acquired to object EngineLock [exclusiveLocks= key: 69add5fa-0615-11e2-b3af-001a4a169754 value: VDS
>, sharedLocks= ]
>2012-09-24 09:18:51,926 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-5) [36b3a26b] Running command: RemoveVdsCommand internal: false. Entities affected :  ID: 69add5fa-0615-11e2-b3af-001a4a169754 Type: VDS
>2012-09-24 09:18:52,043 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-5) [36b3a26b] START, RemoveVdsVDSCommand(vdsId = 69add5fa-0615-11e2-b3af-001a4a169754), log id: 334cfc18
>2012-09-24 09:18:52,043 INFO  [org.ovirt.engine.core.vdsbroker.VdsManager] (ajp-/127.0.0.1:8009-5) [36b3a26b] vdsManager::disposing
>2012-09-24 09:18:52,044 INFO  [org.ovirt.engine.core.vdsbroker.RemoveVdsVDSCommand] (ajp-/127.0.0.1:8009-5) [36b3a26b] FINISH, RemoveVdsVDSCommand, log id: 334cfc18
>2012-09-24 09:18:52,045 INFO  [org.ovirt.engine.core.bll.RemoveVdsCommand] (ajp-/127.0.0.1:8009-5) [36b3a26b] Lock freed to object EngineLock [exclusiveLocks= key: 69add5fa-0615-11e2-b3af-001a4a169754 value: VDS
>, sharedLocks= ]
>2012-09-24 09:18:52,185 INFO  [org.ovirt.engine.core.bll.RemoveVdsGroupCommand] (ajp-/127.0.0.1:8009-1) [46849d43] Running command: RemoveVdsGroupCommand internal: false. Entities affected :  ID: 680cba18-0615-11e2-bbbc-001a4a169754 Type: VdsGroups

Actions: View

Attachments on bug 854141: 609569 | 616389 | 624148