Cinder

Create volume from image and cinder can’t catch the exception from the db which will reschedule to create volume then raise ImageExists

Bug #1521083 reported by jingtao liang
12
This bug affects 2 people
Affects Status Importance Assigned to Milestone
Cinder
New
Undecided
Unassigned

Bug Description

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.

Anand Shanmugam (anand1712)
Changed in cinder:
assignee: nobody → Anand Shanmugam (anand1712)
status: New → In Progress
jingtao liang (liang-jingtao)
Changed in cinder:
assignee: Anand Shanmugam (anand1712) → jingtao liang (liang-jingtao)
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to cinder (master)

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

Yafei Yu (yu-yafei)
summary: - Creating volume from image.Cinder can’t accept the exception from the db
- .That will reschedule to create volume twice and raise ImageExists
+ Create volume from image and cinder can’t catch the exception from the
+ db which will reschedule to create volume then raise ImageExists
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Change abandoned on cinder (master)

Change abandoned by Sean McGinnis (<email address hidden>) on branch: master
Review: https://review.openstack.org/319515
Reason: This review is > 4 weeks without comment, and failed Jenkins the last time it was checked. We are abandoning this for now. Feel free to reactivate the review by pressing the restore button and leaving a 'recheck' comment to get fresh test results.

Revision history for this message
Sean McGinnis (sean-mcginnis) wrote : Bug Assignee Expired

Unassigning due to no activity for > 6 months.

Changed in cinder:
assignee: jingtao liang (liang-jingtao) → nobody
Sean McGinnis (sean-mcginnis)
Changed in cinder:
status: In Progress → New
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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