[Openstack] [Cinder/Heat]: heat stack-delete hangs when volumes are attached to instance
Juha Tynninen
juha.tynninen at tieto.com
Tue Dec 10 13:54:29 UTC 2013
Hi,
I'm using stable/havana version of OpenStack.
I met problem when trying to execute heat stack-delete for a stack in which
a OS::Nova::Server instance has been created with Cinder volume attachments.
Is this a known problem, or should a bug report be raised...?
Workflow:
1) Create Cinder volumes to be used. See the used template below.
2) Create an instance (booted from volume) with storage volume attached.
See the used template below.
3) Situation is ok, instance running with storage volume attached.
4) Execute heat stack-delete for stack created in step 2). Operation hangs:
- stack status remains as "DELETE_IN_PROGRESS" (see heat engine log
entries below).
- storage volume status remains as "detaching" (see cinder api log
entries below).
- instance status doesn't change: Status: ACTIVE, Power State: Running
Any ideas?
Thanks,
-Juha
===============
Additional info
===============
Template used to create volumes:
--------------------------------
{
"AWSTemplateFormatVersion" : "2010-09-09",
"Resources" : {
"StorageVolumeOne" : {
"Type" : "OS::Cinder::Volume",
"Properties" : {
"description" : "Persistent storage volume #1 for VM",
"name" : "Storage volume one",
"size" : 1
}
},
"StorageVolumeTwo" : {
"Type" : "OS::Cinder::Volume",
"Properties" : {
"description" : "Persistent storage volume #2 for VM",
"name" : "Storage volume two",
"size" : 1
}
},
"FedoraBootVolume" : {
"Type" : "OS::Cinder::Volume",
"Properties" : {
"description" : "Bootable Fedora volume",
"name" : "Bootable Fedora volume",
"size" : 2,
"image" : "Fedora19cfntools"
}
}
}
}
Template used to create instance:
--------------------------------
{
"AWSTemplateFormatVersion" : "2010-09-09",
"Parameters" : {
"KeyName" : {
"Description" : "Name of an existing EC2 KeyPair to enable SSH access
to the instance",
"Default" : "heat_key_admin",
"Type" : "String"
},
"BootVolumeId" : {
"Description" : "ID of volume VM is booted from",
"Type" : "String"
},
"StorageVolumeId" : {
"Description" : "ID of storage volume to be used by VM",
"Type" : "String"
}
},
"Resources" : {
"DemoInstance" : {
"Type" : "OS::Nova::Server",
"Properties" : {
"key_name" : { "Ref" : "KeyName" },
"flavor": "m1.small",
"block_device_mapping": [
{"device_name": "vda",
"delete_on_termination": false,
"volume_id": { "Ref": "BootVolumeId"} }
]
}
},
"StorageVolumeAttachment" : {
"Type" : "OS::Cinder::VolumeAttachment",
"DependsOn": "DemoInstance",
"Properties" : {
"instance_uuid" : { "Ref" : "DemoInstance" },
"mountpoint" : "/dev/vdb",
"volume_id" : { "Ref" : "StorageVolumeId" }
}
}
}
}
Status as shown by cinder list:
-------------------------------
+--------------------------------------+-----------+------------------------+------+-------------+----------+--------------------------------------+
| ID | Status | Display Name
| Size | Volume Type | Bootable | Attached to |
+--------------------------------------+-----------+------------------------+------+-------------+----------+--------------------------------------+
| 95ae18ae-0300-4286-9848-9069e1d251e0 | detaching | Storage volume one
| 1 | None | false | |
| ee885acb-d817-4e79-8edd-2f0f393a08e1 | in-use | Bootable Fedora volume
| 2 | None | true | c65cf2db-a52d-4d40-bdf7-b0e879fdb25f |
| f5d50098-1ccb-44ee-b3df-6b3af7a263ca | available | Storage volume two
| 1 | None | false | |
+--------------------------------------+-----------+------------------------+------+-------------+----------+--------------------------------------+
Status as shown by heat list:
-----------------------------
+--------------------------------------+------------+--------------------+----------------------+
| id | stack_name | stack_status |
creation_time |
+--------------------------------------+------------+--------------------+----------------------+
| 29b49f50-b571-46e8-967f-fc7522962011 | volumes | CREATE_COMPLETE |
2013-12-10T12:24:25Z |
| ebbee23b-717f-4b6f-a5b1-48a4c2ad6cd8 | server | DELETE_IN_PROGRESS |
2013-12-10T12:53:56Z |
+--------------------------------------+------------+--------------------+----------------------+
heat engine logs (following kind of lines repeating):
-----------------------------------------------------
2013-12-10 15:15:57.204 INFO urllib3.connectionpool [-] Starting new HTTP
connection (1): xx.xx.xx.xx
2013-12-10 15:15:57.303 DEBUG urllib3.connectionpool [-] "GET
/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
HTTP/1.1" 200 601 from (pid=14579) _make_request
/usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:283
2013-12-10 15:15:57.303 DEBUG heat.engine.resources.volume [-] Detaching
Volume 95ae18ae-0300-4286-9848-9069e1d251e0 from Instance
c65cf2db-a52d-4d40-bdf7-b0e879fdb25f - volume still in use from (pid=14579)
__call__ /opt/stack/heat/heat/engine/resources/volume.py:243
2013-12-10 15:15:57.303 DEBUG heat.engine.scheduler [-] Task
VolumeDetachTask(95ae18ae-0300-4286-9848-9069e1d251e0 -/>
c65cf2db-a52d-4d40-bdf7-b0e879fdb25f) sleeping from (pid=14579) _sleep
/opt/stack/heat/heat/engine/scheduler.py:108
2013-12-10 15:15:58.304 DEBUG heat.engine.scheduler [-] Task
VolumeDetachTask(95ae18ae-0300-4286-9848-9069e1d251e0 -/>
c65cf2db-a52d-4d40-bdf7-b0e879fdb25f) running from (pid=14579) step
/opt/stack/heat/heat/engine/scheduler.py:164
2013-12-10 15:15:58.489 DEBUG urllib3.connectionpool [-] "DELETE
/v2/77c29bbaa7234a7594a7a030a90a3021/servers/c65cf2db-a52d-4d40-bdf7-b0e879fdb25f/os-volume_attachments/95ae18ae-0300-4286-9848-9069e1d251e0
HTTP/1.1" 404 78 from (pid=14579) _make_request
/usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:283
2013-12-10 15:15:58.490 INFO urllib3.connectionpool [-] Starting new HTTP
connection (1): 192.168.56.106
2013-12-10 15:15:58.569 DEBUG urllib3.connectionpool [-] "GET
/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
HTTP/1.1" 200 601 from (pid=14579) _make_request
/usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:283
2013-12-10 15:15:58.569 DEBUG heat.engine.resources.volume [-] Detaching
Volume 95ae18ae-0300-4286-9848-9069e1d251e0 from Instance
c65cf2db-a52d-4d40-bdf7-b0e879fdb25f - volume still in use from (pid=14579)
__call__ /opt/stack/heat/heat/engine/resources/volume.py:243
2013-12-10 15:15:58.569 DEBUG heat.engine.scheduler [-] Task
VolumeDetachTask(95ae18ae-0300-4286-9848-9069e1d251e0 -/>
c65cf2db-a52d-4d40-bdf7-b0e879fdb25f) sleeping from (pid=14579) _sleep
/opt/stack/heat/heat/engine/scheduler.py:108
cinder api logs (following kind of lines repeating):
----------------------------------------------------
2013-12-10 15:20:37.411 AUDIT cinder.api.v1.volumes
[req-90eedc5f-1cad-49df-b68e-82c60f584ebe ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] vol={'migration_status': None,
'availability_zone': u'nova', 'terminated_at': None, 'updated_at':
datetime.datetime(2013, 12, 10, 12, 57, 20), 'provider_geometry': None,
'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at':
None, 'id': u'95ae18ae-0300-4286-9848-9069e1d251e0', 'size': 1L, 'user_id':
u'ba53467682e848da8381b3ce90af7c59', 'attach_time': None, 'attached_host':
None, 'display_description': u'Persistent storage volume #1 for VM',
'volume_admin_metadata': [<cinder.db.sqlalchemy.models.VolumeAdminMetadata
object at 0x4d67950>], 'encryption_key_id': None, 'project_id':
u'77c29bbaa7234a7594a7a030a90a3021', 'launched_at': datetime.datetime(2013,
12, 10, 12, 24, 51), 'scheduled_at': datetime.datetime(2013, 12, 10, 12,
24, 27), 'status': u'detaching', 'volume_type_id': None, 'deleted': False,
'provider_location': u'192.168.56.106:3260,2
iqn.2010-10.org.openstack:volume-95ae18ae-0300-4286-9848-9069e1d251e0 1',
'host': u'lubuntu-VirtualBox', 'source_volid': None, 'provider_auth':
u'CHAP FHPtW6q3JMdQdB2aALco jthcvgQrCp2CGJZo5v54', 'display_name':
u'Storage volume one', 'instance_uuid': None, 'bootable': False,
'created_at': datetime.datetime(2013, 12, 10, 12, 24, 26), 'attach_status':
u'detached', 'volume_type': None, '_name_id': None, 'volume_metadata': [],
'metadata': {u'readonly': u'False'}}
2013-12-10 15:20:37.577 INFO cinder.api.openstack.wsgi
[req-90eedc5f-1cad-49df-b68e-82c60f584ebe ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021]
http://192.168.56.106:8776/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0returned
with HTTP 200
2013-12-10 15:20:38.744 DEBUG keystoneclient.middleware.auth_token [-]
Authenticating user token from (pid=12701) __call__
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:568
2013-12-10 15:20:38.744 DEBUG keystoneclient.middleware.auth_token [-]
Removing headers from request environment:
X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
from (pid=12701) _remove_auth_headers
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:627
2013-12-10 15:20:38.745 DEBUG iso8601.iso8601 [-] Parsed
2013-12-11T12:56:55.000000Z into {'tz_sign': None, 'second_fraction':
u'000000', 'hour': u'12', 'tz_hour': None, 'month': u'12', 'timezone':
u'Z', 'second': u'55', 'tz_minute': None, 'year': u'2013', 'separator':
u'T', 'day': u'11', 'minute': u'56'} with default timezone
<iso8601.iso8601.Utc object at 0x279b490> from (pid=12701) parse_date
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:166
2013-12-10 15:20:38.745 DEBUG iso8601.iso8601 [-] Got u'2013' for 'year'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.745 DEBUG iso8601.iso8601 [-] Got u'12' for 'month'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.745 DEBUG iso8601.iso8601 [-] Got u'11' for 'day' with
default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.745 DEBUG iso8601.iso8601 [-] Got u'12' for 'hour' with
default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.746 DEBUG iso8601.iso8601 [-] Got u'56' for 'minute'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.746 DEBUG iso8601.iso8601 [-] Got u'55' for 'second'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.746 DEBUG keystoneclient.middleware.auth_token [-]
Returning cached token e43bc16fc378342966f5fa99018a4dda from (pid=12701)
_cache_get
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:1024
2013-12-10 15:20:38.746 DEBUG keystoneclient.middleware.auth_token [-]
Received request from user: ba53467682e848da8381b3ce90af7c59 with
project_id : 77c29bbaa7234a7594a7a030a90a3021 and roles: admin from
(pid=12701) _build_user_headers
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:932
2013-12-10 15:20:38.747 DEBUG routes.middleware [-] Matched GET
/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
from (pid=12701) __call__
/usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-12-10 15:20:38.752 DEBUG routes.middleware [-] Route path:
'/{project_id}/volumes/:(id)', defaults: {'action': u'show', 'controller':
<cinder.api.openstack.wsgi.Resource object at 0x40f84d0>} from (pid=12701)
__call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-12-10 15:20:38.753 DEBUG routes.middleware [-] Match dict: {'action':
u'show', 'controller': <cinder.api.openstack.wsgi.Resource object at
0x40f84d0>, 'project_id': u'77c29bbaa7234a7594a7a030a90a3021', 'id':
u'95ae18ae-0300-4286-9848-9069e1d251e0'} from (pid=12701) __call__
/usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-12-10 15:20:38.753 INFO cinder.api.openstack.wsgi
[req-70468da2-0643-4df7-b2f7-086f9456f070 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] GET
http://192.168.56.106:8776/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
2013-12-10 15:20:38.755 DEBUG cinder.api.openstack.wsgi
[req-70468da2-0643-4df7-b2f7-086f9456f070 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] Unrecognized Content-Type provided in
request from (pid=12701) get_body
/opt/stack/cinder/cinder/api/openstack/wsgi.py:792
2013-12-10 15:20:38.816 AUDIT cinder.api.v1.volumes
[req-70468da2-0643-4df7-b2f7-086f9456f070 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] vol={'migration_status': None,
'availability_zone': u'nova', 'terminated_at': None, 'updated_at':
datetime.datetime(2013, 12, 10, 12, 57, 20), 'provider_geometry': None,
'snapshot_id': None, 'ec2_id': None, 'mountpoint': None, 'deleted_at':
None, 'id': u'95ae18ae-0300-4286-9848-9069e1d251e0', 'size': 1L, 'user_id':
u'ba53467682e848da8381b3ce90af7c59', 'attach_time': None, 'attached_host':
None, 'display_description': u'Persistent storage volume #1 for VM',
'volume_admin_metadata': [<cinder.db.sqlalchemy.models.VolumeAdminMetadata
object at 0x5249e10>], 'encryption_key_id': None, 'project_id':
u'77c29bbaa7234a7594a7a030a90a3021', 'launched_at': datetime.datetime(2013,
12, 10, 12, 24, 51), 'scheduled_at': datetime.datetime(2013, 12, 10, 12,
24, 27), 'status': u'detaching', 'volume_type_id': None, 'deleted': False,
'provider_location': u'192.168.56.106:3260,2
iqn.2010-10.org.openstack:volume-95ae18ae-0300-4286-9848-9069e1d251e0 1',
'host': u'lubuntu-VirtualBox', 'source_volid': None, 'provider_auth':
u'CHAP FHPtW6q3JMdQdB2aALco jthcvgQrCp2CGJZo5v54', 'display_name':
u'Storage volume one', 'instance_uuid': None, 'bootable': False,
'created_at': datetime.datetime(2013, 12, 10, 12, 24, 26), 'attach_status':
u'detached', 'volume_type': None, '_name_id': None, 'volume_metadata': [],
'metadata': {u'readonly': u'False'}}
2013-12-10 15:20:38.966 INFO cinder.api.openstack.wsgi
[req-70468da2-0643-4df7-b2f7-086f9456f070 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021]
http://192.168.56.106:8776/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0returned
with HTTP 200
2013-12-10 15:20:38.981 DEBUG keystoneclient.middleware.auth_token [-]
Authenticating user token from (pid=12701) __call__
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:568
2013-12-10 15:20:38.982 DEBUG keystoneclient.middleware.auth_token [-]
Removing headers from request environment:
X-Identity-Status,X-Domain-Id,X-Domain-Name,X-Project-Id,X-Project-Name,X-Project-Domain-Id,X-Project-Domain-Name,X-User-Id,X-User-Name,X-User-Domain-Id,X-User-Domain-Name,X-Roles,X-Service-Catalog,X-User,X-Tenant-Id,X-Tenant-Name,X-Tenant,X-Role
from (pid=12701) _remove_auth_headers
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:627
2013-12-10 15:20:38.983 DEBUG iso8601.iso8601 [-] Parsed
2013-12-11T12:56:55.000000Z into {'tz_sign': None, 'second_fraction':
u'000000', 'hour': u'12', 'tz_hour': None, 'month': u'12', 'timezone':
u'Z', 'second': u'55', 'tz_minute': None, 'year': u'2013', 'separator':
u'T', 'day': u'11', 'minute': u'56'} with default timezone
<iso8601.iso8601.Utc object at 0x279b490> from (pid=12701) parse_date
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:166
2013-12-10 15:20:38.984 DEBUG iso8601.iso8601 [-] Got u'2013' for 'year'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.984 DEBUG iso8601.iso8601 [-] Got u'12' for 'month'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.985 DEBUG iso8601.iso8601 [-] Got u'11' for 'day' with
default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.985 DEBUG iso8601.iso8601 [-] Got u'12' for 'hour' with
default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.985 DEBUG iso8601.iso8601 [-] Got u'56' for 'minute'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.985 DEBUG iso8601.iso8601 [-] Got u'55' for 'second'
with default None from (pid=12701) to_int
/usr/local/lib/python2.7/dist-packages/iso8601/iso8601.py:124
2013-12-10 15:20:38.985 DEBUG keystoneclient.middleware.auth_token [-]
Returning cached token e43bc16fc378342966f5fa99018a4dda from (pid=12701)
_cache_get
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:1024
2013-12-10 15:20:38.986 DEBUG keystoneclient.middleware.auth_token [-]
Received request from user: ba53467682e848da8381b3ce90af7c59 with
project_id : 77c29bbaa7234a7594a7a030a90a3021 and roles: admin from
(pid=12701) _build_user_headers
/opt/stack/python-keystoneclient/keystoneclient/middleware/auth_token.py:932
2013-12-10 15:20:38.987 DEBUG routes.middleware [-] Matched GET
/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
from (pid=12701) __call__
/usr/lib/python2.7/dist-packages/routes/middleware.py:100
2013-12-10 15:20:38.988 DEBUG routes.middleware [-] Route path:
'/{project_id}/volumes/:(id)', defaults: {'action': u'show', 'controller':
<cinder.api.openstack.wsgi.Resource object at 0x40f84d0>} from (pid=12701)
__call__ /usr/lib/python2.7/dist-packages/routes/middleware.py:102
2013-12-10 15:20:38.989 DEBUG routes.middleware [-] Match dict: {'action':
u'show', 'controller': <cinder.api.openstack.wsgi.Resource object at
0x40f84d0>, 'project_id': u'77c29bbaa7234a7594a7a030a90a3021', 'id':
u'95ae18ae-0300-4286-9848-9069e1d251e0'} from (pid=12701) __call__
/usr/lib/python2.7/dist-packages/routes/middleware.py:103
2013-12-10 15:20:38.989 INFO cinder.api.openstack.wsgi
[req-f41d3ab7-3bac-48c3-80d2-72a03749a2c3 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] GET
http://192.168.56.106:8776/v1/77c29bbaa7234a7594a7a030a90a3021/volumes/95ae18ae-0300-4286-9848-9069e1d251e0
2013-12-10 15:20:38.990 DEBUG cinder.api.openstack.wsgi
[req-f41d3ab7-3bac-48c3-80d2-72a03749a2c3 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021] Unrecognized Content-Type provided in
request from (pid=12701) get_body
/opt/stack/cinder/cinder/api/openstack/wsgi.py:792
2013-12-10 15:20:39.037 AUDIT cinder.api.v1.volumes
[req-f41d3ab7-3bac-48c3-80d2-72a03749a2c3 ba53467682e848da8381b3ce90af7c59
77c29bbaa7234a7594a7a030a90a3021
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.openstack.org/pipermail/openstack/attachments/20131210/12512734/attachment.html>
More information about the Openstack
mailing list