Boot from snapshot is broken

[Masashi Nakamichi]

Hi,

I'm deploying OpenStack Folsom-2, and evaluating Cinder.
I will report a issue about "Creating volume from snapshot is broken"

I try to launch an instance from snapshot. But error occur.
$ nova boot --image d6cb5fc7-4c36-4d10-9731-cacfa726a957 --flavor 1 --block_device_mapping /dev/vda=18a127ac-335c-49ec-8283-356f81712080:snap:2:0 --key_name testkey precise-snap-002
$ nova list
Please input your password for the keyring
+--------------------------------------+------------------+--------+-----------------------+
| ID | Name | Status | Networks |
+--------------------------------------+------------------+--------+-----------------------+
| 1bad4a19-2162-416d-8307-9aa452bb45c5 | precise-snap-002 | ERROR | |
+--------------------------------------+------------------+--------+-----------------------+

Error log from cinder-api service:

2012-07-26 10:08:46 AUDIT cinder.api.openstack.volume.volumes [req-8b64d853-bfa1-4667-a101-3726750223ce e5355fe674ca4700a419ecfed5faa9fb 825784e1eadb40b5a81398f60ad5ef3f] Create volume of 0 GB
2012-07-26 10:08:46 ERROR cinder.api.openstack [req-8b64d853-bfa1-4667-a101-3726750223ce e5355fe674ca4700a419ecfed5faa9fb 825784e1eadb40b5a81398f60ad5ef3f] Caught error: (ProgrammingError) (1064, 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near \': "\'available\'", u\'display_name\': "\'test_snapshot-001\'", u\'created_at\': "\'2012-0\' at line 3') 'SELECT snapshots.created_at AS snapshots_created_at, snapshots.updated_at AS snapshots_updated_at, snapshots.deleted_at AS snapshots_deleted_at, snapshots.deleted AS snapshots_deleted, snapshots.id AS snapshots_id, snapshots.user_id AS snapshots_user_id, snapshots.project_id AS snapshots_project_id, snapshots.volume_id AS snapshots_volume_id, snapshots.status AS snapshots_status, snapshots.progress AS snapshots_progress, snapshots.volume_size AS snapshots_volume_size, snapshots.display_name AS snapshots_display_name, snapshots.display_description AS snapshots_display_description \nFROM snapshots \nWHERE snapshots.deleted = %s AND snapshots.id = %s \n LIMIT %s' (0, {u'status': u'available', u'display_name': u'test_snapshot-001', u'created_at': u'2012-07-24 07:34:20', u'display_description': None, u'volume_size': 2, u'volume_id': u'013c7d76-764e-4c8e-aaa3-7df05ff50a6a', u'progress': u'100%', u'project_id': u'825784e1eadb40b5a81398f60ad5ef3f', u'id': u'18a127ac-335c-49ec-8283-356f81712080', u'size': 2}, 1)
2012-07-26 10:08:46 TRACE cinder.api.openstack Traceback (most recent call last):
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/api/openstack/__init__.py", line 41, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return req.get_response(self.application)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/request.py", line 1053, in get_response
2012-07-26 10:08:46 TRACE cinder.api.openstack application, catch_exc_info=False)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/request.py", line 1022, in call_application
2012-07-26 10:08:46 TRACE cinder.api.openstack app_iter = application(self.environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 159, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return resp(environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/keystone-2012.2-py2.7.egg/keystone/middleware/auth_token.py", line 185, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return self.app(env, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 159, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return resp(environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 159, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return resp(environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/routes/middleware.py", line 131, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack response = self.app(environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 159, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack return resp(environ, start_response)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 147, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack resp = self.call_func(req, *args, **self.kwargs)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/local/lib/python2.7/dist-packages/WebOb-1.0.8-py2.7.egg/webob/dec.py", line 208, in call_func
2012-07-26 10:08:46 TRACE cinder.api.openstack return self.func(req, *args, **kwargs)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/api/openstack/wsgi.py", line 802, in __call__
2012-07-26 10:08:46 TRACE cinder.api.openstack content_type, body, accept)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/api/openstack/wsgi.py", line 850, in _process_stack
2012-07-26 10:08:46 TRACE cinder.api.openstack action_result = self.dispatch(meth, request, action_args)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/api/openstack/wsgi.py", line 925, in dispatch
2012-07-26 10:08:46 TRACE cinder.api.openstack return method(req=request, **action_args)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/api/openstack/volume/volumes.py", line 236, in create
2012-07-26 10:08:46 TRACE cinder.api.openstack snapshot_id)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/volume/api.py", line 207, in get_snapshot
2012-07-26 10:08:46 TRACE cinder.api.openstack rv = self.db.snapshot_get(context, snapshot_id)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/db/api.py", line 584, in snapshot_get
2012-07-26 10:08:46 TRACE cinder.api.openstack return IMPL.snapshot_get(context, snapshot_id)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/db/sqlalchemy/api.py", line 122, in wrapper
2012-07-26 10:08:46 TRACE cinder.api.openstack return f(*args, **kwargs)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/opt/folsom/cinder/cinder/db/sqlalchemy/api.py", line 854, in snapshot_get
2012-07-26 10:08:46 TRACE cinder.api.openstack filter_by(id=snapshot_id).\
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1988, in first
2012-07-26 10:08:46 TRACE cinder.api.openstack ret = list(self[0:1])
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 1882, in __getitem__
2012-07-26 10:08:46 TRACE cinder.api.openstack return list(res)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2057, in __iter__
2012-07-26 10:08:46 TRACE cinder.api.openstack return self._execute_and_instances(context)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/orm/query.py", line 2072, in _execute_and_instances
2012-07-26 10:08:46 TRACE cinder.api.openstack result = conn.execute(querycontext.statement, self._params)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1405, in execute
2012-07-26 10:08:46 TRACE cinder.api.openstack params)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1538, in _execute_clauseelement
2012-07-26 10:08:46 TRACE cinder.api.openstack compiled_sql, distilled_params
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1646, in _execute_context
2012-07-26 10:08:46 TRACE cinder.api.openstack context)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/base.py", line 1639, in _execute_context
2012-07-26 10:08:46 TRACE cinder.api.openstack context)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/sqlalchemy/engine/default.py", line 330, in do_execute
2012-07-26 10:08:46 TRACE cinder.api.openstack cursor.execute(statement, parameters)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/MySQLdb/cursors.py", line 174, in execute
2012-07-26 10:08:46 TRACE cinder.api.openstack self.errorhandler(self, exc, value)
2012-07-26 10:08:46 TRACE cinder.api.openstack File "/usr/lib/python2.7/dist-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
2012-07-26 10:08:46 TRACE cinder.api.openstack raise errorclass, errorvalue
2012-07-26 10:08:46 TRACE cinder.api.openstack ProgrammingError: (ProgrammingError) (1064, 'You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near \': "\'available\'", u\'display_name\': "\'test_snapshot-001\'", u\'created_at\': "\'2012-0\' at line 3') 'SELECT snapshots.created_at AS snapshots_created_at, snapshots.updated_at AS snapshots_updated_at, snapshots.deleted_at AS snapshots_deleted_at, snapshots.deleted AS snapshots_deleted, snapshots.id AS snapshots_id, snapshots.user_id AS snapshots_user_id, snapshots.project_id AS snapshots_project_id, snapshots.volume_id AS snapshots_volume_id, snapshots.status AS snapshots_status, snapshots.progress AS snapshots_progress, snapshots.volume_size AS snapshots_volume_size, snapshots.display_name AS snapshots_display_name, snapshots.display_description AS snapshots_display_description \nFROM snapshots \nWHERE snapshots.deleted = %s AND snapshots.id = %s \n LIMIT %s' (0, {u'status': u'available', u'display_name': u'test_snapshot-001', u'created_at': u'2012-07-24 07:34:20', u'display_description': None, u'volume_size': 2, u'volume_id': u'013c7d76-764e-4c8e-aaa3-7df05ff50a6a', u'progress': u'100%', u'project_id': u'825784e1eadb40b5a81398f60ad5ef3f', u'id': u'18a127ac-335c-49ec-8283-356f81712080', u'size': 2}, 1)
2012-07-26 10:08:46 TRACE cinder.api.openstack
2012-07-26 10:08:46 INFO cinder.api.openstack [req-8b64d853-bfa1-4667-a101-3726750223ce e5355fe674ca4700a419ecfed5faa9fb 825784e1eadb40b5a81398f60ad5ef3f] http://192.168.1.1:8776/v1/825784e1eadb40b5a81398f60ad5ef3f/volumes returned with HTTP 500

It seems the superficial problem depends on snapshot_id not being an appropriate value.
As a result, a SQL syntax error occurs.

[Akira Yoshiyama (yosshy)]

It's not cinder's problem but nova's.

nova-2012.2/nova/compute/manager.py:

   378 def _setup_block_device_mapping(self, context, instance):
   ....
   404 if ((bdm['snapshot_id'] is not None) and
   405 (bdm['volume_id'] is None)):
   406 # TODO(yamahata): default name and description
   407 snapshot = self.volume_api.get_snapshot(context,
   408 bdm['snapshot_id'])
   409 vol = self.volume_api.create(context, bdm['volume_size'],
   410 '', '', snapshot)

self.volume_api.create() takes an argument 'snapshot' that is a dictionary.

nova-2012.2/nova/volume/cinder.py:

   172 def create(self, context, size, name, description, snapshot=None,
   173 volume_type=None, metadata=None, availability_zone=None):
   174
   175 item = cinderclient(context).volumes.create(size, snapshot,
   176 name, description,
   177 volume_type)
   178
   179 volume = _untranslate_volume_summary_view(context, item)
   180 return _untranslate_volume_summary_view(context, item)

cinderclient(context).volumes.create() takes that data as is.
But it must be snapshot id (uuid string), so the problem occured.

There are 2 solutions:

a) a simple way:
diff -u nova-2012.2/nova/volume/cinder.py.orig nova-2012.2/nova/volume/cinder.py
--- nova-2012.2/nova/volume/cinder.py.orig 2012-08-21 06:16:55.625616989 +0900
+++ nova-2012.2/nova/volume/cinder.py 2012-08-21 06:17:14.101617617 +0900
@@ -172,7 +172,7 @@
     def create(self, context, size, name, description, snapshot=None,
                      volume_type=None, metadata=None, availability_zone=None):

- item = cinderclient(context).volumes.create(size, snapshot,
+ item = cinderclient(context).volumes.create(size, snapshot['id'],
                                                     name, description,
                                                     volume_type)

b) more complex way:
diff -u nova-2012.2/nova/compute/manager.py.orig nova-2012.2/nova/compute/manager.py
--- nova-2012.2/nova/compute/manager.py.orig 2012-08-21 06:27:35.401636637 +0900
+++ nova-2012.2/nova/compute/manager.py 2012-08-21 06:27:56.769637297 +0900
@@ -404,10 +404,8 @@
             if ((bdm['snapshot_id'] is not None) and
                 (bdm['volume_id'] is None)):
                 # TODO(yamahata): default name and description
- snapshot = self.volume_api.get_snapshot(context,
- bdm['snapshot_id'])
                 vol = self.volume_api.create(context, bdm['volume_size'],
- '', '', snapshot)
+ '', '', bdm['snapshot_id'])
                 # TODO(yamahata): creating volume simultaneously
                 # reduces creation time?
                 # TODO(yamahata): eliminate dumb polling

diff -u nova-2012.2/nova...

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/12253

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/12253
Committed: http://github.com/openstack/nova/commit/1591c94bdd5f2b746be362dee5f0dd4068994ea4
Submitter: Jenkins
Branch: master

commit 1591c94bdd5f2b746be362dee5f0dd4068994ea4
Author: Unmesh Gurjar <email address hidden>
Date: Fri Aug 31 05:59:52 2012 -0700

    Fixed boot from snapshot failure.

    Passed the snapshot_id to cinder client from create API. Previously it was
    failing since snapshot was being passed instead of snapshot_id.

    Fixes LP: #1029211

    Change-Id: I4aa1aca9067b2a282b9b46d909ef8342bf933a46