Bug 872961 - volPath referenced before assignment when creating a VM with foreman
Summary: volPath referenced before assignment when creating a VM with foreman
Keywords:
Status: CLOSED CURRENTRELEASE
Alias: None
Product: oVirt
Classification: Retired
Component: vdsm
Version: 3.1 GA
Hardware: Unspecified
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
: 3.3
Assignee: Saveliev Peter
QA Contact:
URL:
Whiteboard: virt
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2012-11-04 16:22 UTC by cholcomb
Modified: 2013-09-23 07:34 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2013-09-23 07:34:53 UTC
oVirt Team: ---
Embargoed:


Attachments (Terms of Use)
Fixed clientIF.py file (15.13 KB, application/octet-stream)
2012-11-04 16:22 UTC, cholcomb
no flags Details
vdsm log file (764.34 KB, application/octet-stream)
2012-11-07 13:28 UTC, cholcomb
no flags Details


Links
System ID Private Priority Status Summary Last Updated
oVirt gerrit 6803 0 None None None Never

Description cholcomb 2012-11-04 16:22:29 UTC
Created attachment 638063 [details]
Fixed clientIF.py file

Description of problem:
clientIF.py throws an error about volPath being referenced before assignment when I create a vm through foreman.  

Version-Release number of selected component (if applicable):
Latest stable ovirt code was used.  3.1

How reproducible:
Every time I kicked off a vm build I received the same error message and the vm would fail to build.  Foreman would then roll back the creation. 

Steps to Reproduce:
1. Install the latest foreman packages on a server
2. Connect foreman to your ovirt cluster
3. Initiate a vm build.  
  
Actual results:
VM would fail to power on and throw an error message saying. volPath in clientIF.py referenced before assignment.  

Expected results:
Vm would power on successfully.  

Additional info:
My fix was to add volPath = None to line #220 in clientIF.py 
I have attached the fixed file.  
I will work on submitting a patch tomorrow when I get in to work.

Comment 1 Dan Kenigsberg 2012-11-04 22:05:46 UTC
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?

Comment 2 Ohad Levy 2012-11-05 13:41:46 UTC
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.

Comment 3 cholcomb 2012-11-05 14:56:55 UTC
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

Comment 4 Dan Kenigsberg 2012-11-06 08:29:10 UTC
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).

Comment 5 cholcomb 2012-11-06 15:14:59 UTC
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

Comment 6 Dan Kenigsberg 2012-11-07 11:04:33 UTC
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?)

Comment 7 cholcomb 2012-11-07 13:22:23 UTC
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.

Comment 8 cholcomb 2012-11-07 13:28:14 UTC
Created attachment 640072 [details]
vdsm log file

Comment 9 Ayal Baron 2012-11-20 12:50:23 UTC
This bug is about VM payload and has nothing to do with storage.

Comment 10 Eduardo Warszawski 2012-11-20 12:55:38 UTC
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

Comment 11 Adolfo 2012-11-21 19:35:11 UTC
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.

Comment 12 Saveliev Peter 2012-11-30 15:57:24 UTC
http://gerrit.ovirt.org/#/c/6803/4

Comment 13 Saveliev Peter 2012-12-18 11:06:55 UTC
http://gerrit.ovirt.org/#/c/6803/7

Comment 14 Michal Skrivanek 2013-02-20 08:04:58 UTC
this one missed the branch date for 3.2, but it's merged to master as 0499051e4816274bcbc3564953782ecab9d8f8c5

Comment 15 Dan Kenigsberg 2013-02-20 08:17:30 UTC
(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.

Comment 16 Itamar Heim 2013-08-21 16:41:54 UTC
as RC is built, moving to ON_QA (hopefully did not catch incorrect bugs when doing this)

Comment 17 Itamar Heim 2013-09-23 07:34:53 UTC
closing as this should be in 3.3 (doing so in bulk, so may be incorrect)


Note You need to log in before you can comment on or make changes to this bug.