Bug 1054201

Created attachment 851042 [details]
Vdsm log

Description of problem:

When user tries to power off a VM on upgraded environment (3.0...->3.3)
the action fails with unexpected exception in vdsm.

Version-Release number of selected component (if applicable):
is29


How reproducible:
100 % in GSS lab

Steps to Reproduce:
1. upgrade env. from 3.0 all the way up to 3.3
2. create fresh vm (one disk, no nic, first boot device set to pxe)
3. start the vm to bios
4. try to power off the vm

Actual results:


Expected results:


Additional info:
Engine log:
[root@lab-rhevm ~]#  grep -in 5f17bc0 /var/log/ovirt-engine/engine.log
52934:2014-01-16 07:05:35,013 INFO  [org.ovirt.engine.core.bll.StopVmCommand] (pool-5-thread-50) [5f17bc0] Running command: StopVmCommand internal: false. Entities affected :  ID: 10bce6b5-ab25-452b-a8e2-24309deae8b7 Type: VM
52935:2014-01-16 07:05:35,017 INFO  [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (pool-5-thread-50) [5f17bc0] START, DestroyVmVDSCommand(HostName = lab-rhevh-4.gsslab.brq.redhat.com, HostId = e28c9736-8f64-4e3b-a8d0-586637e5b33e, vmId=10bce6b5-ab25-452b-a8e2-24309deae8b7, force=false, secondsToWait=0, gracefully=false), log id: 1b03b540
52936:2014-01-16 07:05:35,031 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] START, DestroyVDSCommand(HostName = lab-rhevh-4.gsslab.brq.redhat.com, HostId = e28c9736-8f64-4e3b-a8d0-586637e5b33e, vmId=10bce6b5-ab25-452b-a8e2-24309deae8b7, force=false, secondsToWait=0, gracefully=false), log id: 2532946a
52937:2014-01-16 07:05:35,348 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] Failed in DestroyVDS method
52938:2014-01-16 07:05:35,348 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] Error code unexpected and error message VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Unexpected exception
52939:2014-01-16 07:05:35,348 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] Command org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand return value 
52941:2014-01-16 07:05:35,348 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] HostName = lab-rhevh-4.gsslab.brq.redhat.com
52942:2014-01-16 07:05:35,349 ERROR [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] Command DestroyVDS execution failed. Exception: VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Unexpected exception
52943:2014-01-16 07:05:35,349 INFO  [org.ovirt.engine.core.vdsbroker.vdsbroker.DestroyVDSCommand] (pool-5-thread-50) [5f17bc0] FINISH, DestroyVDSCommand, log id: 2532946a
52944:2014-01-16 07:05:35,349 ERROR [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (pool-5-thread-50) [5f17bc0] VDS::destroy Failed destroying vm 10bce6b5-ab25-452b-a8e2-24309deae8b7 in vds = e28c9736-8f64-4e3b-a8d0-586637e5b33e : lab-rhevh-4.gsslab.brq.redhat.com, error = org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Unexpected exception
52945:2014-01-16 07:05:35,349 INFO  [org.ovirt.engine.core.vdsbroker.DestroyVmVDSCommand] (pool-5-thread-50) [5f17bc0] FINISH, DestroyVmVDSCommand, log id: 1b03b540
52946:2014-01-16 07:05:35,349 ERROR [org.ovirt.engine.core.bll.StopVmCommand] (pool-5-thread-50) [5f17bc0] Command org.ovirt.engine.core.bll.StopVmCommand throw Vdc Bll exception. With error message VdcBLLException: org.ovirt.engine.core.vdsbroker.vdsbroker.VDSErrorException: VDSGenericException: VDSErrorException: Failed to DestroyVDS, error = Unexpected exception (Failed with error unexpected and code 16)
52947:2014-01-16 07:05:35,364 INFO  [org.ovirt.engine.core.dal.dbbroker.auditloghandling.AuditLogDirector] (pool-5-thread-50) [5f17bc0] Correlation ID: 5f17bc0, Job ID: 4105cf1a-4fd6-406f-9428-ba8848c92f94, Call Stack: null, Custom Event ID: -1, Message: Failed to power off VM pbajenez-RHEL_6.5 (Host: lab-rhevh-4.gsslab.brq.redhat.com, User: rhevadmin).

vdsm.log (please note vdsm log is in indian standard time, while engine is in cet - means 4:30 difference):

Thread-287814::INFO::2014-01-16 17:16:28,355::API::324::vds::(destroy) vmContainerLock acquired by vm 10bce6b5-ab25-452b-a8e2-24309deae8b7
Thread-287814::DEBUG::2014-01-16 17:16:28,355::vm::4477::vm.Vm::(destroy) vmId=`10bce6b5-ab25-452b-a8e2-24309deae8b7`::destroy Called
Thread-287814::ERROR::2014-01-16 17:16:28,375::BindingXMLRPC::1003::vds::(wrapper) unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/BindingXMLRPC.py", line 989, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/BindingXMLRPC.py", line 211, in vmDestroy
    return vm.destroy()
  File "/usr/share/vdsm/API.py", line 329, in destroy
    res = v.destroy()
  File "/usr/share/vdsm/vm.py", line 4485, in destroy
    response = self.releaseVm()
  File "/usr/share/vdsm/vm.py", line 4417, in releaseVm
    supervdsm.getProxy().removeFs(drive.path)
  File "/usr/share/vdsm/supervdsm.py", line 50, in __call__
    return callMethod()
  File "/usr/share/vdsm/supervdsm.py", line 48, in <lambda>
    **kwargs)
  File "<string>", line 2, in removeFs
  File "/usr/lib64/python2.6/multiprocessing/managers.py", line 740, in _callmethod
    raise convert_to_error(kind, result)
Exception: Cannot remove Fs that does not exists in: /var/run/vdsm/payload