metadata agent make invalid token requests

[Bjoern]

Sporadically the neutron metadata agent seems to return 401 wrapped up in a 404.
For still unknown reasons, the metadata agents creates sporadically invalid v3 token requests

2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent Unauthorized: {"error": {"message": "The resource could not be found.", "code": 404, "title": "Not Found"}}

POST /tokens HTTP/1.1
Host: 1.2.3.4:35357
Content-Length: 91
Accept-Encoding: gzip, deflate
Accept: application/json
User-Agent: python-neutronclient

and the response is

HTTP/1.1 404 Not Found
Date: Tue, 01 Mar 2016 22:14:58 GMT
Server: Apache
Vary: X-Auth-Token
Content-Length: 93
Content-Type: application/json

and the agent will stop responding with a full stack. At first we thought this issue would be related to a improper auth_url configuration (see https://bugs.launchpad.net/openstack-ansible/liberty/+bug/1552394) but the issue came back.
Interestingly the agent start working once we restart it but the problem slowly appears once you start putting more workload on it (spinning up instances)

2016-02-26 13:34:46.478 33371 INFO eventlet.wsgi.server [-] (33371) accepted ''
2016-02-26 13:34:46.486 33371 ERROR neutron.agent.metadata.agent [-] Unexpected error.
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent Traceback (most recent call last):
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 109, in __call__
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent instance_id, tenant_id = self._get_instance_and_tenant_id(req)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 204, in _get_instance_and_tenant_id
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent ports = self._get_ports(remote_address, network_id, router_id)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 197, in _get_ports
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent return self._get_ports_for_remote_address(remote_address, networks)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/common/utils.py", line 101, in __call__
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent return self._get_from_cache(target_self, *args, **kwargs)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/common/utils.py", line 79, in _get_from_cache
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent item = self.func(target_self, *args, **kwargs)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 166, in _get_ports_for_remote_address
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent ip_address=remote_address)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 135, in _get_ports_from_server
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent return self._get_ports_using_client(filters)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutron/agent/metadata/agent.py", line 177, in _get_ports_using_client
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent ports = client.list_ports(**filters)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 102, in with_params
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent ret = self.function(instance, *args, **kwargs)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 534, in list_ports
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent **_params)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 307, in list
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent for r in self._pagination(collection, path, **params):
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 320, in _pagination
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent res = self.get(path, params=params)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 293, in get
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent headers=headers, params=params)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 270, in retry_request
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent headers=headers, params=params)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 200, in do_request
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent content_type=self.content_type())
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 158, in do_request
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent self.authenticate_and_fetch_endpoint_url()
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 123, in authenticate_and_fetch_endpoint_url
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent self.authenticate()
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 237, in authenticate
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent self._authenticate_keystone()
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent File "/usr/local/lib/python2.7/dist-packages/neutronclient/client.py", line 218, in _authenticate_keystone
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent raise exceptions.Unauthorized(message=resp_body)
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent Unauthorized: {"error": {"message": "The resource could not be found.", "code": 404, "title": "Not Found"}}
2016-02-26 13:34:46.486 33371 TRACE neutron.agent.metadata.agent

[Bernard Cafarelli (bcafarel)]

From the trace, it looks like for these requests, the agent is using the fallback to neutron client (probably a temporary issue). As you had problems on auth_url configurations, maybe it is still incorrect for neutronclient?

[Bjoern (bjoern-t)]

What we have analyzed so far:

We have a customer that launches roughly 700 (usually more) instances at
once for burst workloads on OpenStack Ansible Kilo. When they do,
Neutron Metadata Agent starts returning 500 errors.

We spent many hours tracking the source of the 500 errors and we have
found *one part* of the root cause. Here's what happens:

In Kilo Neutron Metadata Agent (henceforth known as NMA), attempts to
talk to Neutron API over RPC (in OSA's case Rabbit MQ). If that fails,
it then attempts to use Neutronclient to talk to it over HTTP.

In /etc/neutron/metadata-agent.ini we have auth_url =
https://<internalvip>:35357/v3 for Keystone, but if you follow the code
path through Neutronclient, it is using internal code that *only* works
on Keystone v2. This means that the HTTP fallback ends up receiving a
404 from Keystone which causes an unhandled exception in Neutron.

The mitigation for this is to fix the auth_url in metadata-agent.ini to
use /v2.0 instead of /v3.

I looked at Neutron and Neutronclient on stable/liberty and they both
have the *same* problem and roughly the same code path.

Naturally, this doesn't solve whatever is causing Rabbit connection
problems from NMA *but* this does fix the 500 errors because NMA can
successfully fallback to HTTP using neutronclient.

[Bernard Cafarelli (bcafarel)]

What is your auth_url endpoint? fallback uses v2.0 neutronclient only

[Ian Cordasco (icordasc)]

Bjoern I've worked with Paul and determined that the configuration was incorrect.