Bug 872961

Would you attach an excerpt of your vdsm.log, from vmCreate to the relevant backtrace? I'm not sure that assigning a default None value is the best approach, so I'd like to understand which drive specification was passed to prepareVolumePath().

P.S. does forman interact with vdsm directly, or via oVirt-Engine?

AFAIK this happens because of wrong vm status retuns from ovirt via API.

e.g. when creating a new vm, the vm status is ready, while the disks are still being created.

Sure no problem.  Here's my log file I saw on the ovirt node when I tried to kick off a vm build in foreman:

Thread-157549::DEBUG::2012-11-02 13:59:21,666::resourceManager::558::ResourceManager::(releaseResour
ce) Resource 'Storage.7d3aeead-4140-4a87-a648-1b4ab1009b3e' is free, finding out if anyone is waitin
g for it.
Thread-157549::DEBUG::2012-11-02 13:59:21,666::resourceManager::565::ResourceManager::(releaseResour
ce) No one is waiting for resource 'Storage.7d3aeead-4140-4a87-a648-1b4ab1009b3e', Clearing records.
Thread-157549::DEBUG::2012-11-02 13:59:21,666::task::978::TaskManager.Task::(_decref) Task=`0908296e
-8beb-415c-9b0d-e214eb83f5b5`::ref 0 aborting False
Thread-157549::DEBUG::2012-11-02 13:59:21,666::vm::580::vm.Vm::(_startUnderlyingVm) vmId=`e5dfe2ac-8
6e5-4f64-ac50-4977a624a9d5`::_ongoingCreations released
Thread-157549::ERROR::2012-11-02 13:59:21,666::vm::604::vm.Vm::(_startUnderlyingVm) vmId=`e5dfe2ac-8
6e5-4f64-ac50-4977a624a9d5`::The vm start process failed
Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 570, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/libvirtvm.py", line 1290, in _run
    self.preparePaths(devices[vm.DISK_DEVICES])
  File "/usr/share/vdsm/vm.py", line 616, in preparePaths
    drive['path'] = self.cif.prepareVolumePath(drive, self.id)
  File "/usr/share/vdsm/clientIF.py", line 274, in prepareVolumePath
    self.log.info("prepared volume path: %s", volPath)
UnboundLocalError: local variable 'volPath' referenced before assignment
Thread-157549::DEBUG::2012-11-02 13:59:21,670::vm::920::vm.Vm::(setDownStatus) vmId=`e5dfe2ac-86e5-4f64-ac50-4977a624a9d5`::Changed state to Down: local variable 'volPath' referenced before assignment
Thread-157551::DEBUG::2012-11-02 13:59:22,551::task::588::TaskManager.Task::(_updateState) Task=`83bc84dd-c719-4eff-b9b8-d468ad739968`::moving from state init -> state preparing

I'm still missing the most important part of the log, which is the line with the VM parameters passed from Engine to vdsm (it should be a bit higher up, marked with vmCreate).

Found it.

Thread-157548::DEBUG::2012-11-02 13:59:21,656::BindingXMLRPC::865::vds::(wrapper) return vmCreate wi
th {'status': {'message': 'Done', 'code': 0}, 'vmList': {'status': 'WaitForLaunch', 'acpiEnable': 't
rue', 'emulatedMachine': 'pc-0.14', 'tabletEnable': 'true', 'pid': '0', 'timeOffset': '0', 'displayP
ort': '-1', 'displaySecurePort': '-1', 'spiceSslCipherSuite': 'DEFAULT', 'cpuType': 'Conroe', 'custo
m': {}, 'clientIp': '', 'nicModel': 'rtl8139,pv', 'keyboardLayout': 'en-us', 'kvmEnable': 'true', 'p
itReinjection': 'false', 'vmId': 'e5dfe2ac-86e5-4f64-ac50-4977a624a9d5', 'transparentHugePages': 'tr
ue', 'devices': [{'device': 'qxl', 'specParams': {'vram': '65536'}, 'type': 'video', 'deviceId': 'f9
fc0fcb-06e7-430b-bddb-9568e6a845bf'}, {'index': '2', 'iface': 'ide', 'specParams': {'path': ''}, 're
adonly': 'true', 'deviceId': '29d0065a-69de-41a1-8904-eca5d4d25a2e', 'device': 'cdrom', 'type': 'dis
k'}, {'index': 0, 'iface': 'virtio', 'format': 'cow', 'bootOrder': '2', 'volumeID': '04dc394b-bd64-4
15d-a763-4b4dd749d131', 'imageID': 'f6d6984f-b3b9-4653-ba2e-727b15ca3d35', 'specParams': {}, 'readon
ly': 'false', 'domainID': '7d3aeead-4140-4a87-a648-1b4ab1009b3e', 'optional': 'false', 'deviceId': '
f6d6984f-b3b9-4653-ba2e-727b15ca3d35', 'poolID': '4c350671-7fac-4170-b901-9794b876ec73', 'device': '
disk', 'shared': 'false', 'propagateErrors': 'off', 'type': 'disk'}, {'nicModel': 'pv', 'macAddr': '
00:1a:4a:c0:03:19', 'network': '54', 'bootOrder': '1', 'specParams': {}, 'deviceId': '7f75664d-7c7e-
4c61-88ee-5b76e058ab88', 'device': 'bridge', 'type': 'interface'}, {'device': 'memballoon', 'specPar
ams': {'model': 'virtio'}, 'type': 'balloon', 'deviceId': '259ebf8f-5cf4-4345-96da-bc97133f0151'}], 
'smp': '2', 'vmType': 'kvm', 'memSize': 1024, 'displayIp': '0', 'spiceSecureChannels': 'smain,sinput
s,scursor,splayback,srecord,sdisplay', 'smpCoresPerSocket': '2', 'vmName': 'foreman-test1-ovirt-csc-
local', 'display': 'vnc', 'nice': '0'}}
Thread-157549::INFO::2012-11-02 13:59:21,657::libvirtvm::1285::vm.Vm::(_run) vmId=`e5dfe2ac-86e5-4f6
4-ac50-4977a624a9d5`::VM wrapper has started
Thread-157549::DEBUG::2012-11-02 13:59:21,658::task::588::TaskManager.Task::(_updateState) Task=`090
8296e-8beb-415c-9b0d-e214eb83f5b5`::moving from state init -> state preparing

Would you please attach the whole log, from vmCreate to the exception? I find it hard to understand how did we manage not to set volPath (and how presetting it to None helps anybody. Does you patch enables the VM to boot?)

Yes setting it to None allows the vm's to boot.  When it is not set, I get that error message and ovirt will refuse to power on the virtual machine.  I will have the log attached shortly.

Created attachment 640072 [details]
vdsm log file

This bug is about VM payload and has nothing to do with storage.

Related to
https://bugzilla.redhat.com/show_bug.cgi?id=843387

Invalid inputs:
'specParams': {}
'specParams': {'path': ''}

Anyway we should not railse outbound variable.
(This bug was foresighted a long time ago):

http://gerrit.ovirt.org/#/c/6803/3

Same problem here using python sdk api, with 3.1 under fedora-17 x64.

Simply doing (with a being an API object):
a.templates.add(params.Template(name='test', vm=params.VM(id=a.vms.get(name='no-so').get_id()), cluster=params.Cluster(id=a.clusters.get(name='Iscsi_Cluster').get_id()), description='borrar'))
# Wait until template is ready
a.vms.add( params.VM(name='test_vm', cluster = params.Cluster(id=a.clusters.get(name='Iscsi_Cluster').get_id()), template = params.Template(id=a.templates.get(name='test').get_id()), description='test mas tes', memory=256*1024*1024) )
# Wait until machine is finished

To this point, all goes fine. Now, when i try to start the machine, i get the same error. (In my case, setting volPath to '' at begining of the method 'prepareVolumePath'.

I also has tested using directly cluster and template (instead of params.Cluster), adding and removing params, but always same result.

If you need something, i can remove the 'volPath = ""' that i have added and repeat tests.

http://gerrit.ovirt.org/#/c/6803/4

http://gerrit.ovirt.org/#/c/6803/7

this one missed the branch date for 3.2, but it's merged to master as 0499051e4816274bcbc3564953782ecab9d8f8c5

(In reply to comment #14)
> this one missed the branch date for 3.2, but it's merged to master as
> 0499051e4816274bcbc3564953782ecab9d8f8c5

If there's a real need to backport this to ovirt-3.2, go ahead.

as RC is built, moving to ON_QA (hopefully did not catch incorrect bugs when doing this)

closing as this should be in 3.3 (doing so in bulk, so may be incorrect)