[Rdo-list] [heat]: stack stays interminably under the status create in progress

Thu May 7 23:31:15 UTC 2015

Kilo heat works in Kolla.  So this must be a configuration problem.

I noticed your logs have an authentication failed issue.

Recommend filing a bug against the RDO project (under community) on bugzilla.redhat.com

Regards
-steve

From: ICHIBA Sara <ichi.sara at gmail.com<mailto:ichi.sara at gmail.com>>
Date: Thursday, May 7, 2015 at 5:41 AM
To: Steven Hardy <shardy at redhat.com<mailto:shardy at redhat.com>>, "rdo-list at redhat.com<mailto:rdo-list at redhat.com>" <rdo-list at redhat.com<mailto:rdo-list at redhat.com>>
Subject: Re: [Rdo-list] [heat]: stack stays interminably under the status create in progress

I found this
https://bugs.launchpad.net/heat/+bug/1405110 . Apparently i'm not the only one to have this problem

2015-05-07 14:26 GMT+02:00 ICHIBA Sara <ichi.sara at gmail.com<mailto:ichi.sara at gmail.com>>:

2015-05-07 14:08 GMT+02:00 ICHIBA Sara <ichi.sara at gmail.com<mailto:ichi.sara at gmail.com>>:
Actually, Nova is working I just spawned a VM with  the same flavor  and image. and when I try to do the same with heat it fails. below some logs:

nova-compute.log

2015-05-07 13:58:56.208 3928 AUDIT nova.compute.manager [req-b57bfc38-9d77-48fc-8185-474d1f9076a6 None] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Starting instance...
2015-05-07 13:58:56.376 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Attempting claim: memory 512 MB, disk 1 GB
2015-05-07 13:58:56.376 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Total memory: 3791 MB, used: 512.00 MB
2015-05-07 13:58:56.377 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] memory limit: 5686.50 MB, free: 5174.50 MB
2015-05-07 13:58:56.377 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Total disk: 13 GB, used: 0.00 GB
2015-05-07 13:58:56.378 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] disk limit not specified, defaulting to unlimited
2015-05-07 13:58:56.395 3928 AUDIT nova.compute.claims [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Claim successful
2015-05-07 13:58:56.590 3928 INFO nova.scheduler.client.report [-] Compute_service record updated for ('localhost.localdomain', 'localhost.localdomain')
2015-05-07 13:58:56.787 3928 INFO nova.scheduler.client.report [-] Compute_service record updated for ('localhost.localdomain', 'localhost.localdomain')
2015-05-07 13:58:57.269 3928 INFO nova.virt.libvirt.driver [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Creating image
2015-05-07 13:59:27.642 3928 INFO oslo.messaging._drivers.impl_rabbit [-] Connecting to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>
2015-05-07 13:59:27.661 3928 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2015-05-07 13:59:27.702 3928 INFO oslo.messaging._drivers.impl_rabbit [-] Connected to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>
2015-05-07 13:59:27.800 3928 INFO nova.scheduler.client.report [-] Compute_service record updated for ('localhost.localdomain', 'localhost.localdomain')
2015-05-07 13:59:28.066 3928 AUDIT nova.compute.resource_tracker [-] Total physical ram (MB): 3791, total allocated virtual ram (MB): 1024
2015-05-07 13:59:28.066 3928 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 12
2015-05-07 13:59:28.067 3928 AUDIT nova.compute.resource_tracker [-] Total usable vcpus: 4, total allocated vcpus: 0
2015-05-07 13:59:28.067 3928 AUDIT nova.compute.resource_tracker [-] PCI stats: []
2015-05-07 13:59:28.101 3928 INFO nova.scheduler.client.report [-] Compute_service record updated for ('localhost.localdomain', 'localhost.localdomain')
2015-05-07 13:59:28.101 3928 INFO nova.compute.resource_tracker [-] Compute_service record updated for localhost.localdomain:localhost.localdomain
2015-05-07 13:59:47.110 3928 WARNING nova.virt.disk.vfs.guestfs [-] Failed to close augeas aug_close: do_aug_close: you must call 'aug-init' first to initialize Augeas
2015-05-07 13:59:51.364 3928 INFO nova.compute.manager [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] VM Started (Lifecycle Event)
2015-05-07 13:59:51.384 3928 INFO nova.virt.libvirt.driver [-] [instance: 399c6150-2877-4c5f-865f-c7ac4c5c7ed5] Instance spawned successfully.
2015-05-07 14:00:28.264 3928 AUDIT nova.compute.resource_tracker [-] Auditing locally available compute resources
2015-05-07 14:00:29.007 3928 AUDIT nova.compute.resource_tracker [-] Total physical ram (MB): 3791, total allocated virtual ram (MB): 1024
2015-05-07 14:00:29.008 3928 AUDIT nova.compute.resource_tracker [-] Free disk (GB): 12
2015-05-07 14:00:29.009 3928 AUDIT nova.compute.resource_tracker [-] Total usable vcpus: 4, total allocated vcpus: 1
2015-05-07 14:00:29.009 3928 AUDIT nova.compute.resource_tracker [-] PCI stats: []
2015-05-07 14:00:29.048 3928 INFO nova.scheduler.client.report [-] Compute_service record updated for ('localhost.localdomain', 'localhost.localdomain')
2015-05-07 14:00:29.048 3928 INFO nova.compute.resource_tracker [-] Compute_service record updated for localhost.localdomain:localhost.localdomain

heat-engine.log

2015-05-07 14:02:45.177 3942 INFO heat.engine.service [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] Creating stack my_first_stack
2015-05-07 14:02:45.194 3942 DEBUG stevedore.extension [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] found extension EntryPoint.parse('AWSTemplateFormatVersion.2010-09-09 = heat.engine.cfn.template:CfnTemplate') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156
2015-05-07 14:02:45.194 3942 DEBUG stevedore.extension [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] found extension EntryPoint.parse('heat_template_version.2013-05-23 = heat.engine.hot.template:HOTemplate20130523') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156
2015-05-07 14:02:45.195 3942 DEBUG stevedore.extension [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] found extension EntryPoint.parse('HeatTemplateFormatVersion.2012-12-12 = heat.engine.cfn.template:HeatTemplate') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156
2015-05-07 14:02:45.195 3942 DEBUG stevedore.extension [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] found extension EntryPoint.parse('heat_template_version.2014-10-16 = heat.engine.hot.template:HOTemplate20141016') _load_plugins /usr/lib/python2.7/site-packages/stevedore/extension.py:156
2015-05-07 14:02:45.224 3942 DEBUG heat.engine.parameter_groups [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] <heat.engine.hot.template.HOTemplate20130523 object at 0x38d05d0> __init__ /usr/lib/python2.7/site-packages/heat/engine/parameter_groups.py:31
2015-05-07 14:02:45.225 3942 DEBUG heat.engine.parameter_groups [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] <heat.engine.hot.parameters.HOTParameters object at 0x3a695d0> __init__ /usr/lib/python2.7/site-packages/heat/engine/parameter_groups.py:32
2015-05-07 14:02:45.225 3942 DEBUG heat.engine.parameter_groups [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] Validating Parameter Groups. validate /usr/lib/python2.7/site-packages/heat/engine/parameter_groups.py:43
2015-05-07 14:02:45.226 3942 DEBUG heat.engine.parameter_groups [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] ['OS::stack_id'] validate /usr/lib/python2.7/site-packages/heat/engine/parameter_groups.py:44
2015-05-07 14:02:45.233 3942 INFO heat.engine.resource [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] Validating Server "my_instance"
2015-05-07 14:02:45.385 3942 DEBUG heat.common.keystoneclient [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 None] Using stack domain 9ce7896d79914b68aef34d397fd3fde4 __init__ /usr/lib/python2.7/site-packages/heat/common/heat_keystoneclient.py:115
2015-05-07 14:02:45.405 3942 INFO urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] Starting new HTTP connection (1): 192.168.5.33
2015-05-07 14:02:45.448 3942 DEBUG urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] "GET /v2/fac261cd98974411a9b2e977cd9ec876/os-keypairs/userkey HTTP/1.1" 200 674 _make_request /usr/lib/python2.7/site-packages/urllib3/connectionpool.py:357
2015-05-07 14:02:45.486 3942 DEBUG glanceclient.common.http [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] curl -i -X GET -H 'User-Agent: python-glanceclient' -H 'Content-Type: application/octet-stream' -H 'Accept-Encoding: gzip, deflate' -H 'Accept: */*' -H 'X-Auth-Token: {SHA1}bc08e056cd78f34e9ada3dd99ceae37d33daf3f0' http://192.168.5.33:9292/v1/images/detail?limit=20&name=cirros log_curl_request /usr/lib/python2.7/site-packages/glanceclient/common/http.py:122
2015-05-07 14:02:45.488 3942 INFO urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] Starting new HTTP connection (1): 192.168.5.33
2015-05-07 14:02:45.770 3942 DEBUG urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] "GET /v1/images/detail?limit=20&name=cirros HTTP/1.1" 200 481 _make_request /usr/lib/python2.7/site-packages/urllib3/connectionpool.py:357
2015-05-07 14:02:45.771 3942 DEBUG glanceclient.common.http [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ]
HTTP/1.1 200 OK
date: Thu, 07 May 2015 12:02:45 GMT
content-length: 481
content-type: application/json; charset=UTF-8
x-openstack-request-id: req-c62b407b-0d8f-43c6-a8be-df02015dc846

{"images": [{"status": "active", "deleted_at": null, "name": "cirros", "deleted": false, "container_format": "bare", "created_at": "2015-05-06T14:27:54", "disk_format": "qcow2", "updated_at": "2015-05-06T15:01:15", "min_disk": 0, "protected": false, "id": "d80b5a24-2567-438f-89f8-b381a6716887", "min_ram": 0, "checksum": "133eae9fb1c98f45894a4e60d8736619", "owner": "3740df0f18754509a252738385d375b9", "is_public": true, "virtual_size": null, "properties": {}, "size": 13200896}]}
 log_http_response /usr/lib/python2.7/site-packages/glanceclient/common/http.py:135
2015-05-07 14:02:46.049 3942 DEBUG keystoneclient.auth.identity.v3 [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] Making authentication request to http://192.168.5.33:35357/v3/auth/tokens get_auth_ref /usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v3.py:117
2015-05-07 14:02:46.052 3942 INFO urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] Starting new HTTP connection (1): 192.168.5.33
2015-05-07 14:02:46.247 3942 DEBUG urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] "POST /v3/auth/tokens HTTP/1.1" 201 8275 _make_request /usr/lib/python2.7/site-packages/urllib3/connectionpool.py:357
2015-05-07 14:02:46.250 3942 DEBUG keystoneclient.session [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] REQ: curl -i -X POST http://192.168.5.33:35357/v3/OS-TRUST/trusts -H "User-Agent: python-keystoneclient" -H "Content-Type: application/json" -H "X-Auth-Token: TOKEN_REDACTED" -d '{"trust": {"impersonation": true, "project_id": "fac261cd98974411a9b2e977cd9ec876", "trustor_user_id": "24f6dac3f1444d89884c1b1977bb0d87", "roles": [{"name": "heat_stack_owner"}], "trustee_user_id": "4f7e2e76441e483982fb863ed02fe63e"}}' _http_log_request /usr/lib/python2.7/site-packages/keystoneclient/session.py:155
2015-05-07 14:02:46.252 3942 INFO urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] Starting new HTTP connection (1): 192.168.5.33
2015-05-07 14:02:46.381 3942 DEBUG urllib3.connectionpool [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] "POST /v3/OS-TRUST/trusts HTTP/1.1" 201 717 _make_request /usr/lib/python2.7/site-packages/urllib3/connectionpool.py:357
2015-05-07 14:02:46.383 3942 DEBUG keystoneclient.session [req-6b9bcd97-7a13-4bc3-984c-470e6f5949b9 ] RESP: [201] {'content-length': '717', 'vary': 'X-Auth-Token', 'server': 'Apache/2.4.6 (CentOS)', 'connection': 'close', 'date': 'Thu, 07 May 2015 12:02:46 GMT', 'content-type': 'application/json'}
RESP BODY: {"trust": {"impersonation": true, "roles_links": {"self": "http://192.168.5.33:35357/v3/OS-TRUST/trusts/96e0e32b7c504d3f8f9b82fcc2658e5f/roles", "previous": null, "next": null}, "deleted_at": null, "trustor_user_id": "24f6dac3f1444d89884c1b1977bb0d87", "links": {"self": "http://192.168.5.33:35357/v3/OS-TRUST/trusts/96e0e32b7c504d3f8f9b82fcc2658e5f"}, "roles": [{"id": "cf346090e5a042ebac674bcfe14f4076", "links": {"self": "http://192.168.5.33:35357/v3/roles/cf346090e5a042ebac674bcfe14f4076"}, "name": "heat_stack_owner"}], "remaining_uses": null, "expires_at": null, "trustee_user_id": "4f7e2e76441e483982fb863ed02fe63e", "project_id": "fac261cd98974411a9b2e977cd9ec876", "id": "96e0e32b7c504d3f8f9b82fcc2658e5f"}}
 _http_log_response /usr/lib/python2.7/site-packages/keystoneclient/session.py:182
2015-05-07 14:02:46.454 3942 DEBUG heat.engine.stack_lock [-] Engine b3d3b0e1-5c47-4912-94e9-1b75159b9b10 acquired lock on stack bb7d16c4-b73f-428d-9dbd-5b089748f374 acquire /usr/lib/python2.7/site-packages/heat/engine/stack_lock.py:72
2015-05-07 14:02:46.456 3942 INFO oslo.messaging._drivers.impl_rabbit [-] Connecting to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>
2015-05-07 14:02:46.474 3942 DEBUG keystoneclient.auth.identity.v3 [-] Making authentication request to http://192.168.5.33:35357/v3/auth/tokens get_auth_ref /usr/lib/python2.7/site-packages/keystoneclient/auth/identity/v3.py:117
2015-05-07 14:02:46.477 3942 INFO urllib3.connectionpool [-] Starting new HTTP connection (1): 192.168.5.33
2015-05-07 14:02:46.481 3942 INFO oslo.messaging._drivers.impl_rabbit [-] Connected to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>
2015-05-07 14:02:46.666 3942 DEBUG urllib3.connectionpool [-] "POST /v3/auth/tokens HTTP/1.1" 401 114 _make_request /usr/lib/python2.7/site-packages/urllib3/connectionpool.py:357
2015-05-07 14:02:46.668 3942 DEBUG keystoneclient.session [-] Request returned failure status: 401 request /usr/lib/python2.7/site-packages/keystoneclient/session.py:345
2015-05-07 14:02:46.668 3942 DEBUG keystoneclient.v3.client [-] Authorization failed. get_raw_token_from_identity_service /usr/lib/python2.7/site-packages/keystoneclient/v3/client.py:267
2015-05-07 14:02:46.673 3942 DEBUG heat.engine.stack_lock [-] Engine b3d3b0e1-5c47-4912-94e9-1b75159b9b10 released lock on stack bb7d16c4-b73f-428d-9dbd-5b089748f374 release /usr/lib/python2.7/site-packages/heat/engine/stack_lock.py:122
2015-05-07 14:03:33.623 3942 INFO oslo.messaging._drivers.impl_rabbit [req-18ad2c0b-ab52-4793-99a5-255a010d83fe ] Connecting to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>
2015-05-07 14:03:33.645 3942 INFO oslo.messaging._drivers.impl_rabbit [req-18ad2c0b-ab52-4793-99a5-255a010d83fe ] Connected to AMQP server on 192.168.5.33:5672<http://192.168.5.33:5672>

2015-05-07 11:45 GMT+02:00 Steven Hardy <shardy at redhat.com<mailto:shardy at redhat.com>>:
On Tue, May 05, 2015 at 01:18:17PM +0200, ICHIBA Sara wrote:
>    hello,
>
>    here is my HOT template, it's very basic:
>
>    heat_template_version: 2013-05-23
>
>    description: Simple template to deploy a single compute instance
>
>    resources:
>    A  my_instance:
>    A A A  type: OS::Nova::Server
>    A A A  properties:
>    A A A A A  image: Cirros 0.3.3
>    A A A A A  flavor: m1.small
>    A A A A A  key_name: userkey
>    A A A A A  networks:
>    A A A A A A A  - network: fdf2bb77-a828-401d-969a-736a8028950f
>
>    for the logs please find them attached.

These logs are a little confusing - it looks like you failed to create the
stack due to some validation errors, then tried again and did a stack-check
and a stack resume?

Can you please set debug = True in the [DEFAULT] section of your heat.conf,
restart heat-engine and try again please?

Also, some basic checks are:

1. When the stack is CREATE_IN_PROGRESS, what does nova list show for the
instance?

2. Is it possible to boot an instance using nova boot, using the same
arguments (image, flavor, key etc) that you specify in the heat template?

I suspect that Heat is not actually the problem here, and that some part of
Nova is either misconfigured or not running, but I can't prove that without
seeing the nova CLI output and/or the nova logs.

Steve

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.rdoproject.org/pipermail/dev/attachments/20150507/4bbd0daa/attachment.html>