<html>
  <head>

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