openstack team mailing list archive

Thread
Date
Re: [Cinder] New volume status stuck at "Creating" after creation in Horizon

To: openstack@xxxxxxxxxxxxxxxxxxx
From: Ahmed Al-Mehdi <ahmedalmehdi@xxxxxxxxx>
Date: Tue, 4 Dec 2012 13:55:39 -0800
In-reply-to: <CAKNWCPY=gw4+YN8xutjM663Uj_F4+YZ3KWHGGUyutgxBwek-AQ@mail.gmail.com>
In cider-api.log, I see the following messages when the volume was created,
suggesting Horizon has instructed cinder to create the volume (size 3 GB):

2012-12-04 09:05:02 AUDIT cinder.api.openstack.volume.volumes
[req-1b122042-c3e4-4c1e-8285-ad148c8c2367 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] Create volume of 3 GB
2012-12-04 09:05:02 DEBUG cinder.quota
[req-1b122042-c3e4-4c1e-8285-ad148c8c2367 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] Created reservations
['c9ab451b-b464-46f1-9735-66494
8bcfe2f', '1c3d4643-e9a1-4438-9287-dc2d3c5ed43f'] reserve
/usr/lib/python2.7/dist-packages/cinder/quota.py:663
2012-12-04 09:05:02 5893 DEBUG cinder.openstack.common.rpc.amqp [-] Making
asynchronous cast on cinder-scheduler... cast
/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py:377
2012-12-04 09:05:02 5893 DEBUG cinder.openstack.common.rpc.amqp [-] Pool
creating new connection create
/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py:58
2012-12-04 09:05:02 5893 INFO cinder.openstack.common.rpc.common [-]
Connected to AMQP server on localhost:5672
2012-12-04 09:05:02 AUDIT cinder.api.openstack.volume.volumes
[req-1b122042-c3e4-4c1e-8285-ad148c8c2367 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] vol={'availability_zone': 'no
va', 'terminated_at': None, 'updated_at': None, 'provider_auth': None,
'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at':
None, 'id': '9dd360bf-9ef2-499f-ac6e-893abf5dc5ce', 'size'
: 3, 'user_id': u'386d0f02d6d045e7ba49d8edac7bb43f', 'attach_time': None,
'display_description': u'First test volume (iscsi)', 'project_id':
u'70e5c14a28a14666a86e85b62ca6ae18', 'launched_at': None, '
scheduled_at': None, 'status': 'creating', 'volume_type_id': None,
'deleted': False, 'provider_location': None, 'host': None, 'display_name':
u'myvol1', 'instance_uuid': None, 'created_at': datetime.d
atetime(2012, 12, 4, 17, 5, 2, 471475), 'attach_status': 'detached'}
2012-12-04 09:05:02 INFO cinder.api.openstack.wsgi
[req-1b122042-c3e4-4c1e-8285-ad148c8c2367 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] http://10.176.20.102:8776/v1/70e5c14a28a
14666a86e85b62ca6ae18/volumes returned with HTTP 200
2012-12-04 09:05:02 INFO cinder.api.openstack.wsgi
[req-c6c7ec3a-c2cd-4aa1-851a-1aa3bd218341 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] GET http://10.176.20.102:8776/v1/70e5c14
a28a14666a86e85b62ca6ae18/volumes/detail
2012-12-04 09:05:02 DEBUG cinder.api.openstack.wsgi
[req-c6c7ec3a-c2cd-4aa1-851a-1aa3bd218341 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] Unrecognized Content-Type provided in r
equest get_body
/usr/lib/python2.7/dist-packages/cinder/api/openstack/wsgi.py:695
2012-12-04 09:05:02 DEBUG cinder.api.openstack.volume.volumes
[req-c6c7ec3a-c2cd-4aa1-851a-1aa3bd218341 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] Removing options '' from quer
y remove_invalid_options
/usr/lib/python2.7/dist-packages/cinder/api/openstack/volume/volumes.py:356
2012-12-04 09:05:02 AUDIT cinder.api.openstack.volume.volumes
[req-c6c7ec3a-c2cd-4aa1-851a-1aa3bd218341 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] vol=<cinder.db.sqlalchemy.mod
els.Volume object at 0x368c350>
2012-12-04 09:05:02 INFO cinder.api.openstack.wsgi
[req-c6c7ec3a-c2cd-4aa1-851a-1aa3bd218341 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] http://10.176.20.102:8776/v1/70e5c14a28a
14666a86e85b62ca6ae18/volumes/detail returned with HTTP 200

And then the following three messages repeated every minute or two from
then onwards:

2012-12-04 09:05:03 INFO cinder.api.openstack.wsgi
[req-0a3b9032-b32a-4858-986e-741f213b8c38 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] GET http://10.176.20.102:8776/v1/70e5c14
a28a14666a86e85b62ca6ae18/volumes/9dd360bf-9ef2-499f-ac6e-893abf5dc5ce
2012-12-04 09:05:03 DEBUG cinder.api.openstack.wsgi
[req-0a3b9032-b32a-4858-986e-741f213b8c38 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] Unrecognized Content-Type provided in r
equest get_body
/usr/lib/python2.7/dist-packages/cinder/api/openstack/wsgi.py:695
2012-12-04 09:05:03 AUDIT cinder.api.openstack.volume.volumes
[req-0a3b9032-b32a-4858-986e-741f213b8c38 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] vol={'volume_metadata': [], '
availability_zone': u'nova', 'terminated_at': None, 'updated_at': None,
'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at':
None, 'id': u'9dd360bf-9ef2-499f-ac6e-893abf5dc5ce', 'siz
e': 3L, 'user_id': u'386d0f02d6d045e7ba49d8edac7bb43f', 'attach_time':
None, 'display_description': u'First test volume (iscsi)', 'project_id':
u'70e5c14a28a14666a86e85b62ca6ae18', 'launched_at': None
, 'scheduled_at': None, 'status': u'creating', 'volume_type_id': None,
'deleted': False, 'provider_location': None, 'host': None, 'provider_auth':
None, 'display_name': u'myvol1', 'instance_uuid': Non
e, 'created_at': datetime.datetime(2012, 12, 4, 17, 5, 2), 'attach_status':
u'detached', 'volume_type': None}
2012-12-04 09:05:03 INFO cinder.api.openstack.wsgi
[req-0a3b9032-b32a-4858-986e-741f213b8c38 386d0f02d6d045e7ba49d8edac7bb43f
70e5c14a28a14666a86e85b62ca6ae18] http://10.176.20.102:8776/v1/70e5c14a28a
14666a86e85b62ca6ae18/volumes/9dd360bf-9ef2-499f-ac6e-893abf5dc5ce returned
with HTTP 200

Regards,
Ahmed.





On Tue, Dec 4, 2012 at 9:44 AM, Ahmed Al-Mehdi <ahmedalmehdi@xxxxxxxxx>wrote:

> Hello,
>
> I setup a two node OpenStack setup, one controller-node and one
> compute-node.  I am using Quantum, Cinder services, and KVM for
> virtualization.  I am running into an issue creating a volume through
> Horizon which I will attach to a VM later on.  The status of volume in
> Horizon is stuck at "Creating".  The output of "cinder list" shows nothing.
>
> The iscsi service is setup properly, as far as I can tell.  I feel there
> is a communication issue between the openstack services.
>
> No log entry in cinder-volume.log.
>
> However, cinder-scheduler.log has the following entry:
>
> 2012-12-04 09:05:02 23552 DEBUG cinder.openstack.common.rpc.amqp [-]
> received {u'_context_roles': [u'Member', u'admin'], u'_context_request_id':
> u'req-1b122042-c3e4-4c1e-8285-ad148c8c2367', u'_context
> _quota_class': None, u'args': {u'topic': u'cinder-volume', u'image_id':
> None, u'snapshot_id': None, u'volume_id':
> u'9dd360bf-9ef2-499f-ac6e-893abf5dc5ce'}, u'_context_auth_token':
> '<SANITIZED>', u'_co
> ntext_is_admin': False, u'_context_project_id':
> u'70e5c14a28a14666a86e85b62ca6ae18', u'_context_timestamp':
> u'2012-12-04T17:05:02.375789', u'_context_read_deleted': u'no',
> u'_context_user_id': u'386d0
> f02d6d045e7ba49d8edac7bb43f', u'method': u'create_volume',
> u'_context_remote_address': u'10.176.20.102'} _safe_log
> /usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/common.py:195
> 2012-12-04 09:05:02 23552 DEBUG cinder.openstack.common.rpc.amqp [-]
> unpacked context: {'user_id': u'386d0f02d6d045e7ba49d8edac7bb43f', 'roles':
> [u'Member', u'admin'], 'timestamp': u'2012-12-04T17:05:
> 02.375789', 'auth_token': '<SANITIZED>', 'remote_address':
> u'10.176.20.102', 'quota_class': None, 'is_admin': False, 'request_id':
> u'req-1b122042-c3e4-4c1e-8285-ad148c8c2367', 'project_id': u'70e5c14a
> 28a14666a86e85b62ca6ae18', 'read_deleted': u'no'} _safe_log
> /usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/common.py:195
> 2012-12-04 09:05:02 23552 ERROR cinder.openstack.common.rpc.amqp [-]
> Exception during message handling
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp Traceback
> (most recent call last):
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/amqp.py",
> line 276, in _process_data
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp     rval
> = self.proxy.dispatch(ctxt, version, method, **args)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/openstack/common/rpc/dispatcher.py",
> line 145, in dispatch
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> return getattr(proxyobj, method)(ctxt, **kwargs)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/scheduler/manager.py", line 98, in
> _schedule
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> db.volume_update(context, volume_id, {'status': 'error'})
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/db/api.py", line 256, in
> volume_update
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> return IMPL.volume_update(context, volume_id, values)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 124,
> in wrapper
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> return f(*args, **kwargs)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 1071,
> in volume_update
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> volume_ref = volume_get(context, volume_id, session=session)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 124,
> in wrapper
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> return f(*args, **kwargs)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp   File
> "/usr/lib/python2.7/dist-packages/cinder/db/sqlalchemy/api.py", line 1014,
> in volume_get
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp     raise
> exception.VolumeNotFound(volume_id=volume_id)
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
> VolumeNotFound: Volume 9dd360bf-9ef2-499f-ac6e-893abf5dc5ce could not be
> found.
> 2012-12-04 09:05:02 23552 TRACE cinder.openstack.common.rpc.amqp
>
>
> Has anyone run into this issue.  Can I issue some cinder-* cli command to
> get more info about the issue.
> Any help would be very appreciated.
>
> Thank you,
> Ahmed.
>
>
References

[Cinder] New volume status stuck at "Creating" after creation in Horizon
From: Ahmed Al-Mehdi, 2012-12-04