7:19 a.m.
you can find the rest of heat logs attached. I launched the stack at
14:02:45.
2015-05-07 14:08 GMT+02:00 ICHIBA Sara <ichi.sara(a)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/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
>