[Users] oVirt 3.3 gluster volume active but unable to activate domain

Gianluca Cecchi gianluca.cecchi at gmail.com
Thu Oct 3 21:17:37 UTC 2013 

One engine with f19 and two nodes with f19.
All with ovirt stable repo for f19.
DC defined as GlusterFS
The volume is ok, but I can't activate the domain.
Relevant logs when I clich activate are below

On engine:
2013-10-03 23:05:10,332 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-50) START, GlusterServicesListVDSCommand(HostName =
f18ovn03, HostId = b67bcfd4-f868-49d5-8704-4936ee922249), log id:
5704c54f
2013-10-03 23:05:12,121 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) hostFromVds::selectedVds -
f18ovn01, spmStatus Free, storage pool Gluster
2013-10-03 23:05:12,142 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SpmStatus on vds
80188ccc-83b2-4bc8-9385-8d07f7458a3c: Free
2013-10-03 23:05:12,144 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) starting spm on vds f18ovn01,
storage pool Gluster, prevId 1, LVER 0
2013-10-03 23:05:12,148 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-46) FINISH, GlusterServicesListVDSCommand, return:
[org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 955283ba,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 1ef87397,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at c1b996b6,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 30199726,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 606c4879,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 2b860d38,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at f69fd1f7],
log id: 4a1b4d33
2013-10-03 23:05:12,159 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) START, SpmStartVDSCommand(HostName
= f18ovn01, HostId = 80188ccc-83b2-4bc8-9385-8d07f7458a3c,
storagePoolId = eb679feb-4da2-4fd0-a185-abbe459ffa70, prevId=1,
prevLVER=0, storagePoolFormatType=V3, recoveryMode=Manual,
SCSIFencing=false), log id: 62f11f2d
2013-10-03 23:05:12,169 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling started: taskId =
ab9f2f84-f89b-44e9-b508-a904420635f4
2013-10-03 23:05:12,232 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterServicesListVDSCommand]
(pool-6-thread-50) FINISH, GlusterServicesListVDSCommand, return:
[org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at b624c19b,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 3fcab178,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at e28bd497,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 50ebd507,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 813e865a,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 4c584b19,
org.ovirt.engine.core.common.businessentities.gluster.GlusterServerService at 17720fd8],
log id: 5704c54f
2013-10-03 23:05:12,512 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-6) START,
GlusterVolumesListVDSCommand(HostName = f18ovn01, HostId =
80188ccc-83b2-4bc8-9385-8d07f7458a3c), log id: 39a3f45d
2013-10-03 23:05:12,595 INFO
[org.ovirt.engine.core.vdsbroker.gluster.GlusterVolumesListVDSCommand]
(DefaultQuartzScheduler_Worker-6) FINISH,
GlusterVolumesListVDSCommand, return:
{97873e57-0cc2-4740-ae38-186a8dd94718=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity at a82da199,
d055b38c-2754-4e53-af5c-69cc0b8bf31c=org.ovirt.engine.core.common.businessentities.gluster.GlusterVolumeEntity at ef0c0180},
log id: 39a3f45d
2013-10-03 23:05:14,182 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
(DefaultQuartzScheduler_Worker-83) Failed in HSMGetTaskStatusVDS
method
2013-10-03 23:05:14,184 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetTaskStatusVDSCommand]
(DefaultQuartzScheduler_Worker-83) Error code AcquireHostIdFailure and
error message VDSGenericException: VDSErrorException: Failed to
HSMGetTaskStatusVDS, error = Cannot acquire host id
2013-10-03 23:05:14,186 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling ended: taskId =
ab9f2f84-f89b-44e9-b508-a904420635f4 task status = finished
2013-10-03 23:05:14,188 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) Start SPM Task failed - result:
cleanSuccess, message: VDSGenericException: VDSErrorException: Failed
to HSMGetTaskStatusVDS, error = Cannot acquire host id
2013-10-03 23:05:14,214 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) spmStart polling ended, spm status:
Free
2013-10-03 23:05:14,228 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-83) START,
HSMClearTaskVDSCommand(HostName = f18ovn01, HostId =
80188ccc-83b2-4bc8-9385-8d07f7458a3c,
taskId=ab9f2f84-f89b-44e9-b508-a904420635f4), log id: 6e5df07f
2013-10-03 23:05:14,235 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-83) FINISH, HSMClearTaskVDSCommand, log
id: 6e5df07f
2013-10-03 23:05:14,237 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-83) FINISH, SpmStartVDSCommand, return:
org.ovirt.engine.core.common.businessentities.SpmStatusResult at 5191523,
log id: 62f11f2d
2013-10-03 23:05:14,239 INFO
[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
(DefaultQuartzScheduler_Worker-83) Running command:
SetStoragePoolStatusCommand internal: true. Entities affected :  ID:
eb679feb-4da2-4fd0-a185-abbe459ffa70 Type: StoragePool
2013-10-03 23:05:14,258 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83)
IrsBroker::Failed::GetStoragePoolInfoVDS due to:
IrsSpmStartFailedException: IRSGenericException: IRSErrorException:
SpmStart failed
2013-10-03 23:05:14,307 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) Irs placed on server
80188ccc-83b2-4bc8-9385-8d07f7458a3c failed. Proceed Failover
2013-10-03 23:05:14,341 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) hostFromVds::selectedVds -
f18ovn03, spmStatus Free, storage pool Gluster
2013-10-03 23:05:14,345 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SPM Init: could not find reported
vds or not up - pool:Gluster vds_spm_id: 1
2013-10-03 23:05:14,360 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-83) SPM selection - vds seems as spm
f18ovn01
2013-10-03 23:05:14,375 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStopVDSCommand]
(DefaultQuartzScheduler_Worker-83) START, SpmStopVDSCommand(HostName =
f18ovn01, HostId = 80188ccc-83b2-4bc8-9385-8d07f7458a3c, storagePoolId
= eb679feb-4da2-4fd0-a185-abbe459ffa70), log id: 59e35f64
2013-10-03 23:05:14,384 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand]
(DefaultQuartzScheduler_Worker-83) Command
org.ovirt.engine.core.vdsbroker.vdsbroker.HSMGetAllTasksStatusesVDSCommand
return value


On first vdsm host:
Thread-22567::DEBUG::2013-10-03
23:05:00,996::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll
 requests {}
Thread-22567::DEBUG::2013-10-03
23:05:00,996::task::974::TaskManager.Task::(_decref)
Task=`b00f597e-e73c-49a1-9bb5-14a
5d800c32e`::ref 0 aborting False
4a4a72d1-b1db-4498-aac1-549c986fde24::ERROR::2013-10-03
23:05:01,042::task::850::TaskManager.Task::(_setError)
Task=`4a4a72d1-b1db-4498-aac1-549c986fde24`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/storage/task.py", line 318, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/share/vdsm/storage/sp.py", line 272, in startSpm
    self.masterDomain.acquireHostId(self.id)
  File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId
    self._clusterLock.acquireHostId(hostId, async)
  File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId
    raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id:
('d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291', SanlockException(5, 'Sanlock
lockspace add failure', 'Input/output error'))

On second vdsm host:
Thread-15262::DEBUG::2013-10-03
23:05:23,327::task::1168::TaskManager.Task::(prepare)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::finished: {'taskStatus':
{'code': 0, 'message': 'Task is initializing', 'taskState': 'running',
'taskResult': '', 'taskID': 'f8ada879-f322-4135-9803-b5f8217ac58a'}}
Thread-15262::DEBUG::2013-10-03
23:05:23,327::task::579::TaskManager.Task::(_updateState)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::moving from state
preparing -> state finished
Thread-15262::DEBUG::2013-10-03
23:05:23,327::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-15262::DEBUG::2013-10-03
23:05:23,328::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-15262::DEBUG::2013-10-03
23:05:23,328::task::974::TaskManager.Task::(_decref)
Task=`654b1197-b3a0-4cff-9859-6515c5a908f4`::ref 0 aborting False
f8ada879-f322-4135-9803-b5f8217ac58a::ERROR::2013-10-03
23:05:23,356::task::850::TaskManager.Task::(_setError)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/storage/task.py", line 318, in run
    return self.cmd(*self.argslist, **self.argsdict)
  File "/usr/share/vdsm/storage/sp.py", line 272, in startSpm
    self.masterDomain.acquireHostId(self.id)
  File "/usr/share/vdsm/storage/sd.py", line 458, in acquireHostId
    self._clusterLock.acquireHostId(hostId, async)
  File "/usr/share/vdsm/storage/clusterlock.py", line 189, in acquireHostId
    raise se.AcquireHostIdFailure(self._sdUUID, e)
AcquireHostIdFailure: Cannot acquire host id:
('d0b96d4a-62aa-4e9f-b50e-f7a0cb5be291', SanlockException(5, 'Sanlock
lockspace add failure', 'Input/output error'))
f8ada879-f322-4135-9803-b5f8217ac58a::DEBUG::2013-10-03
23:05:23,358::task::869::TaskManager.Task::(_run)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::Task._run:
f8ada879-f322-4135-9803-b5f8217ac58a () {} failed - stopping task
f8ada879-f322-4135-9803-b5f8217ac58a::DEBUG::2013-10-03
23:05:23,358::task::1194::TaskManager.Task::(stop)
Task=`f8ada879-f322-4135-9803-b5f8217ac58a`::stopping in state running
(force False)


ANy hint?

Thanks,
Gianluca

More information about the Users mailing list