On 06/05/2014 01:36 PM, Jorick Astrego wrote: vdsm log from the host to see why shutdown failed (and later please open a bug on engine not showing that reason...)

--Apple-Mail=_FD6EAB30-3716-4296-93BD-DD540615AF0F Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=iso-8859-1 On 10 Jun 2014, at 11:31, Jorick Astrego wrote: are=20 power=20 Vms=20 CanDoAction=20 CanDoAction=20 CanDoAction=20 command=20 DestroyVDSCommand,=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 7c4b08f7,=20 Custom=20 command=20 DestroyVDSCommand,=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 2239cfe1,=20 Custom=20 command=20 DestroyVDSCommand,=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 17ece55,=20 Custom=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 ConnectDomainToStorage.=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 storage=20 ID:=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= Call=20 failed.=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= Call=20 failed.=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= Call=20 failed.=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= Call=20 failed.=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 the=20 the=20 the=20 storage=20 ID:=20 ConnectDomainToStorage.=20 the=20 the=20 the=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 the=20 the=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 ConnectDomainToStorage.=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 the=20 storage=20 ID:=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 the=20 the=20 the=20 the=20 the=20 the=20 storage=20 ID:=20 ConnectDomainToStorage.=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 ConnectDomainToStorage.=20 the=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 [org.ovirt.engine.core.bll.OvfDataUpdater]=20 the=20 the=20 ID:=20 status=3DPreparingForMaintenance,=20 1d0d3a10=20 object=20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 ID:=20 out=20 out=20 out=20 Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMOR= Y,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDU= LING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName=20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 43b031c4,=20 Custom=20 Consider=20 object=20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 out=20 out=20 out=20 Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMOR= Y,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDU= LING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName=20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 2b68c51d,=20 Custom=20 [org.ovirt.engine.core.bll.StopVdsCommand]=20 EngineLock=20 VDS_FENCE=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= Custom=20 [org.ovirt.engine.core.bll.FenceExecutor]=20 Default=20 [org.ovirt.engine.core.bll.StopVdsCommand]=20 [org.ovirt.engine.core.bll.StopVdsCommand]=20 [exclusiveLocks=3D=20 storage=20 ID:=20 ConnectDomainToStorage.=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 the=20 the=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 ConnectDomainToStorage.=20 the=20 the=20 the=20 ID:=20 object=20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 out=20 out=20 out=20 Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMOR= Y,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDU= LING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName=20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName= =20 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e=20 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]=20= 51b730a8,=20 Custom=20 storage=20 ID:=20 ConnectDomainToStorage.=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= =20 =20 connectionList=20 null=20 open a bug on engine not showing that reason...)=20 I don't see any failure with the shutdown If the guest fails to shut down for whatever reason we revert back to Up = after 5 mins of trying. Typically it's the guest OS misconfiguration I don't quite follow the timeline of events about storage. Can you = somehow isolate the problem? Thanks, michal again, so I extracted the lines that appear relevant. to tweak the fencing a bit because I caused a split brain on the iSCSI = cluster.=20 wrong with the storage domain. Also the ISO domain went offline but the = nfs server is running on the ovirt-engine vm without any problems.=20 domain a couple of minutes ago, the iSCSI domain went offline instantly = and recovered after about 10 minutes domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso = timedout#012Traceback (most recent call last):#012 File = "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012 = sd.DOMAIN_META_DATA))#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in = callCrabRPCFunction#012 *args, **kwargs)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in = callCrabRPCFunction#012 rawLength =3D = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in = _recvAll#012 raise Timeout()#012Timeout domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso = timedout#012Traceback (most recent call last):#012 File = "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012 = sd.DOMAIN_META_DATA))#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in = callCrabRPCFunction#012 *args, **kwargs)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in = callCrabRPCFunction#012 rawLength =3D = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in = _recvAll#012 raise Timeout()#012Timeout domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso = timedout#012Traceback (most recent call last):#012 File = "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012 = sd.DOMAIN_META_DATA))#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in = callCrabRPCFunction#012 *args, **kwargs)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in = callCrabRPCFunction#012 rawLength =3D = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in = _recvAll#012 raise Timeout()#012Timeout domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso = timedout#012Traceback (most recent call last):#012 File = "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012 = sd.DOMAIN_META_DATA))#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in = callCrabRPCFunction#012 *args, **kwargs)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in = callCrabRPCFunction#012 rawLength =3D = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012 File = "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in = _recvAll#012 raise Timeout()#012Timeout 10.100.100.106 port 67 (xid=3D0x2844d170) (xid=3D0x2844d170) renewal in 269 seconds. 02:50:52,084::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd = iflag=3Ddirect if=3D/dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/metadata = bs=3D4096 count=3D1' (cwd None) 02:50:52,094::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: = <err> =3D '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, = 0.000820898 s, 5.0 MB/s\n'; <rc> =3D 0 02:50:52,191::task::595::TaskManager.Task::(_updateState) = Task=3D`77271c2c-b1c7-4fed-a992-da7cd677c09a`::moving from state init -> = state preparing 02:50:52,192::logUtils::44::dispatcher::(wrapper) Run and protect: = repoStats(options=3DNone) 02:50:52,192::logUtils::47::dispatcher::(wrapper) Run and protect: = repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': = {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', = 'lastCheck': '65.2', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '0.1', 'valid': = True}} 02:50:52,192::task::1185::TaskManager.Task::(prepare) = Task=3D`77271c2c-b1c7-4fed-a992-da7cd677c09a`::finished: = {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, = 'acquired': False, 'delay': '0', 'lastCheck': '65.2', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '0.1', 'valid': = True}} 02:50:52,192::task::595::TaskManager.Task::(_updateState) = Task=3D`77271c2c-b1c7-4fed-a992-da7cd677c09a`::moving from state = preparing -> state finished 02:50:52,193::resourceManager::940::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} 02:50:52,193::resourceManager::977::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} 02:50:52,193::task::990::TaskManager.Task::(_decref) = Task=3D`77271c2c-b1c7-4fed-a992-da7cd677c09a`::ref 0 aborting False 02:50:54,321::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno = 46. 02:50:55,381::task::595::TaskManager.Task::(_updateState) = Task=3D`458009da-0516-40d0-a02c-352377f4108f`::moving from state init -> = state preparing 02:50:55,381::logUtils::44::dispatcher::(wrapper) Run and protect: = repoStats(options=3DNone) 02:50:55,381::logUtils::47::dispatcher::(wrapper) Run and protect: = repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': = {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', = 'lastCheck': '68.4', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '3.3', 'valid': = True}} 02:50:55,381::task::1185::TaskManager.Task::(prepare) = Task=3D`458009da-0516-40d0-a02c-352377f4108f`::finished: = {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, = 'acquired': False, 'delay': '0', 'lastCheck': '68.4', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '3.3', 'valid': = True}} 02:50:55,382::task::595::TaskManager.Task::(_updateState) = Task=3D`458009da-0516-40d0-a02c-352377f4108f`::moving from state = preparing -> state finished 02:50:55,382::resourceManager::940::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} 02:50:55,382::resourceManager::977::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} 02:50:55,382::task::990::TaskManager.Task::(_decref) = Task=3D`458009da-0516-40d0-a02c-352377f4108f`::ref 0 aborting False 02:50:56,969::fileSD::673::scanDomains::(collectMetaFiles) Metadata = collection for domain path = /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout collectMetaFiles callCrabRPCFunction callCrabRPCFunction _recvAll 02:50:56,970::sdc::143::Storage.StorageDomainCache::(_findDomain) domain = 9923a5a1-61e0-4edb-a04d-22c962190c53 not found (u'9923a5a1-61e0-4edb-a04d-22c962190c53',) 02:50:56,971::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDo= main) Error while collecting domain 9923a5a1-61e0-4edb-a04d-22c962190c53 = monitoring information _monitorDomain (u'9923a5a1-61e0-4edb-a04d-22c962190c53',) 02:50:58,602::task::595::TaskManager.Task::(_updateState) = Task=3D`6a746109-728c-4029-b4a2-7b47981f3dba`::moving from state = init -> state preparing 02:50:58,602::logUtils::44::dispatcher::(wrapper) Run and protect: = repoStats(options=3DNone) 02:50:58,603::logUtils::47::dispatcher::(wrapper) Run and protect: = repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': = {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', = 'lastCheck': '1.6', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '6.5', 'valid': = True}} 02:50:58,603::task::1185::TaskManager.Task::(prepare) = Task=3D`6a746109-728c-4029-b4a2-7b47981f3dba`::finished: = {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, = 'acquired': False, 'delay': '0', 'lastCheck': '1.6', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '6.5', 'valid': = True}} 02:50:58,603::task::595::TaskManager.Task::(_updateState) = Task=3D`6a746109-728c-4029-b4a2-7b47981f3dba`::moving from state = preparing -> state finished 02:50:58,603::resourceManager::940::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} 02:50:58,603::resourceManager::977::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} 02:50:58,604::task::990::TaskManager.Task::(_decref) = Task=3D`6a746109-728c-4029-b4a2-7b47981f3dba`::ref 0 aborting False 02:51:01,969::task::595::TaskManager.Task::(_updateState) = Task=3D`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::moving from state init -> = state preparing 02:51:01,969::logUtils::44::dispatcher::(wrapper) Run and protect: = repoStats(options=3DNone) 02:51:01,969::logUtils::47::dispatcher::(wrapper) Run and protect: = repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': = {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', = 'lastCheck': '5.0', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '9.8', 'valid': = True}} 02:51:01,970::task::1185::TaskManager.Task::(prepare) = Task=3D`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::finished: = {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, = 'acquired': False, 'delay': '0', 'lastCheck': '5.0', 'valid': False}, = '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, = 'acquired': True, 'delay': '0.000820898', 'lastCheck': '9.8', 'valid': = True}} 02:51:01,970::task::595::TaskManager.Task::(_updateState) = Task=3D`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::moving from state = preparing -> state finished 02:51:01,970::resourceManager::940::ResourceManager.Owner::(releaseAll) = Owner.releaseAll requests {} resources {} 02:51:01,970::resourceManager::977::ResourceManager.Owner::(cancelAll) = Owner.cancelAll requests {} 02:51:01,970::task::990::TaskManager.Task::(_decref) = Task=3D`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::ref 0 aborting False d185aced-10ef-4d82-9b9f-74ccfa0c4f9c.localhost. cf089115-ac2c-4598-b6a2-e7db8c9368c5.node1.n 968a9da8-76ef-4440-aad7-d4cd48b9d1f9.node1.n 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df= 58aa52/ids:0 0x7f4fbc0008c0:0x7f4fbc0008d0:0x7f4fceff3000 ioto 10 to_count 1 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 10 last_success 266344 0x7f4fbc000910:0x7f4fbc000920:0x7f4fcedf0000 ioto 10 to_count 2 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 11 last_success 266344 0x7f4fbc000960:0x7f4fbc000970:0x7f4fcecee000 ioto 10 to_count 3 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 11 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 0x7f4fbc0009b0:0x7f4fbc0009c0:0x7f4fcebec000 ioto 10 to_count 4 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 11 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 10 last_success 266344 last_success 266344 last_success 266344 last_success 266344 last_success 266344 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids delta_length 10 last_success 266344 0x7f4fbc0008c0 busy 0x7f4fbc000910 busy 0x7f4fbc000960 busy 0x7f4fbc0009b0 busy 0x7f4fbc0008c0 busy 0x7f4fbc000910 busy 0x7f4fbc000960 busy 0x7f4fbc0009b0 busy 0x7f4fbc0008c0 busy 0x7f4fbc000910 busy 0x7f4fbc000960 busy 0x7f4fbc0009b0 busy 0x7f4fbc0008c0 busy 0x7f4fbc000910 busy 0x7f4fbc000960 busy 0x7f4fbc0009b0 busy 0x7f4fbc0008c0 busy 0x7f4fbc000910 busy 0x7f4fbc000960 busy 0x7f4fbc0009b0 busy 0x7f4fbc0008c0:0x7f4fbc0008d0:0x7f4fceff3000 result -5:0 close free 0x7f4fbc000910:0x7f4fbc000920:0x7f4fcedf0000 result -5:0 close free 0x7f4fbc000960:0x7f4fbc000970:0x7f4fcecee000 result -5:0 close free 0x7f4fbc0009b0:0x7f4fbc0009c0:0x7f4fcebec000 result -5:0 close free 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df= 58aa52/ids:0 195b1c86-5d28-4b6a-a31c-924495d6a908.node1.n 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df= 58aa52/ids:0 [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-42) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-19) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.bll.AutoRecoveryManager] = (DefaultQuartzScheduler_Worker-57) [da9c949] Autorecovering 1 storage = domains [org.ovirt.engine.core.bll.AutoRecoveryManager] = (DefaultQuartzScheduler_Worker-57) [da9c949] Autorecovering storage = domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-57) [300d83fb] Running command: = ConnectDomainToStorageCommand internal: true. Entities affected : ID: = 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-57) [300d83fb] ConnectDomainToStorage. = Before Connect all hosts to pool. Time:6/10/14 10:50 AM [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-47) [358da518] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-49) [2aa454] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-38) [6156f20d] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-38) [6156f20d] START, = ConnectStorageServerVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 5ac9e75d [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-49) [2aa454] START, = ConnectStorageServerVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 11873507 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-47) [358da518] START, = ConnectStorageServerVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 487c35ad [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (ajp--127.0.0.1-8702-1) [52284e89] Lock Acquired to object EngineLock = [exclusiveLocks=3D key: 9923a5a1-61e0-4edb-a04d-22c962190c53 value: = STORAGE [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] Running command: = ActivateStorageDomainCommand internal: false. Entities affected : ID: = 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] Lock freed to object = EngineLock [exclusiveLocks=3D key: 9923a5a1-61e0-4edb-a04d-22c962190c53 = value: STORAGE > , sharedLocks=3D ] [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] ActivateStorage Domain. = Before Connect all hosts to pool. Time:6/10/14 10:50 AM [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-13) [649a51c3] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-11) [65c2858f] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-13) [649a51c3] START, = ConnectStorageServerVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 1561dfc [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] START, = ConnectStorageServerVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: d51a4d5 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-11) [65c2858f] START, = ConnectStorageServerVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 48278314 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-47) [358da518] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 487c35ad [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-49) [2aa454] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 11873507 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-38) [6156f20d] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 5ac9e75d [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-57) [300d83fb] ConnectDomainToStorage. = After Connect all hosts to pool. Time:6/10/14 10:51 AM [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-45) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-13) [649a51c3] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 1561dfc [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: d51a4d5 [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-11) [65c2858f] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 48278314 [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand= ] (org.ovirt.thread.pool-6-thread-20) [52284e89] START, = ActivateStorageDomainVDSCommand( storagePoolId =3D = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit =3D false, = storageDomainId =3D 9923a5a1-61e0-4edb-a04d-22c962190c53), log id: = 23981a1b [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-50) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-6) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-35) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand= ] (org.ovirt.thread.pool-6-thread-20) [52284e89] Failed in = ActivateStorageDomainVDS method [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] = IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: = IRSGenericException: IRSErrorException: Failed to = ActivateStorageDomainVDS, error =3D Storage domain does not exist: = ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code =3D 358 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] START, = SpmStopVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId =3D = 00000002-0002-0002-0002-000000000390), log id: 2c173efc [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] = SpmStopVDSCommand::Stopping SPM on vds node2.test.me, pool id = 00000002-0002-0002-0002-000000000390 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] FINISH, = SpmStopVDSCommand, log id: 2c173efc [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [52284e89] Irs placed on server = 28fdcb5d-7acd-410e-8b65-0b4f483cb575 failed. Proceed Failover [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Running command: = SetStoragePoolStatusCommand internal: true. Entities affected : ID: = 00000002-0002-0002-0002-000000000390 Type: StoragePool [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Storage Pool = 00000002-0002-0002-0002-000000000390 - Updating Storage Domain = 0751cdb1-0ee3-494c-88e2-c0e7df58aa52 status from Active to Unknown, = reason : null [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Correlation ID: 6808e2ec, = Call Stack: null, Custom Event ID: -1, Message: Data Center is being = initialized, please wait for initialization to complete. [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] hostFromVds::selectedVds = - node3.test.me, spmStatus Free, storage pool Default [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] SPM Init: could not find = reported vds or not up - pool:Default vds_spm_id: 3 [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] SPM selection - vds seems = as spm node2.test.me [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, = SpmStopVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId =3D = 00000002-0002-0002-0002-000000000390), log id: 4c424d7c [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Command = org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand= return value=20 mMessage=3DNot SPM]] [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] HostName =3D = node2.test.me [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Command = HSMGetAllTasksStatusesVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575) execution failed. Exception: = IRSNonOperationalException: IRSGenericException: IRSErrorException: = IRSNonOperationalException: Not SPM [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, = SpmStopVDSCommand, log id: 4c424d7c [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spm stop succeeded, = continuing with spm selection [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] starting spm on vds = node3.test.me, storage pool Default, prevId 3, LVER 2 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, = SpmStartVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000002-0002-0002-0002-000000000390, prevId=3D3, prevLVER=3D2, = storagePoolFormatType=3DV3, recoveryMode=3DManual, SCSIFencing=3Dtrue), = log id: 3056d822 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling started: = taskId =3D 34c9a402-a886-41e3-bf64-52f554669aba [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-22) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-42) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-10) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-13) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-36) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-43) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-22) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-6) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-43) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-22) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-47) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-38) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-10) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling ended: = taskId =3D 34c9a402-a886-41e3-bf64-52f554669aba task status =3D finished [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling ended, = spm status: SPM [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, = HSMClearTaskVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, = taskId=3D34c9a402-a886-41e3-bf64-52f554669aba), log id: 2e6d491a [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, = HSMClearTaskVDSCommand, log id: 2e6d491a [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, = SpmStartVDSCommand, return: = org.ovirt.engine.core.common.businessentities.SpmStatusResult@6e67a4c7, = log id: 3056d822 [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Initialize Irs proxy from = vds: 10.100.100.48 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Correlation ID: null, = Call Stack: null, Custom Event ID: -1, Message: Storage Pool Manager = runs on Host node3.test.me (Address: 10.100.100.48). [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] START, = SPMGetAllTasksInfoVDSCommand( storagePoolId =3D = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit =3D false), = log id: 7eba1136 [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-40) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-27) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-39) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand= ] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Failed in = ActivateStorageDomainVDS method [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] = IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: = IRSGenericException: IRSErrorException: Failed to = ActivateStorageDomainVDS, error =3D Storage domain does not exist: = ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code =3D 358 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, = SpmStopVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000002-0002-0002-0002-000000000390), log id: 3a60caf5 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] = SpmStopVDSCommand::Stopping SPM on vds node3.test.me, pool id = 00000002-0002-0002-0002-000000000390 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, = SpmStopVDSCommand, log id: 3a60caf5 [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Irs placed on server = 7415506c-cda7-4018-804d-5f6d3beddbfb failed. Proceed Failover [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Running command: = SetStoragePoolStatusCommand internal: true. Entities affected : ID: = 00000002-0002-0002-0002-000000000390 Type: StoragePool [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: 69ff8cdd, = Call Stack: null, Custom Event ID: -1, Message: Data Center is being = initialized, please wait for initialization to complete. [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] hostFromVds::selectedVds = - node4.test.me, spmStatus Free, storage pool Default [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] SPM Init: could not find = reported vds or not up - pool:Default vds_spm_id: 1 [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] SPM selection - vds seems = as spm node3.test.me [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, = SpmStopVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000002-0002-0002-0002-000000000390), log id: 26ccb709 [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command = org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand= return value=20 mMessage=3DNot SPM]] [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] HostName =3D = node3.test.me [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSComman= d] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command = HSMGetAllTasksStatusesVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb) execution failed. Exception: = IRSNonOperationalException: IRSGenericException: IRSErrorException: = IRSNonOperationalException: Not SPM [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, = SpmStopVDSCommand, log id: 26ccb709 [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spm stop succeeded, = continuing with spm selection [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] starting spm on vds = node4.test.me, storage pool Default, prevId 1, LVER 3 [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, = SpmStartVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId =3D = 00000002-0002-0002-0002-000000000390, prevId=3D1, prevLVER=3D3, = storagePoolFormatType=3DV3, recoveryMode=3DManual, SCSIFencing=3Dtrue), = log id: cf0e42f [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling started: = taskId =3D 95b6b948-b7b8-46cb-8cc1-cf9bde431874 [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-8) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-25) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-42) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-23) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-15) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-41) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling ended: = taskId =3D 95b6b948-b7b8-46cb-8cc1-cf9bde431874 task status =3D finished [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling ended, = spm status: SPM [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, = HSMClearTaskVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329, = taskId=3D95b6b948-b7b8-46cb-8cc1-cf9bde431874), log id: 2d9cb3dc [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, = HSMClearTaskVDSCommand, log id: 2d9cb3dc [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, = SpmStartVDSCommand, return: = org.ovirt.engine.core.common.businessentities.SpmStatusResult@6b9b5783, = log id: cf0e42f [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Initialize Irs proxy from = vds: 10.100.100.59 [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: null, = Call Stack: null, Custom Event ID: -1, Message: Storage Pool Manager = runs on Host node4.test.me (Address: 10.100.100.59). [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] START, = SPMGetAllTasksInfoVDSCommand( storagePoolId =3D = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit =3D false), = log id: 6ff3e3ea [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-23) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-17) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-50) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-37) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-19) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand= ] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Failed in = ActivateStorageDomainVDS method [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] = IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: = IRSGenericException: IRSErrorException: Failed to = ActivateStorageDomainVDS, error =3D Storage domain does not exist: = ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code =3D 358 [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] -- = executeIrsBrokerCommand: Attempting on storage pool = 00000002-0002-0002-0002-000000000390 [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand= ] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, = ActivateStorageDomainVDSCommand, log id: 23981a1b [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command = org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand throw Vdc = Bll exception. With error message VdcBLLException: = org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: = IRSGenericException: IRSErrorException: Failed to = ActivateStorageDomainVDS, error =3D Storage domain does not exist: = ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code =3D 358 (Failed with = error StorageDomainDoesNotExist and code 358) [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] START, = HSMGetAllTasksInfoVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329), log id: 6229449d [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] FINISH, = HSMGetAllTasksInfoVDSCommand, return: [], log id: 6229449d [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] FINISH, = SPMGetAllTasksInfoVDSCommand, return: [], log id: 6ff3e3ea [org.ovirt.engine.core.bll.AsyncTaskManager] = (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] Discovered no tasks on = Storage Pool Default [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] -- = executeIrsBrokerCommand: Attempting on storage pool = 00000002-0002-0002-0002-000000000390 [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command = [id=3D8d0ac1fe-ed12-48ac-b8a1-13b8a5f17377]: Compensating = CHANGED_STATUS_ONLY of = org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; = snapshot: EntityStatusSnapshot [id=3DstoragePoolId =3D = 00000002-0002-0002-0002-000000000390, storageId =3D = 9923a5a1-61e0-4edb-a04d-22c962190c53, status=3DInActive]. [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] START, = HSMGetAllTasksInfoVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329), log id: 58f9a1ab [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] = (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: 52284e89, = Job ID: f4061f81-ea0d-479a-bd89-b67acae8ec1a, Call Stack: null, Custom = Event ID: -1, Message: Failed to activate Storage Domain ISO (Data = Center Default) by admin [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] FINISH, = HSMGetAllTasksInfoVDSCommand, return: [], log id: 58f9a1ab [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] FINISH, = SPMGetAllTasksInfoVDSCommand, return: [], log id: 7eba1136 [org.ovirt.engine.core.bll.AsyncTaskManager] = (org.ovirt.thread.pool-6-thread-31) [6808e2ec] Discovered no tasks on = Storage Pool Default [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-4) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-20) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-44) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-37) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-42) Executing a command: = java.util.concurrent.FutureTask , but note that there are 2 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-19) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-41) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-20) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-17) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-47) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-16) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.bll.AutoRecoveryManager] = (DefaultQuartzScheduler_Worker-31) [17ab55ad] Autorecovering 1 storage = domains [org.ovirt.engine.core.bll.AutoRecoveryManager] = (DefaultQuartzScheduler_Worker-31) [17ab55ad] Autorecovering storage = domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-31) [336d7eb4] Running command: = ConnectDomainToStorageCommand internal: true. Entities affected : ID: = 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-31) [336d7eb4] ConnectDomainToStorage. = Before Connect all hosts to pool. Time:6/10/14 11:10 AM [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-36) Executing a command: = java.util.concurrent.FutureTask , but note that there are 2 tasks in the = queue. [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-32) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-15) [5f9a3237] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] = (org.ovirt.thread.pool-6-thread-36) [3fc1d201] Running command: = ConnectStorageToVdsCommand internal: true. Entities affected : ID: = aaa00000-0000-0000-0000-123456789aaa Type: System [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-15) [5f9a3237] START, = ConnectStorageServerVDSCommand(HostName =3D node2.test.me, HostId =3D = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 7d344fac [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] START, = ConnectStorageServerVDSCommand(HostName =3D node3.test.me, HostId =3D = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 7c77503a [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-36) [3fc1d201] START, = ConnectStorageServerVDSCommand(HostName =3D node4.test.me, HostId =3D = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId =3D = 00000000-0000-0000-0000-000000000000, storageType =3D NFS, = connectionList =3D [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, = connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: = null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: = null };]), log id: 449484a0 [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] = (org.ovirt.thread.pool-6-thread-48) Executing a command: = java.util.concurrent.FutureTask , but note that there are 1 tasks in the = queue. [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 7c77503a [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-15) [5f9a3237] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 7d344fac [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand]= (org.ovirt.thread.pool-6-thread-36) [3fc1d201] FINISH, = ConnectStorageServerVDSCommand, return: = {f47e9f99-9989-4297-a84f-4f75338eeced=3D0}, log id: 449484a0 [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] = (DefaultQuartzScheduler_Worker-31) [336d7eb4] ConnectDomainToStorage. = After Connect all hosts to pool. Time:6/10/14 11:11 AM --Apple-Mail=_FD6EAB30-3716-4296-93BD-DD540615AF0F Content-Transfer-Encoding: 7bit Content-Type: text/html; charset=iso-8859-1 <html><head></head><body style="word-wrap: break-word; -webkit-nbsp-mode: space; -webkit-line-break: after-white-space; "><br><div><div>On 10 Jun 2014, at 11:31, Jorick Astrego wrote:</div><br class="Apple-interchange-newline"><blockquote type="cite"> <meta content="text/html; charset=ISO-8859-1" http-equiv="Content-Type"> <div text="#000000" bgcolor="#FFFFFF"> On 06/05/2014 01:36 PM, Jorick Astrego wrote: <br> <blockquote cite="mid:5390BF96.5040906@redhat.com" type="cite"> <blockquote type="cite">Hi, <br> <br> After upgrading to 3.4.2 rc I want to reinstall the nodes. But there are <br> some benchmark VM's that I'm unable to shutdown to put the nodes in <br> maintenance. How can I kill these VM's without having to kill the power <br> to the nodes manually? <br> <br> Kind regards, <br> Jorick Astrego <br> <br> Netbulae B.V. <br> <br> <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:24 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Failed to switch Host node1.test.now to Maintenance mode. <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:24 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Host node1.test.now cannot change into maintenance mode - not all Vms <br> have been migrated successfully. Consider manual intervention: <br> stopping/migrating Vms: Bench1 (User: admin). <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:05 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Shutdown of VM Bench2 failed. <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:05 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Shutdown of VM Bench4 failed. <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:05 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Shutdown of VM Bench3 failed. <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:05 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> Shutdown of VM Bench1 failed. <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:00 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> VM shutdown initiated by admin on VM Bench2 (Host: node2.test.now). <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:00 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> VM shutdown initiated by admin on VM Bench4 (Host: node4.test.now). <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:00 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> VM shutdown initiated by admin on VM Bench3 (Host: node3.test.now). <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> 2014-Jun-05, 12:00 <br> &nbsp;&nbsp;&nbsp;&nbsp; <br> VM shutdown initiated by admin on VM Bench1 (Host: node1.test.now). <br> <br> <br> <br> <br> 2014-06-05 12:00:33,127 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-8) [7c4b08f7] Start running CanDoAction <br> for command number 1/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,130 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-14) [2239cfe1] Start running CanDoAction <br> for command number 2/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,134 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-50) [17ece55] Start running CanDoAction <br> for command number 3/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,225 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-50) [17ece55] Finish handling <br> CanDoAction for command number 3/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,229 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-8) [7c4b08f7] Finish handling <br> CanDoAction for command number 1/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,234 INFO <br> [org.ovirt.engine.core.bll.MultipleActionsRunner] <br> (org.ovirt.thread.pool-6-thread-14) [2239cfe1] Finish handling <br> CanDoAction for command number 2/3 (Command type: ShutdownVm) <br> 2014-06-05 12:00:33,710 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] Running command: <br> ShutdownVmCommand internal: false. Entities affected :&nbsp; ID: <br> 6709eaa1-163f-4dc5-9101-e46870438f38 Type: VM <br> 2014-06-05 12:00:33,728 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] Entered (VM Bench3). <br> 2014-06-05 12:00:33,728 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] Sending shutdown command <br> for VM Bench3. <br> 2014-06-05 12:00:33,764 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] START, <br> DestroyVmVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, <br> vmId=6709eaa1-163f-4dc5-9101-e46870438f38, force=false, <br> secondsToWait=30, gracefully=true), log id: 5eddc358 <br> 2014-06-05 12:00:33,790 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] START, <br> DestroyVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, <br> vmId=6709eaa1-163f-4dc5-9101-e46870438f38, force=false, <br> secondsToWait=30, gracefully=true), log id: 19f6f7c8 <br> 2014-06-05 12:00:33,838 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] FINISH, DestroyVDSCommand, <br> log id: 19f6f7c8 <br> 2014-06-05 12:00:33,843 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] FINISH, <br> DestroyVmVDSCommand, return: PoweringDown, log id: 5eddc358 <br> 2014-06-05 12:00:33,855 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (org.ovirt.thread.pool-6-thread-3) [7c4b08f7] Correlation ID: 7c4b08f7, <br> Job ID: 406c481e-102b-4488-9286-c9b38197ef36, Call Stack: null, Custom <br> Event ID: -1, Message: VM shutdown initiated by admin on VM Bench3 <br> (Host: node3.test.now). <br> 2014-06-05 12:00:33,921 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] Running command: <br> ShutdownVmCommand internal: false. Entities affected :&nbsp; ID: <br> 8b305f06-2c82-4a13-99f2-5beab5a056ea Type: VM <br> 2014-06-05 12:00:33,967 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] Entered (VM Bench4). <br> 2014-06-05 12:00:33,969 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] Sending shutdown command <br> for VM Bench4. <br> 2014-06-05 12:00:34,001 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] START, <br> DestroyVmVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, <br> vmId=8b305f06-2c82-4a13-99f2-5beab5a056ea, force=false, <br> secondsToWait=30, gracefully=true), log id: 23611c0e <br> 2014-06-05 12:00:34,041 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] START, <br> DestroyVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, <br> vmId=8b305f06-2c82-4a13-99f2-5beab5a056ea, force=false, <br> secondsToWait=30, gracefully=true), log id: 4f1663eb <br> 2014-06-05 12:00:34,048 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] FINISH, DestroyVDSCommand, <br> log id: 4f1663eb <br> 2014-06-05 12:00:34,257 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] FINISH, <br> DestroyVmVDSCommand, return: PoweringDown, log id: 23611c0e <br> 2014-06-05 12:00:34,455 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (org.ovirt.thread.pool-6-thread-3) [2239cfe1] Correlation ID: 2239cfe1, <br> Job ID: 00fb00a7-88b0-4fb1-b14a-fa099e3d6409, Call Stack: null, Custom <br> Event ID: -1, Message: VM shutdown initiated by admin on VM Bench4 <br> (Host: node4.test.now). <br> 2014-06-05 12:00:34,677 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] Running command: <br> ShutdownVmCommand internal: false. Entities affected :&nbsp; ID: <br> 764b60fd-c255-479b-9082-3f4f04b95cb2 Type: VM <br> 2014-06-05 12:00:34,695 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] Entered (VM Bench2). <br> 2014-06-05 12:00:34,696 INFO <br> [org.ovirt.engine.core.bll.ShutdownVmCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] Sending shutdown command <br> for VM Bench2. <br> 2014-06-05 12:00:34,718 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] START, <br> DestroyVmVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, <br> vmId=764b60fd-c255-479b-9082-3f4f04b95cb2, force=false, <br> secondsToWait=30, gracefully=true), log id: 215e8d55 <br> 2014-06-05 12:00:34,740 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] START, <br> DestroyVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, <br> vmId=764b60fd-c255-479b-9082-3f4f04b95cb2, force=false, <br> secondsToWait=30, gracefully=true), log id: 6a5599de <br> 2014-06-05 12:00:34,755 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] FINISH, DestroyVDSCommand, <br> log id: 6a5599de <br> 2014-06-05 12:00:34,777 INFO <br> [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] FINISH, <br> DestroyVmVDSCommand, return: PoweringDown, log id: 215e8d55 <br> 2014-06-05 12:00:34,833 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (org.ovirt.thread.pool-6-thread-3) [17ece55] Correlation ID: 17ece55, <br> Job ID: d92b0c9a-fb0f-4ca6-bc51-8d363aaf378c, Call Stack: null, Custom <br> Event ID: -1, Message: VM shutdown initiated by admin on VM Bench2 <br> (Host: node2.test.now). <br> 2014-06-05 12:01:00,648 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-45) [22ac5fb6] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7045fa3b <br> 2014-06-05 12:01:00,650 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-48) [4fbc37fa] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 306b54b0 <br> 2014-06-05 12:01:00,657 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-25) [760d647e] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7f7a769d <br> 2014-06-05 12:01:00,661 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-44) [6949bbc8] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 610dcd45 <br> 2014-06-05 12:01:00,663 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-94) [21aa560a] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:01 PM <br> 2014-06-05 12:02:12,172 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-50) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:02:15,245 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-37) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:02:30,697 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-9) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:02:30,724 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-2) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:03:07,860 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-39) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:04:27,836 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-19) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:04:27,841 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-50) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:05:00,296 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-28) [10a45e4f] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:05:00,296 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-28) [10a45e4f] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:05:00,299 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-28) [9bf7039] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:05:00,304 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-28) [9bf7039] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:05 PM <br> 2014-06-05 12:05:00,441 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-35) [3164009c] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:05:00,446 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-29) [1a51a7f5] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:05:00,450 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-5) [19f33713] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:05:00,454 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-10) [3dd2802] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:05:00,577 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-35) [3164009c] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 7ea7832a <br> 2014-06-05 12:05:00,581 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-29) [1a51a7f5] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 143f44d4 <br> 2014-06-05 12:05:00,580 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-10) [3dd2802] START, <br> ConnectStorageServerVDSCommand(HostName = node1.test.now, HostId = <br> e17a740c-47ba-4a81-99ab-6c386b572f26, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 4058bc78 <br> 2014-06-05 12:05:00,578 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [19f33713] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 6eb8491e <br> 2014-06-05 12:05:23,071 INFO <br> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] <br> (DefaultQuartzScheduler_Worker-10) [77f10397] VM Bench1 <br> 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e moved from PoweringDown --&gt; Up <br> 2014-06-05 12:05:23,153 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-10) [77f10397] Correlation ID: null, Call <br> Stack: null, Custom Event ID: -1, Message: Shutdown of VM Bench1 failed. <br> 2014-06-05 12:05:34,341 INFO <br> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] <br> (DefaultQuartzScheduler_Worker-65) [604c5b5d] VM Bench3 <br> 6709eaa1-163f-4dc5-9101-e46870438f38 moved from PoweringDown --&gt; Up <br> 2014-06-05 12:05:34,411 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-65) [604c5b5d] Correlation ID: null, Call <br> Stack: null, Custom Event ID: -1, Message: Shutdown of VM Bench3 failed. <br> 2014-06-05 12:05:35,312 INFO <br> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] <br> (DefaultQuartzScheduler_Worker-38) [3bbcf288] VM Bench4 <br> 8b305f06-2c82-4a13-99f2-5beab5a056ea moved from PoweringDown --&gt; Up <br> 2014-06-05 12:05:35,439 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-38) [3bbcf288] Correlation ID: null, Call <br> Stack: null, Custom Event ID: -1, Message: Shutdown of VM Bench4 failed. <br> 2014-06-05 12:05:35,663 INFO <br> [org.ovirt.engine.core.vdsbroker.VdsUpdateRunTimeInfo] <br> (DefaultQuartzScheduler_Worker-64) [40fb7b62] VM Bench2 <br> 764b60fd-c255-479b-9082-3f4f04b95cb2 moved from PoweringDown --&gt; Up <br> 2014-06-05 12:05:36,101 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-64) [40fb7b62] Correlation ID: null, Call <br> Stack: null, Custom Event ID: -1, Message: Shutdown of VM Bench2 failed. <br> 2014-06-05 12:06:00,627 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-10) [3dd2802] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 4058bc78 <br> 2014-06-05 12:06:00,629 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-29) [1a51a7f5] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 143f44d4 <br> 2014-06-05 12:06:00,632 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-35) [3164009c] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7ea7832a <br> 2014-06-05 12:06:00,645 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [19f33713] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 6eb8491e <br> 2014-06-05 12:06:00,647 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-28) [9bf7039] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:06 PM <br> 2014-06-05 12:07:17,243 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-11) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:08:16,532 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-1) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:08:25,687 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-46) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:10:00,442 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-77) [7cace458] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:10:00,442 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-77) [7cace458] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:10:00,443 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-77) [77f9bcd3] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:10:00,444 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-77) [77f9bcd3] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:10 PM <br> 2014-06-05 12:10:00,597 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-37) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 3 tasks in the <br> queue. <br> 2014-06-05 12:10:00,598 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-10) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 2 tasks in the <br> queue. <br> 2014-06-05 12:10:00,599 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-35) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:10:00,600 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-5) [7ecb4630] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:10:00,602 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-35) [25233142] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:10:00,606 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-37) [175926fc] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:10:00,607 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-10) [8d05e48] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:10:00,745 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-35) [25233142] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 16b62d67 <br> 2014-06-05 12:10:00,748 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [7ecb4630] START, <br> ConnectStorageServerVDSCommand(HostName = node1.test.now, HostId = <br> e17a740c-47ba-4a81-99ab-6c386b572f26, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 2bc2c88 <br> 2014-06-05 12:10:00,748 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-10) [8d05e48] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 4cb7e97c <br> 2014-06-05 12:10:00,747 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-37) [175926fc] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 442ca304 <br> 2014-06-05 12:10:51,626 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-38) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:10:54,669 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-14) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:11:00,801 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-10) [8d05e48] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 4cb7e97c <br> 2014-06-05 12:11:00,811 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-37) [175926fc] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 442ca304 <br> 2014-06-05 12:11:00,814 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [7ecb4630] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 2bc2c88 <br> 2014-06-05 12:11:00,852 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-35) [25233142] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 16b62d67 <br> 2014-06-05 12:11:00,854 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-77) [77f9bcd3] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:11 PM <br> 2014-06-05 12:11:40,654 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-25) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:12:14,657 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-31) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:12:27,462 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-37) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:13:59,781 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-22) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:15,341 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-10) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:21,429 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-35) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:21,455 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-4) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:40,159 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-17) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:52,383 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-15) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:52,412 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-27) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:14:55,658 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-42) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:15:00,031 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-65) [604c5b5d] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:15:00,031 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-65) [604c5b5d] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:15:00,032 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-65) [7d4ef42] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:15:00,035 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-65) [7d4ef42] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:15 PM <br> 2014-06-05 12:15:00,109 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-45) [6c18413] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:15:00,114 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-5) [d3ad154] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:15:00,118 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-1) [32d6d63f] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:15:00,122 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-24) [718f19c7] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:15:00,247 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-24) [718f19c7] START, <br> ConnectStorageServerVDSCommand(HostName = node1.test.now, HostId = <br> e17a740c-47ba-4a81-99ab-6c386b572f26, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 4bba2a9a <br> 2014-06-05 12:15:00,255 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [d3ad154] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 4c27ad04 <br> 2014-06-05 12:15:00,249 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-1) [32d6d63f] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 1d382d00 <br> 2014-06-05 12:15:00,252 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-45) [6c18413] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 7daf7955 <br> 2014-06-05 12:16:00,301 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-5) [d3ad154] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 4c27ad04 <br> 2014-06-05 12:16:00,302 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-24) [718f19c7] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 4bba2a9a <br> 2014-06-05 12:16:00,305 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-45) [6c18413] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7daf7955 <br> 2014-06-05 12:16:00,313 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-1) [32d6d63f] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 1d382d00 <br> 2014-06-05 12:16:00,424 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-65) [7d4ef42] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:16 PM <br> 2014-06-05 12:18:27,725 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-30) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:18:43,043 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-48) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:18:43,064 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-9) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:18:55,383 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-40) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:18:58,450 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-31) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:19:02,314 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-6) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:20:00,088 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-58) [2e5174b2] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:20:00,088 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-58) [2e5174b2] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:20:00,089 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-58) [106f43a5] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:20:00,090 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-58) [106f43a5] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:20 PM <br> 2014-06-05 12:20:00,175 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-23) [4233af79] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:20:00,180 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-11) [4aa18a96] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:20:00,184 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-40) [48fedac6] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:20:00,188 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-26) [4b39df17] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:20:00,317 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-40) [48fedac6] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 2eb75130 <br> 2014-06-05 12:20:00,321 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-26) [4b39df17] START, <br> ConnectStorageServerVDSCommand(HostName = node1.test.now, HostId = <br> e17a740c-47ba-4a81-99ab-6c386b572f26, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 957b133 <br> 2014-06-05 12:20:00,313 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-11) [4aa18a96] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 28e7a51e <br> 2014-06-05 12:20:00,320 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-23) [4233af79] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 1e3eb653 <br> 2014-06-05 12:21:00,371 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-40) [48fedac6] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 2eb75130 <br> 2014-06-05 12:21:00,375 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-11) [4aa18a96] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 28e7a51e <br> 2014-06-05 12:21:00,376 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-26) [4b39df17] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 957b133 <br> 2014-06-05 12:21:00,400 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-23) [4233af79] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 1e3eb653 <br> 2014-06-05 12:21:00,403 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-58) [106f43a5] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:21 PM <br> 2014-06-05 12:23:10,334 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-23) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:23:34,686 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Attempting to update <br> VMs/Templates Ovf. <br> 2014-06-05 12:23:34,687 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Attempting to update VM <br> OVFs in Data Center Default <br> 2014-06-05 12:23:34,692 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Successfully updated VM <br> OVFs in Data Center Default <br> 2014-06-05 12:23:34,693 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Attempting to update <br> template OVFs in Data Center Default <br> 2014-06-05 12:23:34,695 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Successfully updated <br> templates OVFs in Data Center Default <br> 2014-06-05 12:23:34,695 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Attempting to remove <br> unneeded template/vm OVFs in Data Center Default <br> 2014-06-05 12:23:34,697 INFO [org.ovirt.engine.core.bll.OvfDataUpdater] <br> (DefaultQuartzScheduler_Worker-7) [74449d64] Successfully removed <br> unneeded template/vm OVFs in Data Center Default <br> 2014-06-05 12:23:38,356 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-29) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:23:44,441 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-16) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:24:00,113 INFO <br> [org.ovirt.engine.core.bll.MaintenanceNumberOfVdssCommand] <br> (org.ovirt.thread.pool-6-thread-44) [43b031c4] Running command: <br> MaintenanceNumberOfVdssCommand internal: false. Entities affected : ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:24:00,146 INFO <br> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] <br> (org.ovirt.thread.pool-6-thread-44) [43b031c4] START, <br> SetVdsStatusVDSCommand(HostName = node1.test.now, HostId = <br> e17a740c-47ba-4a81-99ab-6c386b572f26, status=PreparingForMaintenance, <br> nonOperationalReason=NONE, stopSpmFailureLogged=true), log id: 1d0d3a10 <br> 2014-06-05 12:24:00,171 INFO <br> [org.ovirt.engine.core.vdsbroker.SetVdsStatusVDSCommand] <br> (org.ovirt.thread.pool-6-thread-44) [43b031c4] FINISH, <br> SetVdsStatusVDSCommand, log id: 1d0d3a10 <br> 2014-06-05 12:24:00,460 INFO <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (org.ovirt.thread.pool-6-thread-44) [43b031c4] Running command: <br> MaintenanceVdsCommand internal: true. Entities affected :&nbsp; ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:24:00,539 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Lock Acquired to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:24:00,622 INFO <br> [org.ovirt.engine.core.bll.MaintenanceNumberOfVdssCommand] <br> (DefaultQuartzScheduler_Worker-69) [2b68c51d] Running command: <br> MaintenanceNumberOfVdssCommand internal: true. Entities affected : ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:24:00,779 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Candidate host <br> node2.test.now (28fdcb5d-7acd-410e-8b65-0b4f483cb575) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:00,808 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Candidate host <br> node3.test.now (7415506c-cda7-4018-804d-5f6d3beddbfb) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:00,809 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Candidate host <br> node4.test.now (bb13752e-85cb-4945-822b-48ab2a7b1329) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:00,813 WARN <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] CanDoAction of action <br> InternalMigrateVm failed. <br> Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName <br> node2.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node4.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node3.test.now,$filterName Memory,SCHEDULING_HOST_FILTERED_REASON <br> 2014-06-05 12:24:00,825 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Lock freed to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:24:00,860 ERROR <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] <br> ResourceManager::vdsMaintenance - Failed migrating desktop Bench1 <br> 2014-06-05 12:24:00,883 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (org.ovirt.thread.pool-6-thread-44) [155d3855] Correlation ID: 43b031c4, <br> Job ID: 38a05481-0ced-4285-b3ee-6574ce39eb77, Call Stack: null, Custom <br> Event ID: -1, Message: Host node1.test.now cannot change into <br> maintenance mode - not all Vms have been migrated successfully. Consider <br> manual intervention: stopping/migrating Vms: Bench1 (User: admin). <br> 2014-06-05 12:24:00,894 INFO <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (DefaultQuartzScheduler_Worker-69) [2b68c51d] Running command: <br> MaintenanceVdsCommand internal: true. Entities affected :&nbsp; ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:24:01,005 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Lock Acquired to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:24:01,147 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Candidate host <br> node2.test.now (28fdcb5d-7acd-410e-8b65-0b4f483cb575) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:01,155 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Candidate host <br> node3.test.now (7415506c-cda7-4018-804d-5f6d3beddbfb) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:01,166 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Candidate host <br> node4.test.now (bb13752e-85cb-4945-822b-48ab2a7b1329) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:24:01,174 WARN <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] CanDoAction of action <br> InternalMigrateVm failed. <br> Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName <br> node2.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node4.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node3.test.now,$filterName Memory,SCHEDULING_HOST_FILTERED_REASON <br> 2014-06-05 12:24:01,187 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Lock freed to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:24:01,228 ERROR <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] <br> ResourceManager::vdsMaintenance - Failed migrating desktop Bench1 <br> 2014-06-05 12:24:01,238 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-69) [36b0c4c7] Correlation ID: 2b68c51d, <br> Job ID: 3a956cf5-ec2e-45b5-a2bc-40632496fec6, Call Stack: null, Custom <br> Event ID: -1, Message: Failed to switch Host node1.test.now to <br> Maintenance mode. <br> 2014-06-05 12:24:40,507 INFO [org.ovirt.engine.core.bll.StopVdsCommand] <br> (ajp--127.0.0.1-8702-4) [32d3da21] Lock Acquired to object EngineLock <br> [exclusiveLocks= key: e17a740c-47ba-4a81-99ab-6c386b572f26 value: VDS_FENCE <br> , sharedLocks= ] <br> 2014-06-05 12:24:40,798 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (ajp--127.0.0.1-8702-4) Correlation ID: null, Call Stack: null, Custom <br> Event ID: -1, Message: Host node3.test.now from cluster Default was <br> chosen as a proxy to execute Status command on Host node1.test.now. <br> 2014-06-05 12:24:40,799 INFO [org.ovirt.engine.core.bll.FenceExecutor] <br> (ajp--127.0.0.1-8702-4) Using Host node3.test.now from cluster Default <br> as proxy to execute Status command on Host node1.test.now <br> 2014-06-05 12:24:40,800 WARN [org.ovirt.engine.core.bll.StopVdsCommand] <br> (ajp--127.0.0.1-8702-4) CanDoAction of action StopVds failed. <br> Reasons:VAR__ACTION__STOP,VDS_STATUS_NOT_VALID_FOR_STOP <br> 2014-06-05 12:24:40,811 INFO [org.ovirt.engine.core.bll.StopVdsCommand] <br> (ajp--127.0.0.1-8702-4) Lock freed to object EngineLock [exclusiveLocks= <br> key: e17a740c-47ba-4a81-99ab-6c386b572f26 value: VDS_FENCE <br> , sharedLocks= ] <br> 2014-06-05 12:25:00,021 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-27) [70486be2] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:25:00,021 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-27) [70486be2] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:25:00,022 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-27) [70d58101] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:25:00,023 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-27) [70d58101] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:25 PM <br> 2014-06-05 12:25:00,088 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-6) [362a5fe3] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:25:00,093 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-47) [683e82b0] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:25:00,100 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-14) [6ed26267] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:25:00,196 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-6) [362a5fe3] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 4591e85a <br> 2014-06-05 12:25:00,197 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-14) [6ed26267] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 17ef6900 <br> 2014-06-05 12:25:00,197 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-47) [683e82b0] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: db1af1a <br> 2014-06-05 12:25:00,207 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-2) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:25:19,989 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-42) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:26:00,247 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-47) [683e82b0] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: db1af1a <br> 2014-06-05 12:26:00,256 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-6) [362a5fe3] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 4591e85a <br> 2014-06-05 12:26:00,263 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-14) [6ed26267] FINISH, <br> ConnectStorageServerVDSCommand, return: <br> {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 17ef6900 <br> 2014-06-05 12:26:00,265 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-27) [70d58101] ConnectDomainToStorage. <br> After Connect all hosts to pool. Time:6/5/14 12:26 PM <br> 2014-06-05 12:28:15,399 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-17) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:28:18,443 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-8) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:28:55,121 WARN <br> [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] <br> (org.ovirt.thread.pool-6-thread-45) Executing a command: <br> java.util.concurrent.FutureTask , but note that there are 1 tasks in the <br> queue. <br> 2014-06-05 12:29:04,927 INFO <br> [org.ovirt.engine.core.bll.MaintenanceNumberOfVdssCommand] <br> (DefaultQuartzScheduler_Worker-51) [51b730a8] Running command: <br> MaintenanceNumberOfVdssCommand internal: true. Entities affected : ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:29:05,029 INFO <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (DefaultQuartzScheduler_Worker-51) [51b730a8] Running command: <br> MaintenanceVdsCommand internal: true. Entities affected :&nbsp; ID: <br> e17a740c-47ba-4a81-99ab-6c386b572f26 Type: VDS <br> 2014-06-05 12:29:05,073 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Lock Acquired to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:29:05,164 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Candidate host <br> node2.test.now (28fdcb5d-7acd-410e-8b65-0b4f483cb575) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:29:05,167 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Candidate host <br> node3.test.now (7415506c-cda7-4018-804d-5f6d3beddbfb) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:29:05,170 INFO <br> [org.ovirt.engine.core.bll.scheduling.SchedulingManager] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Candidate host <br> node4.test.now (bb13752e-85cb-4945-822b-48ab2a7b1329) was filtered out <br> by VAR__FILTERTYPE__INTERNAL filter Memory <br> 2014-06-05 12:29:05,173 WARN <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-51) [63736865] CanDoAction of action <br> InternalMigrateVm failed. <br> Reasons:VAR__ACTION__MIGRATE,VAR__TYPE__VM,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,ACTION_TYPE_FAILED_VDS_VM_MEMORY,SCHEDULING_ALL_HOSTS_FILTERED_OUT,VAR__FILTERTYPE__INTERNAL,$hostName <br> node2.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node4.test.now,$filterName <br> Memory,SCHEDULING_HOST_FILTERED_REASON,VAR__FILTERTYPE__INTERNAL,$hostName <br> node3.test.now,$filterName Memory,SCHEDULING_HOST_FILTERED_REASON <br> 2014-06-05 12:29:05,181 INFO <br> [org.ovirt.engine.core.bll.InternalMigrateVmCommand] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Lock freed to object <br> EngineLock [exclusiveLocks= key: 63b1fd02-1fb5-44d1-b1cc-54cb5c0fdb0e <br> value: VM <br> , sharedLocks= ] <br> 2014-06-05 12:29:05,207 ERROR <br> [org.ovirt.engine.core.bll.MaintenanceVdsCommand] <br> (DefaultQuartzScheduler_Worker-51) [63736865] <br> ResourceManager::vdsMaintenance - Failed migrating desktop Bench1 <br> 2014-06-05 12:29:05,218 INFO <br> [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] <br> (DefaultQuartzScheduler_Worker-51) [63736865] Correlation ID: 51b730a8, <br> Job ID: b8441378-051c-4af0-8802-e2efb9e5d4a4, Call Stack: null, Custom <br> Event ID: -1, Message: Failed to switch Host node1.test.now to <br> Maintenance mode. <br> 2014-06-05 12:30:00,018 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-52) [2e3993e6] Autorecovering 1 storage <br> domains <br> 2014-06-05 12:30:00,018 INFO <br> [org.ovirt.engine.core.bll.AutoRecoveryManager] <br> (DefaultQuartzScheduler_Worker-52) [2e3993e6] Autorecovering storage <br> domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53 <br> 2014-06-05 12:30:00,021 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-52) [1585ee27] Running command: <br> ConnectDomainToStorageCommand internal: true. Entities affected : ID: <br> 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage <br> 2014-06-05 12:30:00,024 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] <br> (DefaultQuartzScheduler_Worker-52) [1585ee27] ConnectDomainToStorage. <br> Before Connect all hosts to pool. Time:6/5/14 12:30 PM <br> 2014-06-05 12:30:00,119 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-17) [6c0a8af9] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:30:00,121 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-26) [10056f73] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:30:00,134 INFO <br> [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] <br> (org.ovirt.thread.pool-6-thread-24) [750ef0f4] Running command: <br> ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: <br> aaa00000-0000-0000-0000-123456789aaa Type: System <br> 2014-06-05 12:30:00,248 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-17) [6c0a8af9] START, <br> ConnectStorageServerVDSCommand(HostName = node4.test.now, HostId = <br> bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 1c35901d <br> 2014-06-05 12:30:00,250 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-24) [750ef0f4] START, <br> ConnectStorageServerVDSCommand(HostName = node2.test.now, HostId = <br> 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 1a4d78a1 <br> 2014-06-05 12:30:00,250 INFO <br> [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] <br> (org.ovirt.thread.pool-6-thread-26) [10056f73] START, <br> ConnectStorageServerVDSCommand(HostName = node3.test.now, HostId = <br> 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = <br> 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList <br> = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: <br> 10.100.100.105:/var/lib/exports/iso, iqn: null, vfsType: null, <br> mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null <br> };]), log id: 60464b56 <br> <br> <br> <br> _______________________________________________ <br> Users mailing list <br> <a class="moz-txt-link-abbreviated" href="mailto:Users@ovirt.org">Users@ovirt.org</a> <br> <a class="moz-txt-link-freetext" href="http://lists.ovirt.org/mailman/listinfo/users">http://... <br> <br> </blockquote> <br> vdsm log from the host to see why shutdown failed (and later please open a bug on engine not showing that reason...) <br></blockquote></div></blockquote><div><br></div><div>I don't see any failure with the shutdown</div><div>If the guest fails to shut down for whatever reason we revert back to Up after 5 mins of trying. Typically it's the guest OS misconfiguration</div><div><br></div><div>I don't quite follow the timeline of events about storage. Can you somehow isolate the problem?</div><div><br></div><div>Thanks,</div><div>michal</div><div><br></div><br><blockquote type="cite"><div text="#000000" bgcolor="#FFFFFF"><blockquote cite="mid:5390BF96.5040906@redhat.com" type="cite"> </blockquote> <br> Hi,<br> <br> The logs are filled with the same messages and errors over and over again, so I extracted the lines that appear relevant.<br> <br> The problem appears to be that the iSCSI failover went wrong. I have to tweak the fencing a bit because I caused a split brain on the iSCSI cluster. <br> <br> I recovered the storage but ovirt engine didn't notice anything went wrong with the storage domain. Also the ISO domain went offline but the nfs server is running on the ovirt-engine vm without any problems. <br> I cannot get it to go up again.... When I tried to activate the ISO domain a couple of minutes ago, the iSCSI domain went offline instantly and recovered after about 10 minutes<br> <br> So strange things happening...<br> <br> /var/log/messages:<br> <br> <blockquote> Jun 10 02:49:46 node1 vdsm scanDomains WARNING Metadata collection for domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout#012Traceback (most recent call last):#012&nbsp; File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012&nbsp;&nbsp;&nbsp; sd.DOMAIN_META_DATA))#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; *args, **kwargs)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll#012&nbsp;&nbsp;&nbsp; raise Timeout()#012Timeout<br> Jun 10 02:50:56 node1 vdsm scanDomains WARNING Metadata collection for domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout#012Traceback (most recent call last):#012&nbsp; File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012&nbsp;&nbsp;&nbsp; sd.DOMAIN_META_DATA))#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; *args, **kwargs)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll#012&nbsp;&nbsp;&nbsp; raise Timeout()#012Timeout<br> Jun 10 02:52:06 node1 vdsm scanDomains WARNING Metadata collection for domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout#012Traceback (most recent call last):#012&nbsp; File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012&nbsp;&nbsp;&nbsp; sd.DOMAIN_META_DATA))#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; *args, **kwargs)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll#012&nbsp;&nbsp;&nbsp; raise Timeout()#012Timeout<br> Jun 10 02:53:16 node1 vdsm scanDomains WARNING Metadata collection for domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout#012Traceback (most recent call last):#012&nbsp; File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles#012&nbsp;&nbsp;&nbsp; sd.DOMAIN_META_DATA))#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; *args, **kwargs)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction#012&nbsp;&nbsp;&nbsp; rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)#012&nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll#012&nbsp;&nbsp;&nbsp; raise Timeout()#012Timeout<br> Jun 10 02:53:32 node1 dhclient[18102]: DHCPREQUEST on bond0 to 10.100.100.106 port 67 (xid=0x2844d170)<br> Jun 10 02:53:32 node1 dhclient[18102]: DHCPACK from 10.100.100.106 (xid=0x2844d170)<br> Jun 10 02:53:34 node1 dhclient[18102]: bound to 10.100.100.53 -- renewal in 269 seconds.<br> </blockquote> <br> /var/log/vdsm/vdsm.log:<br> <br> <blockquote> Thread-15::DEBUG::2014-06-10 02:50:52,084::blockSD::600::Storage.Misc.excCmd::(getReadDelay) '/bin/dd iflag=direct if=/dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/metadata bs=4096 count=1' (cwd None)<br> Thread-15::DEBUG::2014-06-10 02:50:52,094::blockSD::600::Storage.Misc.excCmd::(getReadDelay) SUCCESS: &lt;err&gt; = '1+0 records in\n1+0 records out\n4096 bytes (4.1 kB) copied, 0.000820898 s, 5.0 MB/s\n'; &lt;rc&gt; = 0<br> Thread-5167::DEBUG::2014-06-10 02:50:52,191::task::595::TaskManager.Task::(_updateState) Task=`77271c2c-b1c7-4fed-a992-da7cd677c09a`::moving from state init -&gt; state preparing<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:52,192::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:52,192::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '65.2', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '0.1', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:52,192::task::1185::TaskManager.Task::(prepare) Task=`77271c2c-b1c7-4fed-a992-da7cd677c09a`::finished: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '65.2', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '0.1', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:52,192::task::595::TaskManager.Task::(_updateState) Task=`77271c2c-b1c7-4fed-a992-da7cd677c09a`::moving from state preparing -&gt; state finished<br> Thread-5167::DEBUG::2014-06-10 02:50:52,193::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}<br> Thread-5167::DEBUG::2014-06-10 02:50:52,193::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br> Thread-5167::DEBUG::2014-06-10 02:50:52,193::task::990::TaskManager.Task::(_decref) Task=`77271c2c-b1c7-4fed-a992-da7cd677c09a`::ref 0 aborting False<br> VM Channels Listener::DEBUG::2014-06-10 02:50:54,321::vmChannels::91::vds::(_handle_timeouts) Timeout on fileno 46.<br> Thread-5167::DEBUG::2014-06-10 02:50:55,381::task::595::TaskManager.Task::(_updateState) Task=`458009da-0516-40d0-a02c-352377f4108f`::moving from state init -&gt; state preparing<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:55,381::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:55,381::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '68.4', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '3.3', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:55,381::task::1185::TaskManager.Task::(prepare) Task=`458009da-0516-40d0-a02c-352377f4108f`::finished: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '68.4', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '3.3', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:55,382::task::595::TaskManager.Task::(_updateState) Task=`458009da-0516-40d0-a02c-352377f4108f`::moving from state preparing -&gt; state finished<br> Thread-5167::DEBUG::2014-06-10 02:50:55,382::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}<br> Thread-5167::DEBUG::2014-06-10 02:50:55,382::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br> Thread-5167::DEBUG::2014-06-10 02:50:55,382::task::990::TaskManager.Task::(_decref) Task=`458009da-0516-40d0-a02c-352377f4108f`::ref 0 aborting False<br> Thread-12128::WARNING::2014-06-10 02:50:56,969::fileSD::673::scanDomains::(collectMetaFiles) Metadata collection for domain path /rhev/data-center/mnt/xx.xxx.xxx.xxx:_var_lib_exports_iso timedout<br> Traceback (most recent call last):<br> &nbsp; File "/usr/share/vdsm/storage/fileSD.py", line 662, in collectMetaFiles<br> &nbsp;&nbsp;&nbsp; sd.DOMAIN_META_DATA))<br> &nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 297, in callCrabRPCFunction<br> &nbsp;&nbsp;&nbsp; *args, **kwargs)<br> &nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 184, in callCrabRPCFunction<br> &nbsp;&nbsp;&nbsp; rawLength = self._recvAll(LENGTH_STRUCT_LENGTH, timeout)<br> &nbsp; File "/usr/share/vdsm/storage/remoteFileHandler.py", line 150, in _recvAll<br> &nbsp;&nbsp;&nbsp; raise Timeout()<br> Timeout<br> Thread-40::ERROR::2014-06-10 02:50:56,970::sdc::143::Storage.StorageDomainCache::(_findDomain) domain 9923a5a1-61e0-4edb-a04d-22c962190c53 not found<br> Traceback (most recent call last):<br> &nbsp; File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain<br> &nbsp;&nbsp;&nbsp; dom = findMethod(sdUUID)<br> &nbsp; File "/usr/share/vdsm/storage/nfsSD.py", line 132, in findDomain<br> &nbsp;&nbsp;&nbsp; return NfsStorageDomain(NfsStorageDomain.findDomainPath(sdUUID))<br> &nbsp; File "/usr/share/vdsm/storage/nfsSD.py", line 122, in findDomainPath<br> &nbsp;&nbsp;&nbsp; raise se.StorageDomainDoesNotExist(sdUUID)<br> StorageDomainDoesNotExist: Storage domain does not exist: (u'9923a5a1-61e0-4edb-a04d-22c962190c53',)<br> Thread-40::ERROR::2014-06-10 02:50:56,971::domainMonitor::239::Storage.DomainMonitorThread::(_monitorDomain) Error while collecting domain 9923a5a1-61e0-4edb-a04d-22c962190c53 monitoring information<br> Traceback (most recent call last):<br> &nbsp; File "/usr/share/vdsm/storage/domainMonitor.py", line 215, in _monitorDomain<br> &nbsp;&nbsp;&nbsp; self.domain.selftest()<br> &nbsp; File "/usr/share/vdsm/storage/sdc.py", line 49, in __getattr__<br> &nbsp;&nbsp;&nbsp; return getattr(self.getRealDomain(), attrName)<br> &nbsp; File "/usr/share/vdsm/storage/sdc.py", line 52, in getRealDomain<br> &nbsp;&nbsp;&nbsp; return self._cache._realProduce(self._sdUUID)<br> &nbsp; File "/usr/share/vdsm/storage/sdc.py", line 122, in _realProduce<br> &nbsp;&nbsp;&nbsp; domain = self._findDomain(sdUUID)<br> &nbsp; File "/usr/share/vdsm/storage/sdc.py", line 141, in _findDomain<br> &nbsp;&nbsp;&nbsp; dom = findMethod(sdUUID)<br> &nbsp; File "/usr/share/vdsm/storage/nfsSD.py", line 132, in findDomain<br> &nbsp;&nbsp;&nbsp; return NfsStorageDomain(NfsStorageDomain.findDomainPath(sdUUID))<br> &nbsp; File "/usr/share/vdsm/storage/nfsSD.py", line 122, in findDomainPath<br> &nbsp;&nbsp;&nbsp; raise se.StorageDomainDoesNotExist(sdUUID)<br> StorageDomainDoesNotExist: Storage domain does not exist: (u'9923a5a1-61e0-4edb-a04d-22c962190c53',)<br> Thread-5167::DEBUG::2014-06-10 02:50:58,602::task::595::TaskManager.Task::(_updateState) Task=`6a746109-728c-4029-b4a2-7b47981f3dba`::moving from state init -&gt; state preparing<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:58,602::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:50:58,603::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '1.6', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '6.5', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:58,603::task::1185::TaskManager.Task::(prepare) Task=`6a746109-728c-4029-b4a2-7b47981f3dba`::finished: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '1.6', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '6.5', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:50:58,603::task::595::TaskManager.Task::(_updateState) Task=`6a746109-728c-4029-b4a2-7b47981f3dba`::moving from state preparing -&gt; state finished<br> Thread-5167::DEBUG::2014-06-10 02:50:58,603::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}<br> Thread-5167::DEBUG::2014-06-10 02:50:58,603::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br> Thread-5167::DEBUG::2014-06-10 02:50:58,604::task::990::TaskManager.Task::(_decref) Task=`6a746109-728c-4029-b4a2-7b47981f3dba`::ref 0 aborting False<br> Thread-5167::DEBUG::2014-06-10 02:51:01,969::task::595::TaskManager.Task::(_updateState) Task=`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::moving from state init -&gt; state preparing<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:51:01,969::logUtils::44::dispatcher::(wrapper) Run and protect: repoStats(options=None)<br> Thread-5167::<a class="moz-txt-link-freetext" href="info::2014-06-10">INFO::2014-06-10</a> 02:51:01,969::logUtils::47::dispatcher::(wrapper) Run and protect: repoStats, Return response: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '5.0', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '9.8', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:51:01,970::task::1185::TaskManager.Task::(prepare) Task=`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::finished: {u'9923a5a1-61e0-4edb-a04d-22c962190c53': {'code': 358, 'version': -1, 'acquired': False, 'delay': '0', 'lastCheck': '5.0', 'valid': False}, '0751cdb1-0ee3-494c-88e2-c0e7df58aa52': {'code': 0, 'version': 3, 'acquired': True, 'delay': '0.000820898', 'lastCheck': '9.8', 'valid': True}}<br> Thread-5167::DEBUG::2014-06-10 02:51:01,970::task::595::TaskManager.Task::(_updateState) Task=`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::moving from state preparing -&gt; state finished<br> Thread-5167::DEBUG::2014-06-10 02:51:01,970::resourceManager::940::ResourceManager.Owner::(releaseAll) Owner.releaseAll requests {} resources {}<br> Thread-5167::DEBUG::2014-06-10 02:51:01,970::resourceManager::977::ResourceManager.Owner::(cancelAll) Owner.cancelAll requests {}<br> Thread-5167::DEBUG::2014-06-10 02:51:01,970::task::990::TaskManager.Task::(_decref) Task=`0f9bf6e2-ea86-4b4a-8fe2-d7634705429c`::ref 0 aborting False<br> </blockquote> <br> <br> /var/log/sanlock.log:<br> <br> <blockquote> 2014-05-19 09:49:00+0000 38 [10499]: sanlock daemon started 2.8 host d185aced-10ef-4d82-9b9f-74ccfa0c4f9c.localhost.<br> 2014-05-19 09:54:54+0000 64 [13495]: sanlock daemon started 2.8 host cf089115-ac2c-4598-b6a2-e7db8c9368c5.node1.n<br> 2014-05-19 09:56:49+0000 178 [14390]: sanlock daemon started 2.8 host 968a9da8-76ef-4440-aad7-d4cd48b9d1f9.node1.n<br> 2014-05-19 10:02:36+0000 525 [14396]: s1 lockspace 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids:0<br> 2014-05-22 11:53:26+0000 266375 [19131]: 0751cdb1 aio timeout 0 0x7f4fbc0008c0:0x7f4fbc0008d0:0x7f4fceff3000 ioto 10 to_count 1<br> 2014-05-22 11:53:26+0000 266375 [19131]: s1 delta_renew read rv -202 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:53:26+0000 266375 [19131]: s1 renewal error -202 delta_length 10 last_success 266344<br> 2014-05-22 11:53:37+0000 266386 [19131]: 0751cdb1 aio timeout 0 0x7f4fbc000910:0x7f4fbc000920:0x7f4fcedf0000 ioto 10 to_count 2<br> 2014-05-22 11:53:37+0000 266386 [19131]: s1 delta_renew read rv -202 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:53:37+0000 266386 [19131]: s1 renewal error -202 delta_length 11 last_success 266344<br> 2014-05-22 11:53:48+0000 266397 [19131]: 0751cdb1 aio timeout 0 0x7f4fbc000960:0x7f4fbc000970:0x7f4fcecee000 ioto 10 to_count 3<br> 2014-05-22 11:53:48+0000 266397 [19131]: s1 delta_renew read rv -202 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:53:48+0000 266397 [19131]: s1 renewal error -202 delta_length 11 last_success 266344<br> 2014-05-22 11:53:55+0000 266404 [14390]: s1 check_our_lease warning 60 last_success 266344<br> 2014-05-22 11:53:56+0000 266405 [14390]: s1 check_our_lease warning 61 last_success 266344<br> 2014-05-22 11:53:57+0000 266406 [14390]: s1 check_our_lease warning 62 last_success 266344<br> 2014-05-22 11:53:58+0000 266407 [14390]: s1 check_our_lease warning 63 last_success 266344<br> 2014-05-22 11:53:59+0000 266408 [14390]: s1 check_our_lease warning 64 last_success 266344<br> 2014-05-22 11:53:59+0000 266408 [19131]: 0751cdb1 aio timeout 0 0x7f4fbc0009b0:0x7f4fbc0009c0:0x7f4fcebec000 ioto 10 to_count 4<br> 2014-05-22 11:53:59+0000 266408 [19131]: s1 delta_renew read rv -202 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:53:59+0000 266408 [19131]: s1 renewal error -202 delta_length 11 last_success 266344<br> 2014-05-22 11:54:00+0000 266409 [14390]: s1 check_our_lease warning 65 last_success 266344<br> 2014-05-22 11:54:01+0000 266410 [14390]: s1 check_our_lease warning 66 last_success 266344<br> 2014-05-22 11:54:02+0000 266411 [14390]: s1 check_our_lease warning 67 last_success 266344<br> 2014-05-22 11:54:03+0000 266412 [14390]: s1 check_our_lease warning 68 last_success 266344<br> 2014-05-22 11:54:04+0000 266413 [14390]: s1 check_our_lease warning 69 last_success 266344<br> 2014-05-22 11:54:05+0000 266414 [14390]: s1 check_our_lease warning 70 last_success 266344<br> 2014-05-22 11:54:06+0000 266415 [14390]: s1 check_our_lease warning 71 last_success 266344<br> 2014-05-22 11:54:07+0000 266416 [14390]: s1 check_our_lease warning 72 last_success 266344<br> 2014-05-22 11:54:08+0000 266417 [14390]: s1 check_our_lease warning 73 last_success 266344<br> 2014-05-22 11:54:09+0000 266418 [14390]: s1 check_our_lease warning 74 last_success 266344<br> 2014-05-22 11:54:10+0000 266419 [14390]: s1 check_our_lease warning 75 last_success 266344<br> 2014-05-22 11:54:10+0000 266419 [19131]: s1 delta_renew read rv -2 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:54:10+0000 266419 [19131]: s1 renewal error -2 delta_length 10 last_success 266344<br> 2014-05-22 11:54:11+0000 266420 [14390]: s1 check_our_lease warning 76 last_success 266344<br> 2014-05-22 11:54:12+0000 266421 [14390]: s1 check_our_lease warning 77 last_success 266344<br> 2014-05-22 11:54:13+0000 266422 [14390]: s1 check_our_lease warning 78 last_success 266344<br> 2014-05-22 11:54:14+0000 266423 [14390]: s1 check_our_lease warning 79 last_success 266344<br> 2014-05-22 11:54:15+0000 266424 [14390]: s1 check_our_lease failed 80<br> 2014-05-22 11:54:15+0000 266424 [14390]: s1 all pids clear<br> 2014-05-22 11:54:20+0000 266430 [19131]: s1 delta_renew read rv -2 offset 0 /dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids<br> 2014-05-22 11:54:20+0000 266430 [19131]: s1 renewal error -2 delta_length 10 last_success 266344<br> 2014-05-22 11:54:30+0000 266440 [19131]: 0751cdb1 close_task_aio 0 0x7f4fbc0008c0 busy<br> 2014-05-22 11:54:30+0000 266440 [19131]: 0751cdb1 close_task_aio 1 0x7f4fbc000910 busy<br> 2014-05-22 11:54:30+0000 266440 [19131]: 0751cdb1 close_task_aio 2 0x7f4fbc000960 busy<br> 2014-05-22 11:54:30+0000 266440 [19131]: 0751cdb1 close_task_aio 3 0x7f4fbc0009b0 busy<br> 2014-05-22 11:54:40+0000 266450 [19131]: 0751cdb1 close_task_aio 0 0x7f4fbc0008c0 busy<br> 2014-05-22 11:54:40+0000 266450 [19131]: 0751cdb1 close_task_aio 1 0x7f4fbc000910 busy<br> 2014-05-22 11:54:40+0000 266450 [19131]: 0751cdb1 close_task_aio 2 0x7f4fbc000960 busy<br> 2014-05-22 11:54:40+0000 266450 [19131]: 0751cdb1 close_task_aio 3 0x7f4fbc0009b0 busy<br> 2014-05-22 11:54:50+0000 266460 [19131]: 0751cdb1 close_task_aio 0 0x7f4fbc0008c0 busy<br> 2014-05-22 11:54:50+0000 266460 [19131]: 0751cdb1 close_task_aio 1 0x7f4fbc000910 busy<br> 2014-05-22 11:54:50+0000 266460 [19131]: 0751cdb1 close_task_aio 2 0x7f4fbc000960 busy<br> 2014-05-22 11:54:50+0000 266460 [19131]: 0751cdb1 close_task_aio 3 0x7f4fbc0009b0 busy<br> 2014-05-22 11:55:00+0000 266470 [19131]: 0751cdb1 close_task_aio 0 0x7f4fbc0008c0 busy<br> 2014-05-22 11:55:00+0000 266470 [19131]: 0751cdb1 close_task_aio 1 0x7f4fbc000910 busy<br> 2014-05-22 11:55:00+0000 266470 [19131]: 0751cdb1 close_task_aio 2 0x7f4fbc000960 busy<br> 2014-05-22 11:55:00+0000 266470 [19131]: 0751cdb1 close_task_aio 3 0x7f4fbc0009b0 busy<br> 2014-05-22 11:55:10+0000 266480 [19131]: 0751cdb1 close_task_aio 0 0x7f4fbc0008c0 busy<br> 2014-05-22 11:55:10+0000 266480 [19131]: 0751cdb1 close_task_aio 1 0x7f4fbc000910 busy<br> 2014-05-22 11:55:10+0000 266480 [19131]: 0751cdb1 close_task_aio 2 0x7f4fbc000960 busy<br> 2014-05-22 11:55:10+0000 266480 [19131]: 0751cdb1 close_task_aio 3 0x7f4fbc0009b0 busy<br> 2014-05-22 11:55:16+0000 266485 [19131]: 0751cdb1 aio collect 0x7f4fbc0008c0:0x7f4fbc0008d0:0x7f4fceff3000 result -5:0 close free<br> 2014-05-22 11:55:16+0000 266485 [19131]: 0751cdb1 aio collect 0x7f4fbc000910:0x7f4fbc000920:0x7f4fcedf0000 result -5:0 close free<br> 2014-05-22 11:55:16+0000 266485 [19131]: 0751cdb1 aio collect 0x7f4fbc000960:0x7f4fbc000970:0x7f4fcecee000 result -5:0 close free<br> 2014-05-22 11:55:16+0000 266485 [19131]: 0751cdb1 aio collect 0x7f4fbc0009b0:0x7f4fbc0009c0:0x7f4fcebec000 result -5:0 close free<br> 2014-05-22 12:57:13+0000 270202 [14395]: s2 lockspace 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids:0<br> 2014-06-10 08:11:20+0000 81 [15201]: sanlock daemon started 2.8 host 195b1c86-5d28-4b6a-a31c-924495d6a908.node1.n<br> 2014-06-10 08:13:49+0000 230 [15207]: s1 lockspace 0751cdb1-0ee3-494c-88e2-c0e7df58aa52:4:/dev/0751cdb1-0ee3-494c-88e2-c0e7df58aa52/ids:0<br> <br> </blockquote> /var/log/ovirt-engine.log:<br> <br> <blockquote> 2014-06-10 10:49:27,492 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-42) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:49:27,514 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-19) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:50:00,265 INFO&nbsp; [org.ovirt.engine.core.bll.AutoRecoveryManager] (DefaultQuartzScheduler_Worker-57) [da9c949] Autorecovering 1 storage domains<br> 2014-06-10 10:50:00,265 INFO&nbsp; [org.ovirt.engine.core.bll.AutoRecoveryManager] (DefaultQuartzScheduler_Worker-57) [da9c949] Autorecovering storage domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53<br> 2014-06-10 10:50:00,266 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-57) [300d83fb] Running command: ConnectDomainToStorageCommand internal: true. Entities affected :&nbsp; ID: 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage<br> 2014-06-10 10:50:00,266 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-57) [300d83fb] ConnectDomainToStorage. Before Connect all hosts to pool. Time:6/10/14 10:50 AM<br> 2014-06-10 10:50:00,466 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-47) [358da518] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:00,470 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-49) [2aa454] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:00,474 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-38) [6156f20d] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:00,570 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-38) [6156f20d] START, ConnectStorageServerVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 5ac9e75d<br> 2014-06-10 10:50:00,573 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-49) [2aa454] START, ConnectStorageServerVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 11873507<br> 2014-06-10 10:50:00,572 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-47) [358da518] START, ConnectStorageServerVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 487c35ad<br> 2014-06-10 10:50:04,526 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (ajp--127.0.0.1-8702-1) [52284e89] Lock Acquired to object EngineLock [exclusiveLocks= key: 9923a5a1-61e0-4edb-a04d-22c962190c53 value: STORAGE<br> , sharedLocks= ]<br> 2014-06-10 10:50:05,865 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] Running command: ActivateStorageDomainCommand internal: false. Entities affected :&nbsp; ID: 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage<br> 2014-06-10 10:50:06,010 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] Lock freed to object EngineLock [exclusiveLocks= key: 9923a5a1-61e0-4edb-a04d-22c962190c53 value: STORAGE<br> , sharedLocks= ]<br> 2014-06-10 10:50:06,010 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] ActivateStorage Domain. Before Connect all hosts to pool. Time:6/10/14 10:50 AM<br> 2014-06-10 10:50:06,062 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-13) [649a51c3] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:06,066 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:06,070 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-11) [65c2858f] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 10:50:06,176 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-13) [649a51c3] START, ConnectStorageServerVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 1561dfc<br> 2014-06-10 10:50:06,199 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] START, ConnectStorageServerVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: d51a4d5<br> 2014-06-10 10:50:06,206 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-11) [65c2858f] START, ConnectStorageServerVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 48278314<br> 2014-06-10 10:51:00,615 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-47) [358da518] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 487c35ad<br> 2014-06-10 10:51:00,620 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-49) [2aa454] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 11873507<br> 2014-06-10 10:51:00,623 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-38) [6156f20d] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 5ac9e75d<br> 2014-06-10 10:51:00,625 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-57) [300d83fb] ConnectDomainToStorage. After Connect all hosts to pool. Time:6/10/14 10:51 AM<br> 2014-06-10 10:51:03,733 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-45) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:51:06,229 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-13) [649a51c3] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 1561dfc<br> 2014-06-10 10:51:06,271 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-14) [27b7ad5a] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: d51a4d5<br> 2014-06-10 10:51:06,273 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-11) [65c2858f] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 48278314<br> 2014-06-10 10:51:06,275 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] START, ActivateStorageDomainVDSCommand( storagePoolId = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit = false, storageDomainId = 9923a5a1-61e0-4edb-a04d-22c962190c53), log id: 23981a1b<br> 2014-06-10 10:51:13,278 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-50) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:51:22,474 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-6) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:51:35,071 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-35) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:52:34,068 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] Failed in ActivateStorageDomainVDS method<br> 2014-06-10 10:52:34,069 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to ActivateStorageDomainVDS, error = Storage domain does not exist: ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code = 358<br> 2014-06-10 10:52:34,146 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] START, SpmStopVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = 00000002-0002-0002-0002-000000000390), log id: 2c173efc<br> 2014-06-10 10:52:34,202 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] SpmStopVDSCommand::Stopping SPM on vds node2.test.me, pool id 00000002-0002-0002-0002-000000000390<br> 2014-06-10 10:52:38,260 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] FINISH, SpmStopVDSCommand, log id: 2c173efc<br> 2014-06-10 10:52:38,261 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [52284e89] Irs placed on server 28fdcb5d-7acd-410e-8b65-0b4f483cb575 failed. Proceed Failover<br> 2014-06-10 10:52:38,327 INFO&nbsp; [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :&nbsp; ID: 00000002-0002-0002-0002-000000000390 Type: StoragePool<br> 2014-06-10 10:52:38,329 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.storage.StoragePoolDomainHelper] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Storage Pool 00000002-0002-0002-0002-000000000390 - Updating Storage Domain 0751cdb1-0ee3-494c-88e2-c0e7df58aa52 status from Active to Unknown, reason : null<br> 2014-06-10 10:52:38,402 INFO&nbsp; [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Correlation ID: 6808e2ec, Call Stack: null, Custom Event ID: -1, Message: Data Center is being initialized, please wait for initialization to complete.<br> 2014-06-10 10:52:38,409 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] hostFromVds::selectedVds - node3.test.me, spmStatus Free, storage pool Default<br> 2014-06-10 10:52:38,412 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] SPM Init: could not find reported vds or not up - pool:Default vds_spm_id: 3<br> 2014-06-10 10:52:38,452 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] SPM selection - vds seems as spm node2.test.me<br> 2014-06-10 10:52:38,482 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, SpmStopVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = 00000002-0002-0002-0002-000000000390), log id: 4c424d7c<br> 2014-06-10 10:52:38,491 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value <br> &nbsp;<br> TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]<br> <br> 2014-06-10 10:52:38,509 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] HostName = node2.test.me<br> 2014-06-10 10:52:38,509 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Command HSMGetAllTasksStatusesVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM<br> 2014-06-10 10:52:38,510 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, SpmStopVDSCommand, log id: 4c424d7c<br> 2014-06-10 10:52:38,510 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spm stop succeeded, continuing with spm selection<br> 2014-06-10 10:52:38,524 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] starting spm on vds node3.test.me, storage pool Default, prevId 3, LVER 2<br> 2014-06-10 10:52:38,542 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, SpmStartVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000002-0002-0002-0002-000000000390, prevId=3, prevLVER=2, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=true), log id: 3056d822<br> 2014-06-10 10:52:38,555 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling started: taskId = 34c9a402-a886-41e3-bf64-52f554669aba<br> 2014-06-10 10:52:39,301 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-22) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:52:39,324 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-42) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:52:52,175 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-10) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:53:41,630 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-13) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:00,852 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-36) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:06,936 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-43) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:09,979 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-22) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:43,966 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-6) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:53,204 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-43) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:54:56,248 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-22) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:55:26,994 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-47) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:55:30,037 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-38) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:55:30,058 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-10) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:56:50,452 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling ended: taskId = 34c9a402-a886-41e3-bf64-52f554669aba task status = finished<br> 2014-06-10 10:56:50,498 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] spmStart polling ended, spm status: SPM<br> 2014-06-10 10:56:50,517 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, HSMClearTaskVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, taskId=34c9a402-a886-41e3-bf64-52f554669aba), log id: 2e6d491a<br> 2014-06-10 10:56:50,573 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, HSMClearTaskVDSCommand, log id: 2e6d491a<br> 2014-06-10 10:56:50,574 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@6e67a4c7, log id: 3056d822<br> 2014-06-10 10:56:50,597 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Initialize Irs proxy from vds: 10.100.100.48<br> 2014-06-10 10:56:50,622 INFO&nbsp; [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Storage Pool Manager runs on Host node3.test.me (Address: 10.100.100.48).<br> 2014-06-10 10:56:50,644 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] START, SPMGetAllTasksInfoVDSCommand( storagePoolId = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit = false), log id: 7eba1136<br> 2014-06-10 10:57:48,685 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-40) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:58:28,613 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-27) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:58:34,731 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-39) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 10:58:49,587 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Failed in ActivateStorageDomainVDS method<br> 2014-06-10 10:58:49,588 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to ActivateStorageDomainVDS, error = Storage domain does not exist: ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code = 358<br> 2014-06-10 10:58:49,666 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] START, SpmStopVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000002-0002-0002-0002-000000000390), log id: 3a60caf5<br> 2014-06-10 10:58:49,711 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] SpmStopVDSCommand::Stopping SPM on vds node3.test.me, pool id 00000002-0002-0002-0002-000000000390<br> 2014-06-10 10:58:52,611 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] FINISH, SpmStopVDSCommand, log id: 3a60caf5<br> 2014-06-10 10:58:52,611 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [6808e2ec] Irs placed on server 7415506c-cda7-4018-804d-5f6d3beddbfb failed. Proceed Failover<br> 2014-06-10 10:58:52,668 INFO&nbsp; [org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Running command: SetStoragePoolStatusCommand internal: true. Entities affected :&nbsp; ID: 00000002-0002-0002-0002-000000000390 Type: StoragePool<br> 2014-06-10 10:58:52,991 INFO&nbsp; [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: 69ff8cdd, Call Stack: null, Custom Event ID: -1, Message: Data Center is being initialized, please wait for initialization to complete.<br> 2014-06-10 10:58:52,997 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] hostFromVds::selectedVds - node4.test.me, spmStatus Free, storage pool Default<br> 2014-06-10 10:58:53,000 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] SPM Init: could not find reported vds or not up - pool:Default vds_spm_id: 1<br> 2014-06-10 10:58:53,017 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] SPM selection - vds seems as spm node3.test.me<br> 2014-06-10 10:58:53,035 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, SpmStopVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000002-0002-0002-0002-000000000390), log id: 26ccb709<br> 2014-06-10 10:58:53,043 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand return value <br> &nbsp;<br> TaskStatusListReturnForXmlRpc [mStatus=StatusForXmlRpc [mCode=654, mMessage=Not SPM]]<br> <br> 2014-06-10 10:58:53,060 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] HostName = node3.test.me<br> 2014-06-10 10:58:53,061 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command HSMGetAllTasksStatusesVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb) execution failed. Exception: IRSNonOperationalException: IRSGenericException: IRSErrorException: IRSNonOperationalException: Not SPM<br> 2014-06-10 10:58:53,061 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, SpmStopVDSCommand, log id: 26ccb709<br> 2014-06-10 10:58:53,062 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spm stop succeeded, continuing with spm selection<br> 2014-06-10 10:58:53,091 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] starting spm on vds node4.test.me, storage pool Default, prevId 1, LVER 3<br> 2014-06-10 10:58:53,108 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, SpmStartVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = 00000002-0002-0002-0002-000000000390, prevId=1, prevLVER=3, storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=true), log id: cf0e42f<br> 2014-06-10 10:58:53,117 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling started: taskId = 95b6b948-b7b8-46cb-8cc1-cf9bde431874<br> 2014-06-10 11:01:46,832 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-8) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:01:55,979 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-25) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:02:51,420 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-42) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:02:54,477 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-23) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:03:06,978 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-15) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:03:10,033 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-41) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:03:50,450 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling ended: taskId = 95b6b948-b7b8-46cb-8cc1-cf9bde431874 task status = finished<br> 2014-06-10 11:03:50,511 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] spmStart polling ended, spm status: SPM<br> 2014-06-10 11:03:50,528 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] START, HSMClearTaskVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329, taskId=95b6b948-b7b8-46cb-8cc1-cf9bde431874), log id: 2d9cb3dc<br> 2014-06-10 11:03:50,588 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, HSMClearTaskVDSCommand, log id: 2d9cb3dc<br> 2014-06-10 11:03:50,588 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, SpmStartVDSCommand, return: org.ovirt.engine.core.common.businessentities.SpmStatusResult@6b9b5783, log id: cf0e42f<br> 2014-06-10 11:03:50,890 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Initialize Irs proxy from vds: 10.100.100.59<br> 2014-06-10 11:03:50,935 INFO&nbsp; [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: null, Call Stack: null, Custom Event ID: -1, Message: Storage Pool Manager runs on Host node4.test.me (Address: 10.100.100.59).<br> 2014-06-10 11:03:50,980 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] START, SPMGetAllTasksInfoVDSCommand( storagePoolId = 00000002-0002-0002-0002-000000000390, ignoreFailoverLimit = false), log id: 6ff3e3ea<br> 2014-06-10 11:04:29,664 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-23) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:04:32,809 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-17) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:04:54,324 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-50) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:04:57,368 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-37) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:05:00,433 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-19) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:05:49,611 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Failed in ActivateStorageDomainVDS method<br> 2014-06-10 11:05:49,612 ERROR [org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] IrsBroker::Failed::ActivateStorageDomainVDS due to: IRSErrorException: IRSGenericException: IRSErrorException: Failed to ActivateStorageDomainVDS, error = Storage domain does not exist: ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code = 358<br> 2014-06-10 11:05:49,612 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] -- executeIrsBrokerCommand: Attempting on storage pool 00000002-0002-0002-0002-000000000390<br> 2014-06-10 11:05:49,616 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.ActivateStorageDomainVDSCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] FINISH, ActivateStorageDomainVDSCommand, log id: 23981a1b<br> 2014-06-10 11:05:49,617 ERROR [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.irsbroker.IRSErrorException: IRSGenericException: IRSErrorException: Failed to ActivateStorageDomainVDS, error = Storage domain does not exist: ('9923a5a1-61e0-4edb-a04d-22c962190c53',), code = 358 (Failed with error StorageDomainDoesNotExist and code 358)<br> 2014-06-10 11:05:49,659 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] START, HSMGetAllTasksInfoVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329), log id: 6229449d<br> 2014-06-10 11:05:49,665 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] FINISH, HSMGetAllTasksInfoVDSCommand, return: [], log id: 6229449d<br> 2014-06-10 11:05:49,666 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] FINISH, SPMGetAllTasksInfoVDSCommand, return: [], log id: 6ff3e3ea<br> 2014-06-10 11:05:49,666 INFO&nbsp; [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-6-thread-11) [69ff8cdd] Discovered no tasks on Storage Pool Default<br> 2014-06-10 11:05:49,667 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] -- executeIrsBrokerCommand: Attempting on storage pool 00000002-0002-0002-0002-000000000390<br> 2014-06-10 11:05:49,678 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ActivateStorageDomainCommand] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Command [id=8d0ac1fe-ed12-48ac-b8a1-13b8a5f17377]: Compensating CHANGED_STATUS_ONLY of org.ovirt.engine.core.common.businessentities.StoragePoolIsoMap; snapshot: EntityStatusSnapshot [id=storagePoolId = 00000002-0002-0002-0002-000000000390, storageId = 9923a5a1-61e0-4edb-a04d-22c962190c53, status=InActive].<br> 2014-06-10 11:05:49,692 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] START, HSMGetAllTasksInfoVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329), log id: 58f9a1ab<br> 2014-06-10 11:05:49,733 INFO&nbsp; [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (org.ovirt.thread.pool-6-thread-20) [69ff8cdd] Correlation ID: 52284e89, Job ID: f4061f81-ea0d-479a-bd89-b67acae8ec1a, Call Stack: null, Custom Event ID: -1, Message: Failed to activate Storage Domain ISO (Data Center Default) by admin<br> 2014-06-10 11:05:49,738 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] FINISH, HSMGetAllTasksInfoVDSCommand, return: [], log id: 58f9a1ab<br> 2014-06-10 11:05:49,744 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.irsbroker.SPMGetAllTasksInfoVDSCommand] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] FINISH, SPMGetAllTasksInfoVDSCommand, return: [], log id: 7eba1136<br> 2014-06-10 11:05:49,745 INFO&nbsp; [org.ovirt.engine.core.bll.AsyncTaskManager] (org.ovirt.thread.pool-6-thread-31) [6808e2ec] Discovered no tasks on Storage Pool Default<br> 2014-06-10 11:07:41,006 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-4) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:07:44,068 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-20) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:07:47,128 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-44) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:07:50,190 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-37) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:07:50,221 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-42) Executing a command: java.util.concurrent.FutureTask , but note that there are 2 tasks in the queue.<br> 2014-06-10 11:07:50,222 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-19) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:09:38,306 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-41) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:09:38,328 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-20) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:09:50,816 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-17) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:09:53,859 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-47) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:09:53,881 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-16) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:10:00,118 INFO&nbsp; [org.ovirt.engine.core.bll.AutoRecoveryManager] (DefaultQuartzScheduler_Worker-31) [17ab55ad] Autorecovering 1 storage domains<br> 2014-06-10 11:10:00,119 INFO&nbsp; [org.ovirt.engine.core.bll.AutoRecoveryManager] (DefaultQuartzScheduler_Worker-31) [17ab55ad] Autorecovering storage domains id: 9923a5a1-61e0-4edb-a04d-22c962190c53<br> 2014-06-10 11:10:00,119 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-31) [336d7eb4] Running command: ConnectDomainToStorageCommand internal: true. Entities affected :&nbsp; ID: 9923a5a1-61e0-4edb-a04d-22c962190c53 Type: Storage<br> 2014-06-10 11:10:00,120 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-31) [336d7eb4] ConnectDomainToStorage. Before Connect all hosts to pool. Time:6/10/14 11:10 AM<br> 2014-06-10 11:10:00,196 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-36) Executing a command: java.util.concurrent.FutureTask , but note that there are 2 tasks in the queue.<br> 2014-06-10 11:10:00,196 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-32) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:10:00,198 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-15) [5f9a3237] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 11:10:00,199 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 11:10:00,200 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectStorageToVdsCommand] (org.ovirt.thread.pool-6-thread-36) [3fc1d201] Running command: ConnectStorageToVdsCommand internal: true. Entities affected :&nbsp; ID: aaa00000-0000-0000-0000-123456789aaa Type: System<br> 2014-06-10 11:10:00,321 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-15) [5f9a3237] START, ConnectStorageServerVDSCommand(HostName = node2.test.me, HostId = 28fdcb5d-7acd-410e-8b65-0b4f483cb575, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 7d344fac<br> 2014-06-10 11:10:00,330 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] START, ConnectStorageServerVDSCommand(HostName = node3.test.me, HostId = 7415506c-cda7-4018-804d-5f6d3beddbfb, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 7c77503a<br> 2014-06-10 11:10:00,334 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-36) [3fc1d201] START, ConnectStorageServerVDSCommand(HostName = node4.test.me, HostId = bb13752e-85cb-4945-822b-48ab2a7b1329, storagePoolId = 00000000-0000-0000-0000-000000000000, storageType = NFS, connectionList = [{ id: f47e9f99-9989-4297-a84f-4f75338eeced, connection: xx.xxx.xxx.xxx:/var/lib/exports/iso, iqn: null, vfsType: null, mountOptions: null, nfsVersion: null, nfsRetrans: null, nfsTimeo: null };]), log id: 449484a0<br> 2014-06-10 11:10:21,875 WARN&nbsp; [org.ovirt.engine.core.utils.threadpool.ThreadPoolUtil] (org.ovirt.thread.pool-6-thread-48) Executing a command: java.util.concurrent.FutureTask , but note that there are 1 tasks in the queue.<br> 2014-06-10 11:11:00,372 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-32) [31a8ddb2] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7c77503a<br> 2014-06-10 11:11:00,382 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-15) [5f9a3237] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 7d344fac<br> 2014-06-10 11:11:00,409 INFO&nbsp; [org.ovirt.engine.core.vdsbroker.vdsbroker.ConnectStorageServerVDSCommand] (org.ovirt.thread.pool-6-thread-36) [3fc1d201] FINISH, ConnectStorageServerVDSCommand, return: {f47e9f99-9989-4297-a84f-4f75338eeced=0}, log id: 449484a0<br> 2014-06-10 11:11:00,410 INFO&nbsp; [org.ovirt.engine.core.bll.storage.ConnectDomainToStorageCommand] (DefaultQuartzScheduler_Worker-31) [336d7eb4] ConnectDomainToStorage. After Connect all hosts to pool. Time:6/10/14 11:11 AM</blockquote> </div> <span>&lt;vdsm.log.tar.gz&gt;</span>_______________________________________________<br>Users mailing list<br><a href="mailto:Users@ovirt.org">Users@ovirt.org</a><br>http://lists.ovirt.org/mailman/listinfo/users<br></blockquote></div><br></body></html> --Apple-Mail=_FD6EAB30-3716-4296-93BD-DD540615AF0F--