OpenStack Compute (nova)

Snapshotting VM instance failing for KVM

Bug #750544 reported by Tushar Patil
20
This bug affects 3 people
Affects Status Importance Assigned to Milestone
OpenStack Compute (nova)
Fix Released
High
Mike Scherbakov
OpenStack Compute (nova) 2011.3 "diablo"

Bug Description

Tested using nova revision No 925.

Steps to reproduce:-
1) Run one VM instance
2) Confirm if state of the VM instance is Active
{{{
root@ubuntu-openstack-network-api-server:/home/tpatil/nova# nova list
+----+-----------+--------+-----------+---------------------------------------+
| ID | Name | Status | Public IP | Private IP |
+----+-----------+--------+-----------+---------------------------------------+
| 58 | Server 58 | active | | {u'version': 4, u'addr': u'10.0.0.5'} |
+----+-----------+--------+-----------+---------------------------------------+
}}}

3) snapshot vm instance
$nova image-create 58 "Snapshot Testing"
{{{
Unknown error occurred! {"image": {"status": "queued", "name": "Snapshot Testing", "deleted": false, "container_format": null, "created_at": "2011-04-02T00:20:16.285868", "disk_format": null, "updated_at": null, "id": 6, "location": null, "checksum": null, "is_public": false, "deleted_at": null, "properties": {"instance_id": "58", "user_id": "admin"}, "size": 0}} (HTTP 500)
}}}

4) nova-api.log
{{{
2011-04-01 17:19:21,665 DEBUG eventlet.wsgi.server [-] 10.2.3.150 - - [01/Apr/2011 17:19:21] "GET /v1.1/ HTTP/1.1" 204 276 0.007600
 from (pid=19241) write /home/tpatil/nova/nova/wsgi.py:56
2011-04-01 17:19:21,723 DEBUG routes.middleware [-] No route matched for GET /servers/58 from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:97
2011-04-01 17:19:21,724 DEBUG routes.middleware [-] Matched GET /servers/58 from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:100
2011-04-01 17:19:21,724 DEBUG routes.middleware [-] Route path: '/servers/:(id)', defaults: {'action': u'show', 'controller': <nova.api.openstack.servers.ControllerV11 object at 0x21fffd0>} from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:102
2011-04-01 17:19:21,724 DEBUG routes.middleware [-] Match dict: {'action': u'show', 'controller': <nova.api.openstack.servers.ControllerV11 object at 0x21fffd0>, 'id': u'58'} from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:103
2011-04-01 17:19:21,854 DEBUG eventlet.wsgi.server [-] 10.2.3.150 - - [01/Apr/2011 17:19:21] "GET /v1.1//servers/58?fresh=1301703561.67 HTTP/1.1" 200 723 0.186549
 from (pid=19241) write /home/tpatil/nova/nova/wsgi.py:56
2011-04-01 17:19:21,911 DEBUG routes.middleware [-] No route matched for POST /images from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:97
2011-04-01 17:19:21,912 DEBUG routes.middleware [-] Matched POST /images from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:100
2011-04-01 17:19:21,913 DEBUG routes.middleware [-] Route path: '/images', defaults: {'action': u'create', 'controller': <nova.api.openstack.images.ControllerV11 object at 0x220f910>} from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:102
2011-04-01 17:19:21,913 DEBUG routes.middleware [-] Match dict: {'action': u'create', 'controller': <nova.api.openstack.images.ControllerV11 object at 0x220f910>} from (pid=19241) __call__ /usr/lib/pymodules/python2.6/routes/middleware.py:103
2011-04-01 17:19:21,914 DEBUG nova.image.glance [-] Creating image in Glance. Metadata passed in {'is_public': False, 'name': u'Snapshot Testing', 'properties': {'instance_id': '58', 'user_id': 'admin'}} from (pid=19241) create /home/tpatil/nova/nova/image/glance.py:135
2011-04-01 17:19:21,914 DEBUG nova.image.glance [-] Metadata after formatting for Glance {'is_public': False, 'name': u'Snapshot Testing', 'properties': {'instance_id': '58', 'user_id': 'admin'}} from (pid=19241) create /home/tpatil/nova/nova/image/glance.py:138
2011-04-01 17:19:22,016 ERROR nova.api.openstack [-] Caught error: Unknown error occurred! {"image": {"status": "queued", "name": "Snapshot Testing", "deleted": false, "container_format": null, "created_at": "2011-04-02T00:20:16.285868", "disk_format": null, "updated_at": null, "id": 6, "location": null, "checksum": null, "is_public": false, "deleted_at": null, "properties": {"instance_id": "58", "user_id": "admin"}, "size": 0}}
(nova.api.openstack): TRACE: Traceback (most recent call last):
(nova.api.openstack): TRACE: File "/home/tpatil/nova/nova/api/openstack/__init__.py", line 58, in __call__
(nova.api.openstack): TRACE: return req.get_response(self.application)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 919, in get_response
(nova.api.openstack): TRACE: application, catch_exc_info=False)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/request.py", line 887, in call_application
(nova.api.openstack): TRACE: app_iter = application(self.environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/routes/middleware.py", line 131, in __call__
(nova.api.openstack): TRACE: response = self.app(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/routes/middleware.py", line 131, in __call__
(nova.api.openstack): TRACE: response = self.app(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 159, in __call__
(nova.api.openstack): TRACE: return resp(environ, start_response)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 147, in __call__
(nova.api.openstack): TRACE: resp = self.call_func(req, *args, **self.kwargs)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/webob/dec.py", line 208, in call_func
(nova.api.openstack): TRACE: return self.func(req, *args, **kwargs)
(nova.api.openstack): TRACE: File "/home/tpatil/nova/nova/wsgi.py", line 354, in __call__
(nova.api.openstack): TRACE: result = method(**arg_dict)
(nova.api.openstack): TRACE: File "/home/tpatil/nova/nova/api/openstack/images.py", line 132, in create
(nova.api.openstack): TRACE: image = self._compute_service.snapshot(context, server_id, image_name)
(nova.api.openstack): TRACE: File "/home/tpatil/nova/nova/compute/api.py", line 473, in snapshot
(nova.api.openstack): TRACE: recv_meta = self.image_service.create(context, sent_meta)
(nova.api.openstack): TRACE: File "/home/tpatil/nova/nova/image/glance.py", line 141, in create
(nova.api.openstack): TRACE: sent_service_image_meta, data)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/glance/client.py", line 259, in add_image
(nova.api.openstack): TRACE: res = self.do_request("POST", "/images", body, headers)
(nova.api.openstack): TRACE: File "/usr/lib/pymodules/python2.6/glance/client.py", line 160, in do_request
(nova.api.openstack): TRACE: raise Exception("Unknown error occurred! %s" % res.read())
(nova.api.openstack): TRACE: Exception: Unknown error occurred! {"image": {"status": "queued", "name": "Snapshot Testing", "deleted": false, "container_format": null, "created_at": "2011-04-02T00:20:16.285868", "disk_format": null, "updated_at": null, "id": 6, "location": null, "checksum": null, "is_public": false, "deleted_at": null, "properties": {"instance_id": "58", "user_id": "admin"}, "size": 0}}
(nova.api.openstack): TRACE:
}}}

Related branches

lp:~rackspace-titan/nova/osapi-image-snapshot-response
lp:~mihgen/nova/split-args-qemu-img-call
lp:~termie/nova/fix_snapshot
Jesse Andrews (community): Approve
Vish Ishaya (community): Approve
Brian Lamar (community): Approve
Diff: 45 lines (+12/-8)
1 file modified
nova/virt/libvirt_conn.py (+12/-8)
Revision history for this message
Brian Lamar (blamar) wrote :

What version of glance are you running? Although snapshotting doesn't work for me in nova trunk, this looks to be a glance issue?

Revision history for this message
Tushar Patil (tpatil) wrote :

I am using glance revision no 100.

Revision history for this message
Brian Lamar (blamar) wrote :

The original stack trace you posted seems to be from a revision before rev97 (looking at the line numbers in the trace), is this trace the same with rev 100 running? Not doubting you're running rev100, just trying to reproduce on my end :)

Revision history for this message
Tushar Patil (tpatil) wrote :

Yes, you are correct when I tested this for the first time, I was on glance revision no 96.

Now using glance revision 100, while taking snapshot of vm instance still it is failing. But this time, I am getting errors in nova-compute.log

nova-compute.log
-------------------------
2011-04-04 13:38:34,319 DEBUG nova.rpc [-] received {'_context_request_id': '71SDHCE6PD4MR32SESX3', '_context_read_deleted': False, 'args': {'instance_id': 65, 'image_id': 19}, '_context_is_admin': True, '_context_timestamp': '2011-04-04T20:38:05Z', '_context_user': 'admin', 'method': 'snapshot_instance', '_context_project': 'admin', '_context_remote_address': None} from (pid=22359) _receive /home/tpatil/nova/nova/rpc.py:167
2011-04-04 13:38:34,320 DEBUG nova.rpc [-] unpacked context: {'timestamp': '2011-04-04T20:38:05Z', 'remote_address': None, 'project': 'admin', 'is_admin': True, 'user': 'admin', 'request_id': '71SDHCE6PD4MR32SESX3', 'read_deleted': False} from (pid=22359) _unpack_context /home/tpatil/nova/nova/rpc.py:331
2011-04-04 13:38:34,568 AUDIT nova.compute.manager [71SDHCE6PD4MR32SESX3 admin admin] instance 65: snapshotting
2011-04-04 13:38:34,582 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):
(nova.exception): TRACE: File "/home/tpatil/nova/nova/exception.py", line 120, in _wrap
(nova.exception): TRACE: return f(*args, **kw)
(nova.exception): TRACE: File "/home/tpatil/nova/nova/virt/libvirt_conn.py", line 423, in snapshot
(nova.exception): TRACE: metadata = {'disk_format': base['disk_format'],
(nova.exception): TRACE: KeyError: 'disk_format'
(nova.exception): TRACE:
2011-04-04 13:38:34,583 ERROR nova [-] Exception during message handling
(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/home/tpatil/nova/nova/rpc.py", line 188, in _receive
(nova): TRACE: rval = node_func(context=ctxt, **node_args)
(nova): TRACE: File "/home/tpatil/nova/nova/exception.py", line 120, in _wrap
(nova): TRACE: return f(*args, **kw)
(nova): TRACE: File "/home/tpatil/nova/nova/compute/manager.py", line 342, in snapshot_instance
(nova): TRACE: self.driver.snapshot(instance_ref, image_id)
(nova): TRACE: File "/home/tpatil/nova/nova/exception.py", line 126, in _wrap
(nova): TRACE: raise Error(str(e))
(nova): TRACE: Error: 'disk_format'
(nova): TRACE:

In my case while registering the disk-image using glance-upload I didn't specified disk_format so it is None. will this cause this problem?

I will register new images using nova-manage and try to reproduce this problem.

Revision history for this message
Tushar Patil (tpatil) wrote :

I am using qemu-img version 0.13.91 and after looking at the comments in the code qemu-img should be 0.14+.
I will install qemu-img 0.14+ and will try again.

Revision history for this message
Tushar Patil (tpatil) wrote :

I think qemu-img is a further step, because the error message is complaining that key disk_format is not present in the image dictionary returned by Glance. So may be this issue lies in Glance.

Revision history for this message
Brian Lamar (blamar) wrote :

Could you potentially try out this branch and see if it works for you? https://code.launchpad.net/~rackspace-titan/nova/osapi-image-snapshot-response

Thierry Carrez (ttx)
Changed in nova:
status: New → Incomplete
Revision history for this message
Tushar Patil (tpatil) wrote :
Download full text (3.5 KiB)

Brian: I tried your branch and it seems like the error I was getting before is fixed. But still snapshot of VM instance is not working. I am getting another error in the nova-compute.log.

nova-compute.log
----------------------------
2011-04-05 10:34:46,570 DEBUG nova.rpc [-] received {'_context_request_id': 'BJ8RO486PQEGIV8MF8PF', '_context_read_deleted': False, 'a rgs': {'instance_id': 77, 'image_id': 32}, '_context_is_admin': True, '_context_timestamp': '2011-04-05T17:31:50Z', '_context_user': ' admin', 'method': 'snapshot_instance', '_context_project': 'admin', '_context_remote_address': None} from (pid=2189) _receive /home/tp atil/nova/nova/rpc.py:167
2011-04-05 10:34:46,571 DEBUG nova.rpc [-] unpacked context: {'timestamp': '2011-04-05T17:31:50Z', 'remote_address': None, 'project': 'admin', 'is_admin': True, 'user': 'admin', 'request_id': 'BJ8RO486PQEGIV8MF8PF', 'read_deleted': False} from (pid=2189) _unpack_conte xt /home/tpatil/nova/nova/rpc.py:331
2011-04-05 10:34:46,822 AUDIT nova.compute.manager [BJ8RO486PQEGIV8MF8PF admin admin] instance 77: snapshotting
2011-04-05 10:37:01,130 DEBUG nova.utils [-] Running cmd (subprocess): qemu-img convert -f qcow2 -O raw -s 67dfea6bc7314cad99a451dfb3b01981 /nova/instances/instance -0000004d/disk /tmp/tmpVgnKrE/67dfea6bc7314cad99a451dfb3b01981 from (pid=2189) execute /home/tpatil/nova/nova/utils.py:150
2011-04-05 10:37:01,278 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):
(nova.exception): TRACE: File "/home/tpatil/nova/nova/exception.py", line 120, in _wrap
(nova.exception): TRACE: return f(*args, **kw)
(nova.exception): TRACE: File "/home/tpatil/nova/nova/virt/libvirt_conn.py", line 463, in snapshot
(nova.exception): TRACE: utils.execute(qemu_img_cmd)
(nova.exception): TRACE: File "/home/tpatil/nova/nova/utils.py", line 158, in execute
(nova.exception): TRACE: env=env)
(nova.exception): TRACE: File "/usr/lib/pymodules/python2.6/eventlet/green/subprocess.py", line 25, in __init__
(nova.exception): TRACE: subprocess_orig.Popen.__init__(self, args, 0, *argss, **kwds)
(nova.exception): TRACE: File "/usr/lib/python2.6/subprocess.py", line 623, in __init__
(nova.exception): TRACE: errread, errwrite)
(nova.exception): TRACE: File "/usr/lib/python2.6/subprocess.py", line 1141, in _execute_child
(nova.exception): TRACE: raise child_exception
(nova.exception): TRACE: OSError: [Errno 2] No such file or directory
(nova.exception): TRACE:
2011-04-05 10:37:01,288 ERROR nova [-] Exception during message handling
(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/home/tpatil/nova/nova/rpc.py", line 188, in _receive
(nova): TRACE: rval = node_func(context=ctxt, **node_args)
(nova): TRACE: File "/home/tpatil/nova/nova/exception.py", line 120, in _wrap
(nova): TRACE: return f(*args, **kw)
(nova): TRACE: File "/home/tpatil/nova/nova/compute/manager.py", line 342, in snapshot_instance
(nova): TRACE: self.driver.snapsho...

Read more...

Thierry Carrez (ttx)
Changed in nova:
importance: Undecided → High
status: Incomplete → Confirmed
Revision history for this message
Thierry Carrez (ttx) wrote :

Might be linked to bug 757613

Revision history for this message
Soren Hansen (soren) wrote :

From dup bug:

The qemu_img call in the libvirt driver's snapshot method tries to call utils.execute("qemu-img convert blahblah...") The argv needs to be split before passing it to utils.execute()

Fixing that particluar problem is easy, but I don't know if it does what it's supposed to. Clearly, noone has used/tested this for months.

Revision history for this message
Mike Scherbakov (mihgen) wrote :

Fix is in lp:~mihgen/nova/split-args-qemu-img-call

Changed in nova:
status: Confirmed → Fix Committed
assignee: nobody → Mike Scherbakov (mihgen)
Thierry Carrez (ttx)
Changed in nova:
status: Fix Committed → In Progress
Revision history for this message
Soren Hansen (soren) wrote :

Just to clarify: "Fix committed" means a fix has been applied to trunk. Until the patch has been approved, we leave the bug as "in progress"

Thierry Carrez (ttx)
Changed in nova:
status: In Progress → Fix Committed
Revision history for this message
Mike Scherbakov (mihgen) wrote :

image-create still doesn't work.
There is exception in nova-compute:
2011-04-27 16:33:02,411 ERROR nova.exception [-] Uncaught exception
(nova.exception): TRACE: Traceback (most recent call last):
(nova.exception): TRACE: File "/usr/lib/python2.7/site-packages/nova/exception.py", line 115, in _wrap
(nova.exception): TRACE: return f(*args, **kw)
(nova.exception): TRACE: File "/usr/lib/python2.7/site-packages/nova/virt/libvirt_conn.py", line 459, in snapshot
(nova.exception): TRACE: 'properties': {'architecture': base['architecture'],
(nova.exception): TRACE: KeyError: 'architecture'(nova.exception): TRACE: 2011-04-27 16:33:02,411 ERROR nova [-] Exception during message handling(nova): TRACE: Traceback (most recent call last):
(nova): TRACE: File "/usr/lib/python2.7/site-packages/nova/rpc.py", line 198, in _receive(nova): TRACE: rval = node_func(context=ctxt, **node_args)(nova): TRACE: File "/usr/lib/python2.7/site-packages/nova/exception.py", line 115, in _wrap
(nova): TRACE: return f(*args, **kw)
(nova): TRACE: File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 372, in snapshot_instance(nova): TRACE: self.driver.snapshot(instance_ref, image_id)
(nova): TRACE: File "/usr/lib/python2.7/site-packages/nova/exception.py", line 121, in _wrap
(nova): TRACE: raise Error(str(e))(nova): TRACE: Error: 'architecture'
(nova): TRACE:

Trivial fix will do the job - in libvirt_conn.py:

=== modified file 'nova/virt/libvirt_conn.py'
--- nova/virt/libvirt_conn.py 2011-04-26 22:48:28 +0000
+++ nova/virt/libvirt_conn.py 2011-04-28 16:52:50 +0000
@@ -456,7 +456,8 @@
                     'container_format': base['container_format'],
                     'is_public': False,
                     'name': '%s.%s' % (base['name'], image_id),
- 'properties': {'architecture': base['architecture'],
+ 'properties': {'architecture':
+ base['properties']['architecture'],
                                    'kernel_id': instance['kernel_id'],
                                    'image_location': 'snapshot',
                                    'image_state': 'available',

Changed in nova:
status: Fix Committed → Incomplete
Revision history for this message
Thierry Carrez (ttx) wrote :

@Mike:
Could you open a separate bug ? This one was snapshot-specific and got fixed, yours is actually a new issue... Please also specify which version of nova you're reproducing the error on. Thanks !

Changed in nova:
status: Incomplete → Fix Committed
Thierry Carrez (ttx)
Changed in nova:
milestone: none → diablo-1
Revision history for this message
Mike Scherbakov (mihgen) wrote :

Thierry,
I opened separate bug as you proposed a while ago: https://bugs.launchpad.net/nova/+bug/780784,
it's in review state.
I guess I needed to mark it here somehow.

Thierry Carrez (ttx)
Changed in nova:
milestone: diablo-1 → 2011.3
status: Fix Committed → Fix Released
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Duplicates of this bug

Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.