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

Thu May 7 12:26:04 UTC 2015

2015-05-07 14:08 GMT+02:00 ICHIBA Sara <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
> 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
> 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
> 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
> 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
> 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
>
>
>
>
>
> 2015-05-07 11:45 GMT+02:00 Steven Hardy <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/2104012f/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: heat-api.log
Type: application/octet-stream
Size: 15383632 bytes
Desc: not available
URL: <http://lists.rdoproject.org/pipermail/dev/attachments/20150507/2104012f/attachment.obj>