819460 – Cannot resume VM due to unexpected exception (Error code:16)

RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 819460 - Cannot resume VM due to unexpected exception (Error code:16)

Summary: Cannot resume VM due to unexpected exception (Error code:16)

Keywords:
Status:	CLOSED DUPLICATE of bug 797526
Alias:	None
Product:	Red Hat Enterprise Linux 6
Classification:	Red Hat
Component:	vdsm
Sub Component:
Version:	6.3
Hardware:	Unspecified
OS:	Unspecified
Priority:	unspecified
Severity:	unspecified
Target Milestone:	rc
Target Release:	---
Assignee:	Federico Simoncelli
QA Contact:	Haim
Docs Contact:
URL:
Whiteboard:	storage
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2012-05-07 10:21 UTC by Chao Yang
Modified:	2014-01-13 00:51 UTC (History)
CC List:	9 users (show)
Fixed In Version:
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2012-05-16 18:24:25 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)
the latest vdsm log I found on the host (266.28 KB, text/plain) 2012-05-07 13:05 UTC, Chao Yang	no flags	Details
vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224 (654.80 KB, application/x-gzip) 2012-05-08 05:50 UTC, Chao Yang	no flags	Details
libvirt.log (384.99 KB, application/x-gzip) 2012-05-08 06:28 UTC, Chao Yang	no flags	Details
View All

Description Chao Yang 2012-05-07 10:21:28 UTC

Description of problem:
VMs in my testing first hit error no space, after removing some VMs to save space, try to start the paused VMs, I got "Unexpected exception (Error code: 16)"

Version-Release number of selected component (if applicable):
# rpm -q vdsm libvirt qemu-kvm
vdsm-4.9.6-7.el6.x86_64
libvirt-0.9.10-11.el6.x86_64
qemu-kvm-0.12.1.2-2.276.el6.x86_64


How reproducible:


Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:

Comment 2 Yaniv Kaul 2012-05-07 10:40:06 UTC

VDSM logs?

Comment 3 Haim 2012-05-07 10:46:10 UTC

(In reply to comment #0)
> Description of problem:
> VMs in my testing first hit error no space, after removing some VMs to save
> space, try to start the paused VMs, I got "Unexpected exception (Error code:
> 16)"

will you be kind to add both vdsm and RHEVM logs ?

also: 

please provide: 

vdsClient -s 0 list table
virsh -r list

> 
> Version-Release number of selected component (if applicable):
> # rpm -q vdsm libvirt qemu-kvm
> vdsm-4.9.6-7.el6.x86_64
> libvirt-0.9.10-11.el6.x86_64
> qemu-kvm-0.12.1.2-2.276.el6.x86_64
> 
> 
> How reproducible:
> 
> 
> Steps to Reproduce:
> 1.
> 2.
> 3.
> 
> Actual results:
> 
> 
> Expected results:
> 
> 
> Additional info:

Comment 4 Chao Yang 2012-05-07 12:56:41 UTC

(In reply to comment #3)
> (In reply to comment #0)
> > Description of problem:
> > VMs in my testing first hit error no space, after removing some VMs to save
> > space, try to start the paused VMs, I got "Unexpected exception (Error code:
> > 16)"
> 
> will you be kind to add both vdsm and RHEVM logs ?
> 
There are a lot of vdsm logs, is there an easy way to pick up the one related?
Logs under /var/log/jbossas/rhevm-slimmed since 18 April are missed after rebooting jbossas. Or they are moved to somewhere else?
> also: 
> 
> please provide: 
> 
> vdsClient -s 0 list table
> 
# vdsClient -s 0 list table
8842aa9e-2d20-4540-8557-4d04752a28d7  32602  6u3-e5620-5-4        Paused                                   
6cab1aa5-15bb-450f-86f0-18c69057f0d1    869  6u3-e5620-5-3        Up                   10.66.108.255       
e397193c-ecfa-4ae9-a5d0-f4f22fb9e8fc  20941  2k8r2sp1-e-5-2       Up                                       
cf3bbc6a-9121-4f14-b864-4766ed1018c7    607  6u3-e5620-5-1        Up                   10.66.111.226       
fe0c288a-6d98-43a4-bf38-9f5fb4f0861e  21283  6u3-e5620-5-2        Paused                                   
0b9b9116-4973-4483-8d4a-4ecabb5742fe    326  5u8uZ-e5620-5-5      Paused                                   
64fa64cf-57d2-4d45-ae14-65ea3b3c9b02  21194  6u2uZ-e5620-5-2      Up                   10.66.110.255       
71876232-3ff1-458f-a771-75454731896e   3394  2k8r2sp1-e-5-1       Up                                       
c91ed5fa-3040-45d9-9c8a-35072a31bd5e  21109  6u2uZ-e5620-5-3      Paused                                   
86651bfa-1768-4d59-95df-df3fcc22ac7d   3428  2k8r2sp1-e-5-4       Up                                       
ee84bf0f-df09-4173-8946-e9184230d7a4    357  5u8uZ-e5620-5-1      Up                   10.66.111.227       
d0fd05b2-a549-4e7f-842d-6355b768e224  21025  6u2uZ-e5620-5-1      Paused                                   
12e63854-8aac-4e42-abee-0c4f8c08d639   5951  5u8uZ-e5620-5-4      Up                   10.66.109.253       
ab672435-bbb0-4792-aebf-b3145f3846b0  32413  6u2uZ-e5620-5-5      Up                   10.66.110.252       
2d3a8d47-dcc2-473b-8a4f-b96ecdd6ca57  31231  2k8r2sp1-4           Up                                       
e828fc04-d723-4f58-9420-365a2344c19c   5681  6u2uZ-e5620-5-4      Up                   10.66.109.254       
6d014d55-5c5e-4f0f-9c1f-b27ed10c1439  20158  5u8uZ-e5620-5-2      Up                   10.66.110.253       
3d00704b-26cd-429b-9fae-d8eb7726e9f1    783  5u8uZ-e5620-5-3      Paused                             

> virsh -r list
# virsh -r list
 Id    Name                           State
----------------------------------------------------
 1     5u8uZ-e5620-5-1                running
 2     6u3-e5620-5-1                  running
 4     2k8r2sp1-e-5-1                 running
 5     5u8uZ-e5620-5-2                running
 6     2k8r2sp1-e-5-2                 running
 7     6u2uZ-e5620-5-1                running
 8     6u2uZ-e5620-5-3                running
 9     6u2uZ-e5620-5-2                running
 10    6u3-e5620-5-2                  running
 12    5u8uZ-e5620-5-3                running
 13    6u3-e5620-5-3                  running
 14    6u2uZ-e5620-5-4                running
 16    5u8uZ-e5620-5-4                running
 23    2k8r2sp1-e-5-4                 running
 27    2k8r2sp1-4                     running
 29    6u2uZ-e5620-5-5                running
 30    6u3-e5620-5-4                  running
 31    5u8uZ-e5620-5-5                running

Comment 5 Chao Yang 2012-05-07 13:05:45 UTC

Created attachment 582656 [details]
the latest vdsm log I found on the host

Comment 6 Haim 2012-05-07 14:46:44 UTC

(In reply to comment #5)
> Created attachment 582656 [details]
> the latest vdsm log I found on the host

thanks a lot for the logs, i'm missing the 'continue' command in vdsm log, the only related issue I see is failure in setVmTicket which looks like this:

Thread-117149::DEBUG::2012-05-07 21:00:43,992::BindingXMLRPC::869::vds::(wrapper) client [10.66.11.208]::call vmSetTicket with ('3d00704b-26cd-429b-9fae-d8eb7726e9f1', '6N9/IwMGT4Sz', '120') {}
Thread-117149::ERROR::2012-05-07 21:00:43,993::BindingXMLRPC::884::vds::(wrapper) unexpected error
Traceback (most recent call last):
  File "/usr/share/vdsm/BindingXMLRPC.py", line 874, in wrapper
    res = f(*args, **kwargs)
  File "/usr/share/vdsm/BindingXMLRPC.py", line 226, in vmSetTicket
    return vm.setTicket(password, ttl, existingConnAction)
  File "/usr/share/vdsm/API.py", line 522, in setTicket
    return v.setTicket(password, ttl, existingConnAction)
  File "/usr/share/vdsm/libvirtvm.py", line 1886, in setTicket
    graphics = xml.dom.minidom.parseString(self._dom.XMLDesc(0)) \
AttributeError: 'NoneType' object has no attribute 'XMLDesc'

could you please reproduce again and attach both libivrt & vdsm logs ?

also, will you try the command manually: 

vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224

Comment 7 Chao Yang 2012-05-08 05:47:18 UTC

(In reply to comment #6)
> (In reply to comment #5)
> > Created attachment 582656 [details]
> > the latest vdsm log I found on the host
> 
> thanks a lot for the logs, i'm missing the 'continue' command in vdsm log, the
> only related issue I see is failure in setVmTicket which looks like this:
> 
> Thread-117149::DEBUG::2012-05-07
> 21:00:43,992::BindingXMLRPC::869::vds::(wrapper) client [10.66.11.208]::call
> vmSetTicket with ('3d00704b-26cd-429b-9fae-d8eb7726e9f1', '6N9/IwMGT4Sz',
> '120') {}
> Thread-117149::ERROR::2012-05-07
> 21:00:43,993::BindingXMLRPC::884::vds::(wrapper) unexpected error
> Traceback (most recent call last):
>   File "/usr/share/vdsm/BindingXMLRPC.py", line 874, in wrapper
>     res = f(*args, **kwargs)
>   File "/usr/share/vdsm/BindingXMLRPC.py", line 226, in vmSetTicket
>     return vm.setTicket(password, ttl, existingConnAction)
>   File "/usr/share/vdsm/API.py", line 522, in setTicket
>     return v.setTicket(password, ttl, existingConnAction)
>   File "/usr/share/vdsm/libvirtvm.py", line 1886, in setTicket
>     graphics = xml.dom.minidom.parseString(self._dom.XMLDesc(0)) \
> AttributeError: 'NoneType' object has no attribute 'XMLDesc'
> 
> could you please reproduce again and attach both libivrt & vdsm logs ?
> 
I reroduced again on d0fd05b2-a549-4e7f-842d-6355b768e224, will attach vdsm log soon, but I find no useful info from libvirt.log since no uuid like d0fd05b2-a549-4e7f-842d-6355b768e224 in libvirt log
> also, will you try the command manually: 
> 
> vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224

# vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224
Unexpected exception

Comment 8 Chao Yang 2012-05-08 05:50:41 UTC

Created attachment 582858 [details]
vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224

Comment 9 Yaniv Kaul 2012-05-08 06:16:46 UTC

(In reply to comment #8)
> Created attachment 582858 [details]
> vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224

And the libvirt log?

Comment 10 Chao Yang 2012-05-08 06:27:01 UTC

(In reply to comment #9)
> (In reply to comment #8)
> > Created attachment 582858 [details]
> > vdsClient -s 0 continue d0fd05b2-a549-4e7f-842d-6355b768e224
> 
> And the libvirt log?
I did not find the uuid d0fd05b2-a549-4e7f-842d-6355b768e224 in libvirt.log, so I did not upload it. Attaching this time.

Comment 11 Chao Yang 2012-05-08 06:28:44 UTC

Created attachment 582864 [details]
libvirt.log

Comment 12 Yaniv Kaul 2012-05-08 07:05:07 UTC

BTW, I warmly suggest to upgrade all components to a newer version (libvirt, VDSM and qemu-kvm are all a bit outdated - almost a month old or so).

Comment 13 RHEL Program Management 2012-05-13 04:05:12 UTC

This request was not resolved in time for the current release.
Red Hat invites you to ask your support representative to
propose this request, if still desired, for consideration in
the next release of Red Hat Enterprise Linux.

Comment 14 Federico Simoncelli 2012-05-16 11:19:16 UTC

I had the opportunity to debug this on Leonid's machine and I noticed that the real problem was:

Traceback (most recent call last):
  File "/usr/share/vdsm/vm.py", line 567, in _startUnderlyingVm
    self._run()
  File "/usr/share/vdsm/libvirtvm.py", line 1330, in _run
    self._devices[devType].append(devClass(self.conf, self.log, **dev))
  File "/usr/share/vdsm/libvirtvm.py", line 1002, in __init__
    self.blockDev = utils.isBlockDevice(self.path)
  File "/usr/lib/python2.6/site-packages/vdsm/utils.py", line 52, in isBlockDevice
    return stat.S_ISBLK(os.stat(path).st_mode)
OSError: [Errno 2] No such file or directory: '/rhev/data-center/36cc6fbc-9468-11e1-a5e5-001a4a169789/1c60971a-8647-44ac-ae33-6520887f8843/images/a2dd0b3b-928a-4bbe-8371-7eb0a92f929b/2827d3aa-0fb1-4227-b418-c8033094c0b8'

See bug 797526
Such exception was moving the VM to "Paused" when instead the _run method didn't complete, therefore having self._dom = None.
Later on any operation on the vm was failing because of uninitialized values (eg: self._dom).

I suggest to mark this bug as a duplicate of bug 797526
Leonid tested the proposed fix and wasn't able to reproduce the issue anymore (no Paused VMs after restart):

BZ#797526 Lazy evaluation for Drive.blockDev

Signed-off-by: Federico Simoncelli <fsimonce>
Change-Id: I93bc95650544372cec8883a8b7b568ecf419c129

http://gerrit.ovirt.org/4339

Comment 15 Federico Simoncelli 2012-05-16 18:24:25 UTC

Leonid verified the fix.

*** This bug has been marked as a duplicate of bug 797526 ***

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