Login
[x]
Log in using an account from:
Fedora Account System
Red Hat Associate
Red Hat Customer
Or login using a Red Hat Bugzilla account
Forgot Password
Login:
Hide Forgot
Create an Account
Red Hat Bugzilla – Attachment 616389 Details for
Bug 854141
[engine-core] direct lun: unable to start VM with direct lun disk over FC/Removal of FC lun (java.lang.IndexOutOfBoundsException : Index: 0, Size: 0)
[?]
New
Simple Search
Advanced Search
My Links
Browse
Requests
Reports
Current State
Search
Tabular reports
Graphical reports
Duplicates
Other Reports
User Changes
Plotly Reports
Bug Status
Bug Severity
Non-Defaults
|
Product Dashboard
Help
Page Help!
Bug Writing Guidelines
What's new
Browser Support Policy
5.0.4.rh83 Release notes
FAQ
Guides index
User guide
Web Services
Contact
Legal
This site requires JavaScript to be enabled to function correctly, please enable it.
Engine log
engine.log (text/x-log), 193.42 KB, created by
Jakub Libosvar
on 2012-09-24 07:31:25 UTC
(
hide
)
Description:
Engine log
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
You cannot view the attachment while viewing its details because your browser does not support IFRAMEs.
View the attachment on a separate page
.
View Attachment As Raw
Actions:
View
Attachments on
bug 854141
:
609569
| 616389 |
624148