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