4:27 p.m.
Hello everybody,
I've been experimenting a bit with Fedora 19 + vdsm and I'm getting this
funny /VolumeGroupReplaceTagError/. 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.
here is an excerpt from the offending vdsm running a VM:
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
''; <rc> = 0
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
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']
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
Starting transaction
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
Flushing changes
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']
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
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
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
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
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
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
''; <rc> = 0
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
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
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)
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
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
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
9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
Error in transaction, rolling back changes
Traceback (most recent call last):
File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
self.flush(self._metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
self._metaRW.writelines(lines)
File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
(vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
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)',)
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']
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
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
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
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
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
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
''; <rc> = 0
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
9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/sp.py", line 268, in startSpm
PMDK_SPM_ID: self.id}, __securityOverride=True)
File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
return f(self, *args, **kwargs)
File "/usr/share/vdsm/storage/sp.py", line 1478, in setMetaParams
self._metadata.update(params)
File "/usr/share/vdsm/storage/persistentDict.py", line 121, in update
self._dict.update(metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 214, in update
self._metadata.update(metadata)
File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
self.gen.next()
File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
self.flush(self._metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
self._metaRW.writelines(lines)
File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
(vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
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)',)
meanwhile, on the engine side of the thing (same behaviour at a
different time of the day):
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
2013-07-18 15:19:18,745 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
HSMClearTaskVDSCommand, log id: bff1ad1
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
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
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
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
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
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
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
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
2013-07-18 15:19:29,974 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
(DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in
HSMGetTaskStatusVDS method
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
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
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
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
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
2013-07-18 15:19:30,018 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH,
HSMClearTaskVDSCommand, log id: 115a9661
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
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
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
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
the whole vdsm log is attached. Got any clues?
Thanks,
Daniele Pavia
Engineering I.I.
R&D Labs
2:03 p.m.
Hi Daniele,
Your lvm version seems wrong:
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 ... --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'
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
I'm guessing this is the Fedora 18?
Can you attach the vdsm.log for the Fedora 19 as well?
----- Original Message -----
Hello everybody,
I've been experimenting a bit with Fedora 19 + vdsm and I'm getting this
funny VolumeGroupReplaceTagError . 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.
here is an excerpt from the offending vdsm running a VM:
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
<rc> = 0
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
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']
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
Starting transaction
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
Flushing changes
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']
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
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
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
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
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
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
<rc> = 0
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
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
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)
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
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
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
9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
Error in transaction, rolling back changes
Traceback (most recent call last):
File "/usr/share/vdsm/storage/persistentDict.py", line 174, in transaction
self.flush(self._metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
self._metaRW.writelines(lines)
File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
(vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
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)',)
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']
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
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
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
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
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
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)
9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
<rc> = 0
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
9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected error
Traceback (most recent call last):
File "/usr/share/vdsm/storage/sp.py", line 268, in startSpm
PMDK_SPM_ID: self.id}, __securityOverride=True)
File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
return f(self, *args, **kwargs)
File "/usr/share/vdsm/storage/sp.py", line 1478, in setMetaParams
self._metadata.update(params)
File "/usr/share/vdsm/storage/persistentDict.py", line 121, in update
self._dict.update(metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 214, in update
self._metadata.update(metadata)
File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
self.gen.next()
File "/usr/share/vdsm/storage/persistentDict.py", line 174, in transaction
self.flush(self._metadata)
File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
self._metaRW.writelines(lines)
File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
(vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
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)',)
meanwhile, on the engine side of the thing (same behaviour at a different
time of the day):
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
2013-07-18 15:19:18,745 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
HSMClearTaskVDSCommand, log id: bff1ad1
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
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
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
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
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
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
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
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
2013-07-18 15:19:29,974 ERROR
[org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
(DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in HSMGetTaskStatusVDS
method
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
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
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
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
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
2013-07-18 15:19:30,018 INFO
[org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
(DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH, HSMClearTaskVDSCommand,
log id: 115a9661
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
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
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
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
the whole vdsm log is attached. Got any clues?
Thanks,
Daniele Pavia
Engineering I.I.
R&D Labs
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
12:29 p.m.
Hi Ayal,
thanks for your reply! Well, I just realized that I didn't give the
whole picture: I've got a Fed18 3.2 engine and a Fed18 host running as
SPM. I added a second Fed19 host whose log you're looking at right now.
So, yes - that's the Fed19 host trying to become SPM when the Fed18 host
goes in maintenance. As far as I understand, the error message you've
found makes me think there's something missing when the Fed19 host tries
to vgchange the tags on the storage domain's volume group:
# vgs
VG #PV #LV #SN Attr VSize VFree
a646d974-19be-4a8d-bf68-a3974d46a823 1 17 0 wz--n- 511.62g 473.12g
fedora 1 3 0 wz--n- 67.50g 0
Now, if I manually run the same command on the Fed19 while it's trying
to be elected as SPM:
/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
Parse error at byte 31 (line 1): expected a value
Failed to set overridden configuration entries.
Run `vgchange --help' for more information.
Does this ring a bell?
Cheers,
Daniele
On 07/21/2013 01:03 PM, Ayal Baron wrote:
Hi Daniele,
Your lvm version seems wrong:
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 ... --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'
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
I'm guessing this is the Fedora 18?
Can you attach the vdsm.log for the Fedora 19 as well?
----- Original Message -----
> Hello everybody,
> I've been experimenting a bit with Fedora 19 + vdsm and I'm getting this
> funny VolumeGroupReplaceTagError . 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.
>
> here is an excerpt from the offending vdsm running a VM:
>
> 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)
> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
> 11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
> <rc> = 0
> 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
> 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']
> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
> 11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
> Starting transaction
> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
> 11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
> Flushing changes
> 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']
> 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
> 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
> 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
> 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
> 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
> 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)
> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
> 11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
> <rc> = 0
> 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
> 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
> 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)
> 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
> 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
> 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
> 9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
> 11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
> Error in transaction, rolling back changes
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in transaction
> self.flush(self._metadata)
> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
> self._metaRW.writelines(lines)
> File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
> (vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
> 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)',)
> 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']
> 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
> 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
> 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
> 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
> 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
> 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)
> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
> 11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS: <err> =
'';
> <rc> = 0
> 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
> 9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
> 11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected error
> Traceback (most recent call last):
> File "/usr/share/vdsm/storage/sp.py", line 268, in startSpm
> PMDK_SPM_ID: self.id}, __securityOverride=True)
> File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
> return f(self, *args, **kwargs)
> File "/usr/share/vdsm/storage/sp.py", line 1478, in setMetaParams
> self._metadata.update(params)
> File "/usr/share/vdsm/storage/persistentDict.py", line 121, in update
> self._dict.update(metadata)
> File "/usr/share/vdsm/storage/persistentDict.py", line 214, in update
> self._metadata.update(metadata)
> File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
> self.gen.next()
> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in transaction
> self.flush(self._metadata)
> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
> self._metaRW.writelines(lines)
> File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
> (vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
> 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)',)
>
> meanwhile, on the engine side of the thing (same behaviour at a different
> time of the day):
>
> 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
> 2013-07-18 15:19:18,745 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
> (DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
> HSMClearTaskVDSCommand, log id: bff1ad1
> 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
> 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
> 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
> 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
> 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
> 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
> 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
> 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
> 2013-07-18 15:19:29,974 ERROR
> [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
> (DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in HSMGetTaskStatusVDS
> method
> 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
> 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
> 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
> 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
> 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
> 2013-07-18 15:19:30,018 INFO
> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
> (DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH, HSMClearTaskVDSCommand,
> log id: 115a9661
> 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
> 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
> 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
> 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
>
> the whole vdsm log is attached. Got any clues?
>
> Thanks,
> Daniele Pavia
>
> Engineering I.I.
> R&D Labs
>
>
> _______________________________________________
> Users mailing list
> Users(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
>
_______________________________________________
Users mailing list
Users(a)ovirt.org
http://lists.ovirt.org/mailman/listinfo/users
1:42 p.m.
----- Original Message -----
Hi Ayal,
thanks for your reply! Well, I just realized that I didn't give the
whole picture: I've got a Fed18 3.2 engine and a Fed18 host running as
SPM. I added a second Fed19 host whose log you're looking at right now.
So, yes - that's the Fed19 host trying to become SPM when the Fed18 host
goes in maintenance. As far as I understand, the error message you've
found makes me think there's something missing when the Fed19 host tries
to vgchange the tags on the storage domain's volume group:
# vgs
VG #PV #LV #SN Attr VSize VFree
a646d974-19be-4a8d-bf68-a3974d46a823 1 17 0 wz--n- 511.62g 473.12g
fedora 1 3 0 wz--n- 67.50g 0
Now, if I manually run the same command on the Fed19 while it's trying
to be elected as SPM:
/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
Parse error at byte 31 (line 1): expected a value
Failed to set overridden configuration entries.
Run `vgchange --help' for more information.
Does this ring a bell?
This looks like shell issues (you cannot simply copy the command from the log and run it
as it goes through some shell processing when run from python.
What version of lvm do you have on this host?
Cheers,
Daniele
On 07/21/2013 01:03 PM, Ayal Baron wrote:
> Hi Daniele,
>
> Your lvm version seems wrong:
>
> 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 ... --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'
>
> 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
>
> I'm guessing this is the Fedora 18?
> Can you attach the vdsm.log for the Fedora 19 as well?
>
> ----- Original Message -----
>> Hello everybody,
>> I've been experimenting a bit with Fedora 19 + vdsm and I'm getting
this
>> funny VolumeGroupReplaceTagError . 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.
>>
>> here is an excerpt from the offending vdsm running a VM:
>>
>> 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)
>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>> 11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>> '';
>> <rc> = 0
>> 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
>> 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']
>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>> 11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
>> Starting transaction
>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>> 11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
>> Flushing changes
>> 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']
>> 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
>> 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
>> 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
>> 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
>> 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
>> 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)
>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>> 11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>> '';
>> <rc> = 0
>> 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
>> 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
>> 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)
>> 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
>> 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
>> 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
>> 9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
>> 11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
>> Error in transaction, rolling back changes
>> Traceback (most recent call last):
>> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
>> self.flush(self._metadata)
>> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
>> self._metaRW.writelines(lines)
>> File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
>> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
>> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
>> (vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
>> 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)',)
>> 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']
>> 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
>> 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
>> 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
>> 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
>> 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
>> 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)
>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>> 11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>> '';
>> <rc> = 0
>> 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
>> 9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
>> 11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected error
>> Traceback (most recent call last):
>> File "/usr/share/vdsm/storage/sp.py", line 268, in startSpm
>> PMDK_SPM_ID: self.id}, __securityOverride=True)
>> File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
>> return f(self, *args, **kwargs)
>> File "/usr/share/vdsm/storage/sp.py", line 1478, in setMetaParams
>> self._metadata.update(params)
>> File "/usr/share/vdsm/storage/persistentDict.py", line 121, in update
>> self._dict.update(metadata)
>> File "/usr/share/vdsm/storage/persistentDict.py", line 214, in update
>> self._metadata.update(metadata)
>> File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
>> self.gen.next()
>> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
>> self.flush(self._metadata)
>> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in flush
>> self._metaRW.writelines(lines)
>> File "/usr/share/vdsm/storage/blockSD.py", line 301, in writelines
>> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
>> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
>> (vgName, ", ".join(delTags), ", ".join(addTags), err[-1]))
>> 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)',)
>>
>> meanwhile, on the engine side of the thing (same behaviour at a different
>> time of the day):
>>
>> 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
>> 2013-07-18 15:19:18,745 INFO
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>> (DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
>> HSMClearTaskVDSCommand, log id: bff1ad1
>> 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
>> 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
>> 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
>> 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
>> 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
>> 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
>> 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
>> 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
>> 2013-07-18 15:19:29,974 ERROR
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
>> (DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in HSMGetTaskStatusVDS
>> method
>> 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
>> 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
>> 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
>> 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
>> 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
>> 2013-07-18 15:19:30,018 INFO
>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>> (DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH,
>> HSMClearTaskVDSCommand,
>> log id: 115a9661
>> 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
>> 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
>> 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
>> 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
>>
>> the whole vdsm log is attached. Got any clues?
>>
>> Thanks,
>> Daniele Pavia
>>
>> Engineering I.I.
>> R&D Labs
>>
>>
>> _______________________________________________
>> Users mailing list
>> Users(a)ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/users
>>
> _______________________________________________
> Users mailing list
> Users(a)ovirt.org
> http://lists.ovirt.org/mailman/listinfo/users
1:53 p.m.
Hi Ayal,
my bad, noob mistake. Fed19 host is running lvm2-2.02.98-9.fc19.x86_64,
the Fed18 machines are running lvm2-2.02.98-4.fc18.x86_64, they're all
coming from the stable repos. Think this gap in versions could be the cause?
Cheers,
Daniele
On 07/22/2013 12:42 PM, Ayal Baron wrote:
----- Original Message -----
> Hi Ayal,
> thanks for your reply! Well, I just realized that I didn't give the
> whole picture: I've got a Fed18 3.2 engine and a Fed18 host running as
> SPM. I added a second Fed19 host whose log you're looking at right now.
> So, yes - that's the Fed19 host trying to become SPM when the Fed18 host
> goes in maintenance. As far as I understand, the error message you've
> found makes me think there's something missing when the Fed19 host tries
> to vgchange the tags on the storage domain's volume group:
>
> # vgs
> VG #PV #LV #SN Attr VSize VFree
> a646d974-19be-4a8d-bf68-a3974d46a823 1 17 0 wz--n- 511.62g 473.12g
> fedora 1 3 0 wz--n- 67.50g 0
>
> Now, if I manually run the same command on the Fed19 while it's trying
> to be elected as SPM:
>
> /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
>
> Parse error at byte 31 (line 1): expected a value
> Failed to set overridden configuration entries.
> Run `vgchange --help' for more information.
>
> Does this ring a bell?
This looks like shell issues (you cannot simply copy the command from the log and run it
as it goes through some shell processing when run from python.
What version of lvm do you have on this host?
> Cheers,
> Daniele
>
> On 07/21/2013 01:03 PM, Ayal Baron wrote:
>> Hi Daniele,
>>
>> Your lvm version seems wrong:
>>
>> 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 ... --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'
>>
>> 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
>>
>> I'm guessing this is the Fedora 18?
>> Can you attach the vdsm.log for the Fedora 19 as well?
>>
>> ----- Original Message -----
>>> Hello everybody,
>>> I've been experimenting a bit with Fedora 19 + vdsm and I'm getting
this
>>> funny VolumeGroupReplaceTagError . 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.
>>>
>>> here is an excerpt from the offending vdsm running a VM:
>>>
>>> 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)
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>>> 11:01:07,115::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>>> '';
>>> <rc> = 0
>>> 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
>>> 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']
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>>> 11:01:07,118::persistentDict::167::Storage.PersistentDict::(transaction)
>>> Starting transaction
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>>> 11:01:07,118::persistentDict::173::Storage.PersistentDict::(transaction)
>>> Flushing changes
>>> 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']
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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)
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>>> 11:01:07,157::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>>> '';
>>> <rc> = 0
>>> 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
>>> 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
>>> 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)
>>> 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
>>> 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
>>> 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
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::WARNING::2013-07-18
>>> 11:01:07,205::persistentDict::178::Storage.PersistentDict::(transaction)
>>> Error in transaction, rolling back changes
>>> Traceback (most recent call last):
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
>>> self.flush(self._metadata)
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in
flush
>>> self._metaRW.writelines(lines)
>>> File "/usr/share/vdsm/storage/blockSD.py", line 301, in
writelines
>>> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
>>> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
>>> (vgName, ", ".join(delTags), ", ".join(addTags),
err[-1]))
>>> 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)',)
>>> 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']
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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)
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::DEBUG::2013-07-18
>>> 11:01:07,244::misc::84::Storage.Misc.excCmd::(<lambda>) SUCCESS:
<err> =
>>> '';
>>> <rc> = 0
>>> 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
>>> 9b238eef-380f-4fd4-aca1-465f675b7656::ERROR::2013-07-18
>>> 11:01:07,247::sp::314::Storage.StoragePool::(startSpm) Unexpected error
>>> Traceback (most recent call last):
>>> File "/usr/share/vdsm/storage/sp.py", line 268, in startSpm
>>> PMDK_SPM_ID: self.id}, __securityOverride=True)
>>> File "/usr/share/vdsm/storage/securable.py", line 68, in wrapper
>>> return f(self, *args, **kwargs)
>>> File "/usr/share/vdsm/storage/sp.py", line 1478, in setMetaParams
>>> self._metadata.update(params)
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 121, in
update
>>> self._dict.update(metadata)
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 214, in
update
>>> self._metadata.update(metadata)
>>> File "/usr/lib64/python2.7/contextlib.py", line 24, in __exit__
>>> self.gen.next()
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 174, in
transaction
>>> self.flush(self._metadata)
>>> File "/usr/share/vdsm/storage/persistentDict.py", line 300, in
flush
>>> self._metaRW.writelines(lines)
>>> File "/usr/share/vdsm/storage/blockSD.py", line 301, in
writelines
>>> lvm.changeVGTags(self._vgName, delTags=toRemove, addTags=toAdd)
>>> File "/usr/share/vdsm/storage/lvm.py", line 1219, in changeVGTags
>>> (vgName, ", ".join(delTags), ", ".join(addTags),
err[-1]))
>>> 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)',)
>>>
>>> meanwhile, on the engine side of the thing (same behaviour at a different
>>> time of the day):
>>>
>>> 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
>>> 2013-07-18 15:19:18,745 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>>> (DefaultQuartzScheduler_Worker-10) [1cdd7d6f] FINISH,
>>> HSMClearTaskVDSCommand, log id: bff1ad1
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 2013-07-18 15:19:29,974 ERROR
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.BrokerCommandBase]
>>> (DefaultQuartzScheduler_Worker-5) [19567f5a] Failed in HSMGetTaskStatusVDS
>>> method
>>> 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
>>> 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
>>> 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
>>> 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
>>> 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
>>> 2013-07-18 15:19:30,018 INFO
>>> [org.ovirt.engine.core.vdsbroker.vdsbroker.HSMClearTaskVDSCommand]
>>> (DefaultQuartzScheduler_Worker-5) [19567f5a] FINISH,
>>> HSMClearTaskVDSCommand,
>>> log id: 115a9661
>>> 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
>>> 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
>>> 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
>>> 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
>>>
>>> the whole vdsm log is attached. Got any clues?
>>>
>>> Thanks,
>>> Daniele Pavia
>>>
>>> Engineering I.I.
>>> R&D Labs
>>>
>>>
>>> _______________________________________________
>>> Users mailing list
>>> Users(a)ovirt.org
>>> http://lists.ovirt.org/mailman/listinfo/users
>>>
>> _______________________________________________
>> Users mailing list
>> Users(a)ovirt.org
>> http://lists.ovirt.org/mailman/listinfo/users
>
4153
days inactive
4157
days old
4 comments
3 participants
participants (3)
-
Ayal Baron -
Daniele Pavia -
Pavia Daniele