heat networking auto-discovery causes heat-engine to exit

[Gregory Haynes]

All our novabm-overcloud-f20-nonha jobs are failing with a heat authorization failure on stack-create.

console.log:

2014-08-28 16:02:49.718 | + heat stack-create -e /opt/stack/new//overcloud-env.json -t 360 -f /opt/stack/new//tripleo-heat-templates/overcloud.yaml -P ExtraConfig= overcloud
2014-08-28 16:03:50.859 | ERROR: Timed out waiting for a reply to message ID 1e164e966fff49e7977d086c72156727

heat-engine.log:

Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 CRITICAL heat [req-ee2ec386-644c-43e0-b4ff-6dcd410a90b8 None] Unauthorized: The request you have made requires authentication. (HTTP 401)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat Traceback (most recent call last):
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/bin/heat-engine", line 72, in
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat discover_networking_service()
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/bin/heat-engine", line 56, in discover_networking_service
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat admin_client = hkc.KeystoneClient(ctxt).admin_client
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/heat/common/heat_keystoneclient.py", line 128, in admin_client
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat if c.authenticate():
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat return func(*args, **kwargs)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/httpclient.py", line 425, in authenticate
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat resp = self.get_raw_token_from_identity_service(**kwargs)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/v3/client.py", line 258, in get_raw_token_from_identity_service
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat return plugin.get_auth_ref(self.session)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/auth/identity/v3.py", line 115, in get_auth_ref
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat authenticated=False, log=False)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/session.py", line 389, in post
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat return self.request(url, 'POST', **kwargs)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/utils.py", line 318, in inner
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat return func(*args, **kwargs)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystoneclient/session.py", line 330, in request
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat raise exceptions.from_response(resp, method, url)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat Unauthorized: The request you have made requires authentication. (HTTP 401)
Aug 28 15:27:10 host-192-168-1-108 heat-engine[3044]: 2014-08-28 15:27:10.035 3044 TRACE heat
Aug 28 15:27:11 host-192-168-1-108 systemd[1]: heat-engine.service: main process exited, code=exited, status=1/FAILURE
Aug 28 15:27:11 host-192-168-1-108 systemd[1]: Unit heat-engine.service entered failed state.

keystone.log:

Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 ERROR keystone.auth.controllers [-] Could not find project: service
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers Traceback (most recent call last):
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystone/auth/controllers.py", line 202, in _lookup_project
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers project_name, domain_ref['id'])
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/cache/region.py", line 1013, in decorate
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers should_cache_fn)
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/cache/region.py", line 640, in get_or_create
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers async_creator) as value:
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 158, in __enter__
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers return self._enter()
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 98, in _enter
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers generated = self._enter_create(createdtime)
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/core/dogpile.py", line 149, in _enter_create
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers created = self.creator()
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/cache/region.py", line 612, in gen_value
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers created_value = creator()
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/dogpile/cache/region.py", line 1009, in creator
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers return fn(*arg, **kw)
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystone/assignment/core.py", line 466, in get_project_by_name
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers return self.driver.get_project_by_name(tenant_name, domain_id)
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers File "/opt/stack/venvs/openstack/lib/python2.7/site-packages/keystone/assignment/backends/sql.py", line 56, in get_project_by_name
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers raise exception.ProjectNotFound(project_id=tenant_name)
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers ProjectNotFound: Could not find project: service
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 TRACE keystone.auth.controllers
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:10.016 2826 WARNING keystone.common.wsgi [-] Authorization failed. The request you have made requires authentication. from 127.0.0.1

[Robert Collins (lifeless)]

Looking in keystone log:
Aug 28 15:27:10 host-192-168-1-108 keystone-all[2826]: 2014-08-28 15:27:09.955 2826 ERROR keystone.auth.controllers [-] Could not find project: service

The service tenant/project is created once heat signals stack ready by os-cloud-config // tuskar. This error being returned to heat-engine should not kill the service. Sure, it can't serve responses, but it can't fail to start just because keystone isn't usable /right then/.

[Robert Collins (lifeless)]

Oh - and I suspect this autodetection will fail entirely for TripleO even once thats fixed, because keystone will initially be empty, and then will get populated.

So we probably need to set the config option to match our deployment - but one-time autodetection like this seems like a bad idea IMNSHO.

Likewise, when dealing with federated clouds, won't a single global value for 'networking impl' be problematic?

[Steve Baker (steve-stevebaker)]

This is the problem commit:
https://review.openstack.org/#/c/115968/6
Keystone may not be up when heat-engine is started, so this is a race which doesn't occur on devstack but does on tripleo.

I think autodiscovery needs to be moved to Resource.is_using_neutron. It only ever gets called with a valid context, which should already have a service catalog, so it will be a simple matter of:

    def is_using_neutron(self):
        try:
            self.client('neutron')
        except Exception:
            return False
        else:
            return True

which means the rest of https://review.openstack.org/#/c/115968/6 can be reverted, including the autodiscovery *and* the config options which lifeless points out could also be problematic.

[Zane Bitter (zaneb)]

> Likewise, when dealing with federated clouds, won't a single global value for 'networking impl' be problematic?

Unlikely; Heat already assumes that separate Regions run separate engines. I assume that federated clouds won't include a single region that spans multiple clouds.

[OpenStack Infra (hudson-openstack)]

Fix proposed to branch: master
Review: https://review.openstack.org/117646

[OpenStack Infra (hudson-openstack)]

Reviewed: https://review.openstack.org/117646
Committed: https://git.openstack.org/cgit/openstack/heat/commit/?id=d70da16894187d4f029e4352b4103cb629ebdaaf
Submitter: Jenkins
Branch: master

commit d70da16894187d4f029e4352b4103cb629ebdaaf
Author: Steve Baker <email address hidden>
Date: Fri Aug 29 11:11:59 2014 +1200

    Detect neutron endpoint on-the-fly

    This change does the following:
    - reverts commit 04de60093b602c2eac4a612df5d4a2e31424a25d
    - reimplements Resource.is_using_neutron to check for neutron by
      attempting to create a neutron client
    - fix mocking in tests for changes which landed after 04de600

    If there is no 'network' entry in the service catalog then
    keystoneclient will raise an EndpointNotFound. The context will
    already have a keystone client cached which has a full service catalog
    locally, so calling is_using_neutron should have no particular overhead.

    This fixes a tripleo regression where the autodetection is triggered
    before keystone is ready, so that heat-engine fails to start. This
    race does not affect devstack as keystone is fully configured before
    heat services are started.

    Not adding config option networking_service will also prevent
    extra work required by downstream installation tools.

    Change-Id: I45a6154fa560f672d8d1942bf57f39601110bfc6
    Closes-Bug: #1362812

[James Polley (tchaypo)]

This was fixed in Heat.