7:08 a.m.
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/96e0e32b7c504d3f8f9b82fcc265...;,
"previous": null, "next": null}, "deleted_at": null,
"trustor_user_id":
"24f6dac3f1444d89884c1b1977bb0d87", "links": {"self":
"
http://192.168.5.33:35357/v3/OS-TRUST/trusts/96e0e32b7c504d3f8f9b82fcc265...,
"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(a)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