[Users] SD Disk's Logical Volume not visible/activated on some nodes

Tue Feb 18 13:34:49 UTC 2014

Hello,

I have ovirt 3.3 installed on on FC 19 hosts with vdsm 4.13.3-2.fc19.
One of the hosts (host1) is engine + node + SPM and the other host2 is
just a node. I have an iSCSI storage domain configured and accessible
from both nodes.

When creating a new disk in the SD, the underlying logical volume gets
properly created (seen in vgdisplay output on host1), but doesn't seem
to be automatically picked by host2. Consequently, when creating/booting
a VM with the said disk attached, the VM fails to start on host2,
because host2 can't see the LV. Similarly, if the VM is started on
host1, it fails to migrate to host2. Extract from host2 log is in the
end. The LV in question is 6b35673e-7062-4716-a6c8-d5bf72fe3280.

As far as I could track quickly the vdsm code, there is only call to lvs
and not to lvscan or lvchange so the host2 LVM doesn't fully refresh.
The only workaround so far has been to restart VDSM on host2, which
makes it refresh all LVM data properly.

When is host2 supposed to pick up any newly created LVs in the SD VG?
Any suggestions where the problem might be?

Thanks!

Thread-998::DEBUG::2014-02-18
14:49:15,399::BindingXMLRPC::965::vds::(wrapper) client
[10.10.0.10]::call vmCreate with ({'acpiEnable': 'true',
'emulatedMachine': 'pc-1.0', 'tabletEnable': 'true', 'vmId':
'4669e4ad-7b76-4531-a16b-2b85345593a3', 'memGuaranteedSize': 1024,
'spiceSslCipherSuite': 'DEFAULT', 'timeOffset': '0', 'cpuType':
'Penryn', 'custom': {}, 'smp': '1', 'vmType': 'kvm', 'memSize': 1024,
'smpCoresPerSocket': '1', 'vmName': 'testvm', 'nice': '0',
'smartcardEnable': 'false', 'keyboardLayout': 'en-us', 'kvmEnable':
'true', 'pitReinjection': 'false', 'transparentHugePages': 'true',
'devices': [{'device': 'cirrus', 'specParams': {'vram': '32768',
'heads': '1'}, 'type': 'video', 'deviceId':
'9b769f44-db37-4e42-a343-408222e1422f'}, {'index': '2', 'iface': 'ide',
'specParams': {'path': ''}, 'readonly': 'true', 'deviceId':
'a61b291c-94de-4fd4-922e-1d51f4d2760d', 'path': '', 'device': 'cdrom',
'shared': 'false', 'type': 'disk'}, {'index': 0, 'iface': 'virtio',
'format': 'raw', 'bootOrder': '1', 'volumeID':
'6b35673e-7062-4716-a6c8-d5bf72fe3280', 'imageID':
'3738d400-a62e-4ded-b97f-1b4028e5f45b', 'specParams': {}, 'readonly':
'false', 'domainID': '3307f6fa-dd58-43db-ab23-b1fb299006c7', 'optional':
'false', 'deviceId': '3738d400-a62e-4ded-b97f-1b4028e5f45b', 'poolID':
'61f15cc0-8bba-482d-8a81-cd636a581b58', 'device': 'disk', 'shared':
'false', 'propagateErrors': 'off', 'type': 'disk'}, {'device':
'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon',
'deviceId': '4e05c1d1-2ac3-4885-8c1d-92ccd1388f0d'}, {'device': 'scsi',
'specParams': {}, 'model': 'virtio-scsi', 'type': 'controller',
'deviceId': 'fa3c223a-0cfc-4adf-90bc-cb6073a4b212'}],
'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'display': 'vnc'},) {} flowID [20468793]
Thread-998::INFO::2014-02-18
14:49:15,406::API::642::vds::(_getNetworkIp) network None: using 0
Thread-998::INFO::2014-02-18
14:49:15,406::clientIF::394::vds::(createVm) vmContainerLock acquired by
vm 4669e4ad-7b76-4531-a16b-2b85345593a3
Thread-999::DEBUG::2014-02-18
14:49:15,409::vm::2091::vm.Vm::(_startUnderlyingVm)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::Start
Thread-998::DEBUG::2014-02-18
14:49:15,409::clientIF::407::vds::(createVm) Total desktops after
creation of 4669e4ad-7b76-4531-a16b-2b85345593a3 is 1
Thread-999::DEBUG::2014-02-18
14:49:15,409::vm::2095::vm.Vm::(_startUnderlyingVm)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::_ongoingCreations acquired
Thread-998::DEBUG::2014-02-18
14:49:15,410::BindingXMLRPC::972::vds::(wrapper) return vmCreate with
{'status': {'message': 'Done', 'code': 0}, 'vmList': {'status':
'WaitForLaunch', 'acpiEnable': 'true', 'emulatedMachine': 'pc-1.0',
'tabletEnable': 'true', 'pid': '0', 'memGuaranteedSize': 1024,
'timeOffset': '0', 'keyboardLayout': 'en-us', 'displayPort': '-1',
'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType':
'Penryn', 'smp': '1', 'clientIp': '', 'nicModel': 'rtl8139,pv',
'smartcardEnable': 'false', 'kvmEnable': 'true', 'pitReinjection':
'false', 'vmId': '4669e4ad-7b76-4531-a16b-2b85345593a3',
'transparentHugePages': 'true', 'devices': [{'device': 'cirrus',
'specParams': {'vram': '32768', 'heads': '1'}, 'type': 'video',
'deviceId': '9b769f44-db37-4e42-a343-408222e1422f'}, {'index': '2',
'iface': 'ide', 'specParams': {'path': ''}, 'readonly': 'true',
'deviceId': 'a61b291c-94de-4fd4-922e-1d51f4d2760d', 'path': '',
'device': 'cdrom', 'shared': 'false', 'type': 'disk'}, {'index': 0,
'iface': 'virtio', 'format': 'raw', 'bootOrder': '1', 'volumeID':
'6b35673e-7062-4716-a6c8-d5bf72fe3280', 'imageID':
'3738d400-a62e-4ded-b97f-1b4028e5f45b', 'specParams': {}, 'readonly':
'false', 'domainID': '3307f6fa-dd58-43db-ab23-b1fb299006c7', 'optional':
'false', 'deviceId': '3738d400-a62e-4ded-b97f-1b4028e5f45b', 'poolID':
'61f15cc0-8bba-482d-8a81-cd636a581b58', 'device': 'disk', 'shared':
'false', 'propagateErrors': 'off', 'type': 'disk'}, {'device':
'memballoon', 'specParams': {'model': 'virtio'}, 'type': 'balloon',
'deviceId': '4e05c1d1-2ac3-4885-8c1d-92ccd1388f0d'}, {'device': 'scsi',
'specParams': {}, 'model': 'virtio-scsi', 'type': 'controller',
'deviceId': 'fa3c223a-0cfc-4adf-90bc-cb6073a4b212'}], 'custom': {},
'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0',
'spiceSecureChannels':
'smain,sinputs,scursor,splayback,srecord,sdisplay,susbredir,ssmartcard',
'smpCoresPerSocket': '1', 'vmName': 'testvm', 'display': 'vnc', 'nice':
'0'}}
Thread-999::INFO::2014-02-18 14:49:15,410::vm::2926::vm.Vm::(_run)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::VM wrapper has started
Thread-999::DEBUG::2014-02-18
14:49:15,412::task::579::TaskManager.Task::(_updateState)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::moving from state init ->
state preparing
Thread-999::INFO::2014-02-18
14:49:15,413::logUtils::44::dispatcher::(wrapper) Run and protect:
getVolumeSize(sdUUID='3307f6fa-dd58-43db-ab23-b1fb299006c7',
spUUID='61f15cc0-8bba-482d-8a81-cd636a581b58',
imgUUID='3738d400-a62e-4ded-b97f-1b4028e5f45b',
volUUID='6b35673e-7062-4716-a6c8-d5bf72fe3280', options=None)
Thread-999::DEBUG::2014-02-18
14:49:15,413::lvm::440::OperationMutex::(_reloadlvs) Operation 'lvm
reload operation' got the operation mutex
Thread-999::DEBUG::2014-02-18
14:49:15,413::lvm::309::Storage.Misc.excCmd::(cmd) '/usr/bin/sudo -n
/sbin/lvm lvs --config " devices { preferred_names =
[\\"^/dev/mapper/\\"] ignore_suspended_devices=1 write_cache_state=0
disable_after_error_count=3 obtain_device_list_from_udev=0 filter = [
\'a|/dev/mapper/36090a098103b1821532d057a5a0120d4|/dev/mapper/36090a09810bb99fefb2da57b94332027|\',
\'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,vg_name,attr,size,seg_start_pe,devices,tags
3307f6fa-dd58-43db-ab23-b1fb299006c7' (cwd None)
Thread-999::DEBUG::2014-02-18
14:49:15,466::lvm::309::Storage.Misc.excCmd::(cmd) SUCCESS: <err> = '';
<rc> = 0
Thread-999::DEBUG::2014-02-18
14:49:15,481::lvm::475::Storage.LVM::(_reloadlvs) lvs reloaded
Thread-999::DEBUG::2014-02-18
14:49:15,481::lvm::475::OperationMutex::(_reloadlvs) Operation 'lvm
reload operation' released the operation mutex
Thread-999::WARNING::2014-02-18
14:49:15,482::lvm::621::Storage.LVM::(getLv) lv:
6b35673e-7062-4716-a6c8-d5bf72fe3280 not found in lvs vg:
3307f6fa-dd58-43db-ab23-b1fb299006c7 response
Thread-999::ERROR::2014-02-18
14:49:15,482::task::850::TaskManager.Task::(_setError)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::Unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/storage/task.py", line 857, in _run
    return fn(*args, **kargs)
  File "/usr/share/vdsm/logUtils.py", line 45, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/storage/hsm.py", line 3059, in getVolumeSize
    apparentsize = str(volClass.getVSize(dom, imgUUID, volUUID, bs=1))
  File "/usr/share/vdsm/storage/blockVolume.py", line 111, in getVSize
    size = int(int(lvm.getLV(sdobj.sdUUID, volUUID).size) / bs)
  File "/usr/share/vdsm/storage/lvm.py", line 914, in getLV
    raise se.LogicalVolumeDoesNotExistError("%s/%s" % (vgName, lvName))
LogicalVolumeDoesNotExistError: Logical volume does not exist:
('3307f6fa-dd58-43db-ab23-b1fb299006c7/6b35673e-7062-4716-a6c8-d5bf72fe3280',)
Thread-999::DEBUG::2014-02-18
14:49:15,485::task::869::TaskManager.Task::(_run)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::Task._run:
07adf25e-b9fe-44d0-adf4-9159ac0f1f4d
('3307f6fa-dd58-43db-ab23-b1fb299006c7',
'61f15cc0-8bba-482d-8a81-cd636a581b58',
'3738d400-a62e-4ded-b97f-1b4028e5f45b',
'6b35673e-7062-4716-a6c8-d5bf72fe3280') {} failed - stopping task
Thread-999::DEBUG::2014-02-18
14:49:15,485::task::1194::TaskManager.Task::(stop)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::stopping in state preparing
(force False)
Thread-999::DEBUG::2014-02-18
14:49:15,486::task::974::TaskManager.Task::(_decref)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::ref 1 aborting True
Thread-999::INFO::2014-02-18
14:49:15,486::task::1151::TaskManager.Task::(prepare)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::aborting: Task is aborted:
'Logical volume does not exist' - code 610
Thread-999::DEBUG::2014-02-18
14:49:15,486::task::1156::TaskManager.Task::(prepare)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::Prepare: aborted: Logical
volume does not exist
Thread-999::DEBUG::2014-02-18
14:49:15,486::task::974::TaskManager.Task::(_decref)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::ref 0 aborting True
Thread-999::DEBUG::2014-02-18
14:49:15,486::task::909::TaskManager.Task::(_doAbort)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::Task._doAbort: force False
Thread-999::DEBUG::2014-02-18
14:49:15,487::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-999::DEBUG::2014-02-18
14:49:15,487::task::579::TaskManager.Task::(_updateState)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::moving from state preparing
-> state aborting
Thread-999::DEBUG::2014-02-18
14:49:15,487::task::534::TaskManager.Task::(__state_aborting)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::_aborting: recover policy none
Thread-999::DEBUG::2014-02-18
14:49:15,487::task::579::TaskManager.Task::(_updateState)
Task=`07adf25e-b9fe-44d0-adf4-9159ac0f1f4d`::moving from state aborting
-> state failed
Thread-999::DEBUG::2014-02-18
14:49:15,487::resourceManager::939::ResourceManager.Owner::(releaseAll)
Owner.releaseAll requests {} resources {}
Thread-999::DEBUG::2014-02-18
14:49:15,488::resourceManager::976::ResourceManager.Owner::(cancelAll)
Owner.cancelAll requests {}
Thread-999::ERROR::2014-02-18
14:49:15,488::dispatcher::67::Storage.Dispatcher.Protect::(run)
{'status': {'message': "Logical volume does not exist:
('3307f6fa-dd58-43db-ab23-b1fb299006c7/6b35673e-7062-4716-a6c8-d5bf72fe3280',)",
'code': 610}}
Thread-999::ERROR::2014-02-18
14:49:15,488::vm::1826::vm.Vm::(_normalizeVdsmImg)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::Unable to get volume size
for 6b35673e-7062-4716-a6c8-d5bf72fe3280
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 1822, in _normalizeVdsmImg
    drv['truesize'] = res['truesize']
KeyError: 'truesize'
Thread-999::DEBUG::2014-02-18
14:49:15,489::vm::2112::vm.Vm::(_startUnderlyingVm)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::_ongoingCreations released
Thread-999::ERROR::2014-02-18
14:49:15,489::vm::2138::vm.Vm::(_startUnderlyingVm)
vmId=`4669e4ad-7b76-4531-a16b-2b85345593a3`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 2098, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/vm.py", line 2930, in _run
    devices = self.buildConfDevices()
  File "/usr/share/vdsm/vm.py", line 1935, in buildConfDevices
    self._normalizeVdsmImg(drv)
  File "/usr/share/vdsm/vm.py", line 1828, in _normalizeVdsmImg
    drv['volumeID'])
RuntimeError: Volume 6b35673e-7062-4716-a6c8-d5bf72fe3280 is corrupted
or missing

Best regards,
Boyan Tabakov

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 268 bytes
Desc: OpenPGP digital signature
URL: <http://lists.ovirt.org/pipermail/users/attachments/20140218/e0068515/attachment-0001.sig>