Openstack Version : kilo 2015.1.0
describtion:
Creating volume from image.when the action of updating db to enable bootable flag for the volume is wrong. Cinder can’t accept the exception to raise exception.MetadataUpdateFailure.That will reschedule to create volume twice and raise ImageExists
In the logs we firstly see this:
2015-10-28 11:44:55.029 30946 ERROR oslo.messaging.rpc.dispatcher [req-2f2a22b6-02cc-4857-999e-d97ae717ca9e 34bcf21d461f4e9daa4ab3e171efd7fe 8f5aff5e28fe4d54a2e75936f7dd652c - - -] Exception during message handling: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 479, in create_volume
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher _run_flow()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 472, in _run_flow
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher flow_engine.run()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 89, in run
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher for _state in self.run_iter():
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 137, in run_iter
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher misc.Failure.reraise_if_any(failures.values())
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/utils/misc.py", line 797, in reraise_if_any
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher failures[0].reraise()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/utils/misc.py", line 804, in reraise
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher six.reraise(*self._exc_info)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 34, in _execute_task
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher result = task.execute(**arguments)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 619, in execute
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher **volume_spec)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 585, in _create_from_image
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher image_meta=image_meta)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 352, in _handle_bootable_volume_glance_meta
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher self._enable_bootable_flag(context, volume_id)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 422, in _enable_bootable_flag
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher self.db.volume_update(context, volume_id, {'bootable': True})
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/db/api.py", line 243, in volume_update
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return IMPL.volume_update(context, volume_id, values)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 139, in wrapper
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return f(*args, **kwargs)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 1433, in volume_update
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher volume_ref = _volume_get(context, volume_id, session=session)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 139, in wrapper
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return f(*args, **kwargs)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/db/sqlalchemy/api.py", line 1205, in _volume_get
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher filter_by(id=volume_id).\
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2282, in first
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher ret = list(self[0:1])
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2149, in __getitem__
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return list(res)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2353, in __iter__
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return self._execute_and_instances(context)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2366, in _execute_and_instances
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher close_with_result=True)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/query.py", line 2357, in _connection_from_session
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher **kw)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 799, in connection
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher close_with_result=close_with_result)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 803, in _connection_for_bind
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return self.transaction._connection_for_bind(engine)
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/orm/session.py", line 299, in _connection_for_bind
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher conn = bind.contextual_connect()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/engine/base.py", line 1661, in contextual_connect
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher self.pool.connect(),
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 272, in connect
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher return _ConnectionFairy(self).checkout()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 431, in __init__
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher rec = self._connection_record = pool._do_get()
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib64/python2.7/site-packages/sqlalchemy/pool.py", line 768, in _do_get
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher (self.size(), self.overflow(), self._timeout))
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher TimeoutError: QueuePool limit of size 5 overflow 10 reached, connection timed out, timeout 30
2015-10-28 11:44:55.029 30946 TRACE oslo.messaging.rpc.dispatcher
And then:
2015-10-28 11:44:58.757 30946 ERROR oslo.messaging.rpc.dispatcher [req-2f2a22b6-02cc-4857-999e-d97ae717ca9e 34bcf21d461f4e9daa4ab3e171efd7fe 8f5aff5e28fe4d54a2e75936f7dd652c - - -] Exception during message handling: error creating clone
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher Traceback (most recent call last):
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 133, in _dispatch_and_reply
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher incoming.message))
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 176, in _dispatch
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher return self._do_dispatch(endpoint, method, ctxt, args)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/oslo/messaging/rpc/dispatcher.py", line 122, in _do_dispatch
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher result = getattr(endpoint, method)(ctxt, **new_args)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 479, in create_volume
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher _run_flow()
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/manager.py", line 472, in _run_flow
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher flow_engine.run()
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 89, in run
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher for _state in self.run_iter():
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/engine.py", line 137, in run_iter
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher misc.Failure.reraise_if_any(failures.values())
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/utils/misc.py", line 797, in reraise_if_any
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher failures[0].reraise()
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/utils/misc.py", line 804, in reraise
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher six.reraise(*self._exc_info)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/taskflow/engines/action_engine/executor.py", line 34, in _execute_task
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher result = task.execute(**arguments)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 619, in execute
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher **volume_spec)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/flows/manager/create_volume.py", line 557, in _create_from_image
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher volume_ref, image_location, image_id, image_meta)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/rbd.py", line 841, in clone_image
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher self._clone(volume, pool, image, snapshot)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/cinder/volume/drivers/rbd.py", line 547, in _clone
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher features=self.rbd.RBD_FEATURE_LAYERING)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 179, in doit
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher result = proxy_call(self._autowrap, f, *args, **kwargs)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 139, in proxy_call
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher rv = execute(f,*args,**kwargs)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/eventlet/tpool.py", line 77, in tworker
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher rv = meth(*args,**kwargs)
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher File "/usr/lib/python2.7/site-packages/rbd.py", line 259, in clone
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher raise make_ex(ret, 'error creating clone')
2015-10-28 11:44:58.757 30946 TRACE oslo.messaging.rpc.dispatcher ImageExists: error creating clone
The main function like this:
/cinder/volume/flows/manager/create_volume.py:
def _enable_bootable_flag(self, context, volume_id):
try:
LOG.debug('Marking volume %s as bootable.', volume_id)
self.db.volume_update(context, volume_id, {'bootable': True})
except exception.CinderException as ex:
LOG.exception(_LE("Failed updating volume %(volume_id)s bootable "
"flag to true"), {'volume_id': volume_id})
raise exception.MetadataUpdateFailure(reason=ex)
please check this bug ,tks.
Fix proposed to branch: master /review. openstack. org/319515
Review: https:/