<html>
<head>
<meta http-equiv="content-type" content="text/html; charset=ISO-8859-1">
</head>
<body bgcolor="#FFFFFF" text="#000000">
Hello everybody,<br>
I've been experimenting a bit with Fedora 19 + vdsm and I'm getting
this funny <i>VolumeGroupReplaceTagError</i>. I've got a 3.2 engine
running with two hosts, a Fed18 and a Fed19, both sporting
vdsm-4.10.3-17. I can run VMs on both hostss but I can't migrate
them and, worst of them all, the engine can't elect the Fe19 host as
SPM - it just keeps trying and trying to no avail. What's even
weirder is that the Fed19's vdsm keeps complaining about not being
able to find the storage, even when VMs are up and running on the
very same host. Both hosts are accessing the same LUN via fibre
channel. <br>
<br>
here is an excerpt from the offending vdsm running a VM:<br>
<br>
<tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,078::misc::84::Storage.Misc.excCmd::(<lambda>)
'/usr/bin/sudo -n /sbin/lvm vgs --config " devices {
preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1
write_cache_state=0 disable_after_error_count=3 filter = [
\\"a%360060160f4d03100dc456812fdb3e211%\\", \\"r%.*%\\" ] }
global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } "
--noheadings --units b --nosuffix --separator | -o
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free
a646d974-19be-4a8d-bf68-a3974d46a823' (cwd None)</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>)
SUCCESS: <err> = ''; <rc> = 0</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,117::lvm::397::OperationMutex::(_reloadvgs) Operation
'lvm reload operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,117::persistentDict::234::Storage.PersistentDict::(refresh)
read lines
(VGTagMetadataRW)=[u'PV0=pv:mpathb,uuid:TMIy2w-1GR2-DW93-SETn-AhJG-yXfA-mHYwWW,pestart:0,pecount:4093,mapoffset:0',
'VERSION=3', 'LOGBLKSIZE=512', 'DESCRIPTION=provisioning1',
'LEASERETRIES=3', 'LOCKRENEWALINTERVALSEC=5', 'LOCKPOLICY=',
'PHYBLKSIZE=512', 'SDUUID=a646d974-19be-4a8d-bf68-a3974d46a823',
'CLASS=Data', 'TYPE=FCP',
'VGUUID=bqt7AY-kDVm-rZnW-IMI6-83Zy-5Go2-HvNY6Y',
'IOOPTIMEOUTSEC=10', 'LEASETIMESEC=60', 'MASTER_VERSION=1',
'POOL_UUID=c923d5bb-ea08-44ea-937d-10eea4485ae2', 'ROLE=Master',
'POOL_DESCRIPTION=AreaProvisioning',
u'POOL_DOMAINS=a646d974-19be-4a8d-bf68-a3974d46a823:Active,53b27dc5-fa49-4257-962d-b475e160d7b3:Active',
'POOL_SPM_LVER=18', 'POOL_SPM_ID=-1',
'_SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c']</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
Starting transaction</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
Flushing changes</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,119::persistentDict::299::Storage.PersistentDict::(flush)
about to write lines (VGTagMetadataRW)=['CLASS=Data',
'DESCRIPTION=provisioning1', 'IOOPTIMEOUTSEC=10',
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'LOGBLKSIZE=512', 'MASTER_VERSION=1',
'PHYBLKSIZE=512', 'POOL_DESCRIPTION=AreaProvisioning',
u'POOL_DOMAINS=a646d974-19be-4a8d-bf68-a3974d46a823:Active,53b27dc5-fa49-4257-962d-b475e160d7b3:Active',
'POOL_SPM_ID=1', 'POOL_SPM_LVER=19',
'POOL_UUID=c923d5bb-ea08-44ea-937d-10eea4485ae2',
u'PV0=pv:mpathb,uuid:TMIy2w-1GR2-DW93-SETn-AhJG-yXfA-mHYwWW,pestart:0,pecount:4093,mapoffset:0',
'ROLE=Master', 'SDUUID=a646d974-19be-4a8d-bf68-a3974d46a823',
'TYPE=FCP', 'VERSION=3',
'VGUUID=bqt7AY-kDVm-rZnW-IMI6-83Zy-5Go2-HvNY6Y',
'_SHA_CKSUM=79a6a0705dc0011d7f44f24b5c639f5d8baae074']</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,119::lvm::483::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,119::lvm::485::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,120::lvm::493::OperationMutex::(_invalidatelvs) Operation
'lvm invalidate operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,120::lvm::505::OperationMutex::(_invalidatelvs) Operation
'lvm invalidate operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,120::lvm::368::OperationMutex::(_reloadvgs) Operation
'lvm reload operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,121::misc::84::Storage.Misc.excCmd::(<lambda>)
'/usr/bin/sudo -n /sbin/lvm vgs --config " devices {
preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1
write_cache_state=0 disable_after_error_count=3 filter = [
\\"a%360060160f4d03100dc456812fdb3e211%\\", \\"r%.*%\\" ] }
global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } "
--noheadings --units b --nosuffix --separator | -o
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free
a646d974-19be-4a8d-bf68-a3974d46a823' (cwd None)</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>)
SUCCESS: <err> = ''; <rc> = 0</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,159::lvm::397::OperationMutex::(_reloadvgs) Operation
'lvm reload operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,160::blockSD::300::storage.Metadata.VGTagMetadataRW::(writelines)
Updating metadata adding=MDT_POOL_SPM_ID=1,
MDT__SHA_CKSUM=79a6a0705dc0011d7f44f24b5c639f5d8baae074,
MDT_POOL_SPM_LVER=19 removing=MDT_POOL_SPM_ID=-1,
MDT__SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c,
MDT_POOL_SPM_LVER=18</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,161::misc::84::Storage.Misc.excCmd::(<lambda>)
'/usr/bin/sudo -n /sbin/lvm vgchange --config " devices {
preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1
write_cache_state=0 disable_after_error_count=3 filter = [
\\"a%360060160f4d03100dc456812fdb3e211%\\", \\"r%.*%\\" ] }
global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } "
--deltag MDT_POOL_SPM_LVER=18 --deltag MDT_POOL_SPM_ID=-1 --deltag
MDT__SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c --addtag
MDT_POOL_SPM_ID=1 --addtag
MDT__SHA_CKSUM=79a6a0705dc0011d7f44f24b5c639f5d8baae074 --addtag
MDT_POOL_SPM_LVER=19 a646d974-19be-4a8d-bf68-a3974d46a823' (cwd
None)</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,200::misc::84::Storage.Misc.excCmd::(<lambda>)
FAILED: <err> = '
/dev/mapper/360060160f4d03100dc456812fdb3e211: lseek
18446744073575333888 failed: Invalid argument\n'; <rc> = 5</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,204::lvm::483::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,204::lvm::485::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
Error in transaction, rolling back changes</tt><tt><br>
</tt><tt>Traceback (most recent call last):</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
174, in transaction</tt><tt><br>
</tt><tt> self.flush(self._metadata)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
300, in flush</tt><tt><br>
</tt><tt> self._metaRW.writelines(lines)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/blockSD.py", line 301, in
writelines</tt><tt><br>
</tt><tt> lvm.changeVGTags(self._vgName, delTags=toRemove,
addTags=toAdd)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/lvm.py", line 1219, in
changeVGTags</tt><tt><br>
</tt><tt> (vgName, ", ".join(delTags), ", ".join(addTags),
err[-1]))</tt><tt><br>
</tt><tt>VolumeGroupReplaceTagError: Replace Volume Group tag error:
('vg:a646d974-19be-4a8d-bf68-a3974d46a823
del:MDT_POOL_SPM_LVER=18, MDT_POOL_SPM_ID=-1,
MDT__SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c
add:MDT_POOL_SPM_ID=1,
MDT__SHA_CKSUM=79a6a0705dc0011d7f44f24b5c639f5d8baae074,
MDT_POOL_SPM_LVER=19 (
/dev/mapper/360060160f4d03100dc456812fdb3e211: lseek
18446744073575333888 failed: Invalid argument)',)</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,206::persistentDict::299::Storage.PersistentDict::(flush)
about to write lines (VGTagMetadataRW)=['CLASS=Data',
'DESCRIPTION=provisioning1', 'IOOPTIMEOUTSEC=10',
'LEASERETRIES=3', 'LEASETIMESEC=60', 'LOCKPOLICY=',
'LOCKRENEWALINTERVALSEC=5', 'LOGBLKSIZE=512', 'MASTER_VERSION=1',
'PHYBLKSIZE=512', 'POOL_DESCRIPTION=AreaProvisioning',
u'POOL_DOMAINS=a646d974-19be-4a8d-bf68-a3974d46a823:Active,53b27dc5-fa49-4257-962d-b475e160d7b3:Active',
'POOL_SPM_ID=-1', 'POOL_SPM_LVER=18',
'POOL_UUID=c923d5bb-ea08-44ea-937d-10eea4485ae2',
u'PV0=pv:mpathb,uuid:TMIy2w-1GR2-DW93-SETn-AhJG-yXfA-mHYwWW,pestart:0,pecount:4093,mapoffset:0',
'ROLE=Master', 'SDUUID=a646d974-19be-4a8d-bf68-a3974d46a823',
'TYPE=FCP', 'VERSION=3',
'VGUUID=bqt7AY-kDVm-rZnW-IMI6-83Zy-5Go2-HvNY6Y',
'_SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c']</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,206::lvm::483::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,206::lvm::485::OperationMutex::(_invalidatevgs) Operation
'lvm invalidate operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,207::lvm::493::OperationMutex::(_invalidatelvs) Operation
'lvm invalidate operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,207::lvm::505::OperationMutex::(_invalidatelvs) Operation
'lvm invalidate operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,207::lvm::368::OperationMutex::(_reloadvgs) Operation
'lvm reload operation' got the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,208::misc::84::Storage.Misc.excCmd::(<lambda>)
'/usr/bin/sudo -n /sbin/lvm vgs --config " devices {
preferred_names = [\\"^/dev/mapper/\\"] ignore_suspended_devices=1
write_cache_state=0 disable_after_error_count=3 filter = [
\\"a%360060160f4d03100dc456812fdb3e211%\\", \\"r%.*%\\" ] }
global { locking_type=1 prioritise_write_locks=1
wait_for_locks=1 } backup { retain_min = 50 retain_days = 0 } "
--noheadings --units b --nosuffix --separator | -o
uuid,name,attr,size,free,extent_size,extent_count,free_count,tags,vg_mda_size,vg_mda_free
a646d974-19be-4a8d-bf68-a3974d46a823' (cwd None)</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>)
SUCCESS: <err> = ''; <rc> = 0</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,246::lvm::397::OperationMutex::(_reloadvgs) Operation
'lvm reload operation' released the operation mutex</tt><tt><br>
</tt><tt>9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected
error</tt><tt><br>
</tt><tt>Traceback (most recent call last):</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/sp.py", line 268, in
startSpm</tt><tt><br>
</tt><tt> PMDK_SPM_ID: self.id}, __securityOverride=True)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/securable.py", line 68, in
wrapper</tt><tt><br>
</tt><tt> return f(self, *args, **kwargs)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/sp.py", line 1478, in
setMetaParams</tt><tt><br>
</tt><tt> self._metadata.update(params)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
121, in update</tt><tt><br>
</tt><tt> self._dict.update(metadata)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
214, in update</tt><tt><br>
</tt><tt> self._metadata.update(metadata)</tt><tt><br>
</tt><tt> File "/usr/lib64/python2.7/contextlib.py", line 24, in
__exit__</tt><tt><br>
</tt><tt> self.gen.next()</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
174, in transaction</tt><tt><br>
</tt><tt> self.flush(self._metadata)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/persistentDict.py", line
300, in flush</tt><tt><br>
</tt><tt> self._metaRW.writelines(lines)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/blockSD.py", line 301, in
writelines</tt><tt><br>
</tt><tt> lvm.changeVGTags(self._vgName, delTags=toRemove,
addTags=toAdd)</tt><tt><br>
</tt><tt> File "/usr/share/vdsm/storage/lvm.py", line 1219, in
changeVGTags</tt><tt><br>
</tt><tt> (vgName, ", ".join(delTags), ", ".join(addTags),
err[-1]))</tt><tt><br>
</tt><tt>VolumeGroupReplaceTagError: Replace Volume Group tag error:
('vg:a646d974-19be-4a8d-bf68-a3974d46a823
del:MDT_POOL_SPM_LVER=18, MDT_POOL_SPM_ID=-1,
MDT__SHA_CKSUM=7d5585b7b7adeabd4cb193ea6f3e5af06bd8f64c
add:MDT_POOL_SPM_ID=1,
MDT__SHA_CKSUM=79a6a0705dc0011d7f44f24b5c639f5d8baae074,
MDT_POOL_SPM_LVER=19 (
/dev/mapper/360060160f4d03100dc456812fdb3e211: lseek
18446744073575333888 failed: Invalid argument)',)</tt><tt><br>
</tt><br>
meanwhile, on the engine side of the thing (same behaviour at a
different time of the day):<br>
<br>
<tt>2013-07-18 15:19:18,736 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-10) [1cdd7d6f] START,
HSMClearTaskVDSCommand(HostName = heidi, HostId =
7c0f1d65-750e-458c-95ac-90846d4755bf,
taskId=4879a4ab-41fc-4991-a93b-7407a21701e0), log id: bff1ad1</tt><tt><br>
</tt><tt>2013-07-18 15:19:18,745 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
HSMClearTaskVDSCommand, log id: bff1ad1</tt><tt><br>
</tt><tt>2013-07-18 15:19:18,746 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
SpmStartVDSCommand, return:
org.ovirt.engine.core.common.businessentities.SpmStatusResult@1939957e,
log id: 72518013</tt><tt><br>
</tt><tt>2013-07-18 15:19:18,749 INFO
[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
(DefaultQuartzScheduler_Worker-10) [13859022] Running command:
SetStoragePoolStatusCommand internal: true. Entities affected :
ID: c923d5bb-ea08-44ea-937d-10eea4485ae2 Type: StoragePool</tt><tt><br>
</tt><tt>2013-07-18 15:19:18,783 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(DefaultQuartzScheduler_Worker-10) [13859022] No string for
SYSTEM_CHANGE_STORAGE_POOL_STATUS_PROBLEMATIC type. Use default
Log</tt><tt><br>
</tt><tt>2013-07-18 15:19:18,790 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-10) [13859022]
IrsBroker::Failed::GetStoragePoolInfoVDS due to:
IrsSpmStartFailedException: IRSGenericException:
IRSErrorException: SpmStart failed</tt><tt><br>
</tt><tt>2013-07-18 15:19:28,893 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a]
hostFromVds::selectedVds - heidi, spmStatus Free, storage pool
AreaProvisioning</tt><tt><br>
</tt><tt>2013-07-18 15:19:28,899 INFO
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] starting spm on vds
heidi, storage pool AreaProvisioning, prevId -1, LVER 18</tt><tt><br>
</tt><tt>2013-07-18 15:19:28,925 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] START,
SpmStartVDSCommand(HostName = heidi, HostId =
7c0f1d65-750e-458c-95ac-90846d4755bf, storagePoolId =
c923d5bb-ea08-44ea-937d-10eea4485ae2, prevId=-1, prevLVER=18,
storagePoolFormatType=V3, recoveryMode=Manual, SCSIFencing=false),
log id: 1101aacc</tt><tt><br>
</tt><tt>2013-07-18 15:19:28,942 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] spmStart polling
started: taskId = 03d8ee8f-cf3d-42c5-be4a-a9136f5e9fa1</tt><tt><br>
</tt><tt>2013-07-18 15:19:29,974 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
(DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in
HSMGetTaskStatusVDS method</tt><tt><br>
</tt><tt>2013-07-18 15:19:29,976 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
(DefaultQuartzScheduler_Worker-5) [19567f5a] Error code
VolumeGroupReplaceTagError and error message VDSGenericException:
VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Replace
Volume Group tag error</tt><tt><br>
</tt><tt>2013-07-18 15:19:29,977 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] spmStart polling
ended: taskId = 03d8ee8f-cf3d-42c5-be4a-a9136f5e9fa1 task status =
finished</tt><tt><br>
</tt><tt>2013-07-18 15:19:29,978 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] Start SPM Task failed
- result: cleanSuccess, message: VDSGenericException:
VDSErrorException: Failed to HSMGetTaskStatusVDS, error = Replace
Volume Group tag error</tt><tt><br>
</tt><tt>2013-07-18 15:19:29,985 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] spmStart polling
ended, spm status: Free</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,010 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] START,
HSMClearTaskVDSCommand(HostName = heidi, HostId =
7c0f1d65-750e-458c-95ac-90846d4755bf,
taskId=03d8ee8f-cf3d-42c5-be4a-a9136f5e9fa1), log id: 115a9661</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,018 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH,
HSMClearTaskVDSCommand, log id: 115a9661</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,019 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.SpmStartVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH,
SpmStartVDSCommand, return:
org.ovirt.engine.core.common.businessentities.SpmStatusResult@5246c32d,
log id: 1101aacc</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,022 INFO
[org.ovirt.engine.core.bll.storage.SetStoragePoolStatusCommand]
(DefaultQuartzScheduler_Worker-5) [23b7e98e] Running command:
SetStoragePoolStatusCommand internal: true. Entities affected :
ID: c923d5bb-ea08-44ea-937d-10eea4485ae2 Type: StoragePool</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,054 INFO
[org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector]
(DefaultQuartzScheduler_Worker-5) [23b7e98e] No string for
SYSTEM_CHANGE_STORAGE_POOL_STATUS_PROBLEMATIC type. Use default
Log</tt><tt><br>
</tt><tt>2013-07-18 15:19:30,061 ERROR
[org.ovirt.engine.core.vdsbroker.irsbroker.IrsBrokerCommand]
(DefaultQuartzScheduler_Worker-5) [23b7e98e]
IrsBroker::Failed::GetStoragePoolInfoVDS due to:
IrsSpmStartFailedException: IRSGenericException:
IRSErrorException: SpmStart failed</tt><tt><br>
</tt><br>
the whole vdsm log is attached. Got any clues?<br>
<br>
Thanks,<br>
Daniele Pavia<br>
<br>
Engineering I.I. <br>
R&D Labs<br>
<br>
</body>
</html>