Unable to authorize with keystone, fails to allocate floating IP

[Francis Ginther]

This was found with a Landscape Autopilot openstack deployment in CI: https://ci.lscape.net/job/landscape-system-tests/3803/

Test configuration:
SERVER_PPA=trunk, OPENSTACK_RELEASE=mitaka, OBJECT=ceph, BLOCK=iscsi, USE_NEXT_CHARMS=true, LDS=16.08~bzr10522+jenkins3023-2, JUJU=1.25.6-0ubuntu1.16.04.1, MAAS=1.9.4+bzr4592-0ubuntu1

The deployment of the openstack cloud was successful, but a test to perform a juju bootstrap within that cloud failed. Bootstrap failed with an error that indicated that multiple floating IPs had been allocated for the bootstrap node, however, the error was traced back to nova-api-os-compute being unable to allocate any floating IPs:

[From landscape-0-inner-logs/nova-cloud-controller-0/var/log/nova/nova-api-os-compute.log]
2016-09-13 13:24:59.957 68912 WARNING keystonemiddleware.auth_token [-] Using the in-process token cache is deprecated as of the 4.2.0 release and may be removed in the 5.0.0 release or the 'O' development cycle. The in-process cache causes inconsistent results and high memory usage. When the feature is removed the auth_token middleware will not cache tokens by default which may result in performance issues. It is recommended to use memcache for the auth_token token cache by setting the memcached_servers option.
2016-09-13 13:24:59.994 68912 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "The request you have made requires authentication.", "code": 401, "title": "Unauthorized"}}
2016-09-13 13:25:06.184 68913 WARNING nova.api.openstack.compute.floating_ips [req-5a764a92-7f7d-47a3-873a-3a8a88cf9770 d4c1ef115be343f3b0f867fb0be76c2d 6f1bdf0d6bdd4aec92f238c2f39dd88a - - -] [instance: ad500af0-5dc8-457f-83f1-097aec282a63] Info cache is InstanceInfoCache(created_at=2016-09-13T13:25:03Z,deleted=False,deleted_at=None,instance_uuid=ad500af0-5dc8-457f-83f1-097aec282a63,network_info=NetworkModel(),updated_at=None) during associate with no nw_info cache
2016-09-13 13:25:09.950 68911 ERROR nova.network.base_api [req-b38bd51c-c6f1-4e6a-bcf3-c18344c0bb34 d4c1ef115be343f3b0f867fb0be76c2d 6f1bdf0d6bdd4aec92f238c2f39dd88a - - -] [instance: ad500af0-5dc8-457f-83f1-097aec282a63] Failed storing info cache
...
Traceback
...
2016-09-13 13:25:09.955 68911 ERROR nova.api.openstack.compute.floating_ips [req-b38bd51c-c6f1-4e6a-bcf3-c18344c0bb34 d4c1ef115be343f3b0f867fb0be76c2d 6f1bdf0d6bdd4aec92f238c2f39dd88a - - -] Unable to associate floating IP 10.96.129.4 to fixed IP 10.10.0.3 for instance ad500af0-5dc8-457f-83f1-097aec282a63. Error: The request you have made requires authentication. (HTTP 401) (Request-ID: req-9e94cefb-c8a5-4145-b5ce-c65e3c9f09ce)

It's unclear to me how the nova instance didn't have the proper credentials to authenticate. I've attached logs from the keystone and nova-cloud-controller instances.

[David Britton (dpb)]

I hit this exact failure. Restarting all apache2 services on all keystone units fixed it. The weird thing is, keystone/2 was constantly erroring like this:

(keystone.common.wsgi): 2016-12-16 21:58:55,700 WARNING Authorization failed. The request you have made requires authentication. from 10.5.1.76
(keystone.common.controller): 2016-12-16 21:59:08,183 WARNING RBAC: Bypassing authorization
(keystone.common.wsgi): 2016-12-16 21:59:08,188 WARNING Could not find token: e1ab5fc118354edbad22a541a1ad4ff4
(keystone.common.wsgi): 2016-12-16 21:59:25,725 WARNING Authorization failed. The request you have made requires authentication. from 10.5.1.76
(keystone.common.wsgi): 2016-12-16 21:59:55,742 WARNING Authorization failed. The request you have made requires authentication. from 10.5.1.76
(keystone.common.controller): 2016-12-16 22:00:03,301 WARNING RBAC: Bypassing authorization

*BUT*

10.5.1.76 is actually keystone/0. That IP address was the only error in the logs. I'll attach logs from the keystone units.

[James Page (james-page)]

This sniffs like a single misconfigured/not restarted keystone unit in the cluster; I was hoping the log data might give us a hint, but the info attached in #3 is incomplete - all the log files are empty.

David - can you re-do that dump? or do we need to wait for another instance of this.

[James Page (james-page)]

Marking 'Incomplete' for now and 'Low' priority as we've only seen this bug twice in 3 months with no other similar bug reports.

[Launchpad Janitor (janitor)]

[Expired for OpenStack nova-cloud-controller charm because there has been no activity for 60 days.]

[Launchpad Janitor (janitor)]

[Expired for OpenStack keystone charm because there has been no activity for 60 days.]