NeutronAdminCredentialConfigurationInvalid in n-cpu logs

[Matt Riedemann]

I've been seeing this all over the n-cpu logs in gate runs on master even in successful runs:

http://logs.openstack.org/08/418108/4/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/dafcfca/logs/screen-n-cpu.txt.gz?level=TRACE#_2017-01-12_17_05_25_061

2017-01-12 17:05:25.061 1236 ERROR nova.network.neutronv2.api [req-dfe387da-8f68-40f7-a781-9fec1f7408b1 tempest-ImagesTestJSON-2082975254 tempest-ImagesTestJSON-2082975254] Neutron client was not able to generate a valid admin token, please verify Neutron admin credential located in nova.conf

-----

http://logs.openstack.org/08/418108/4/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/dafcfca/logs/screen-n-cpu.txt.gz?level=TRACE#_2017-01-12_17_05_25_623

2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [req-dfe387da-8f68-40f7-a781-9fec1f7408b1 tempest-ImagesTestJSON-2082975254 tempest-ImagesTestJSON-2082975254] [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] Setting instance vm_state to ERROR
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] Traceback (most recent call last):
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2425, in do_terminate_instance
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._delete_instance(context, instance, bdms, quotas)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/hooks.py", line 154, in inner
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] rv = f(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2388, in _delete_instance
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] quotas.rollback()
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self.force_reraise()
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] six.reraise(self.type_, self.value, self.tb)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2352, in _delete_instance
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._shutdown_instance(context, instance, bdms)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2257, in _shutdown_instance
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._try_deallocate_network(context, instance, requested_networks)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2179, in _try_deallocate_network
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._set_instance_obj_error_state(context, instance)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 220, in __exit__
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self.force_reraise()
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/oslo_utils/excutils.py", line 196, in force_reraise
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] six.reraise(self.type_, self.value, self.tb)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 2173, in _try_deallocate_network
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._deallocate_network(context, instance, requested_networks)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/compute/manager.py", line 1667, in _deallocate_network
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] context, instance, requested_networks=requested_networks)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 1156, in deallocate_for_instance
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] data = neutron.list_ports(**search_opts)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] ret = obj(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 742, in list_ports
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] **_params)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] ret = obj(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 375, in list
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] for r in self._pagination(collection, path, **params):
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 390, in _pagination
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] res = self.get(path, params=params)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] ret = obj(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 360, in get
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] headers=headers, params=params)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] ret = obj(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 337, in retry_request
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] headers=headers, params=params)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 96, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] ret = obj(*args, **kwargs)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/usr/local/lib/python2.7/dist-packages/neutronclient/v2_0/client.py", line 300, in do_request
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] self._handle_fault_response(status_code, replybody, resp)
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] File "/opt/stack/new/nova/nova/network/neutronv2/api.py", line 112, in wrapper
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] raise exception.NeutronAdminCredentialConfigurationInvalid()
2017-01-12 17:05:25.157 1236 ERROR nova.compute.manager [instance: 4c7f8d12-2142-457c-b725-c95cf931cfa7] NeutronAdminCredentialConfigurationInvalid: Networking client is experiencing an unauthorized exception.

This is using an admin client connection to neutron so we should be regenerating a token for the admin so it's unclear why this is failing now.

http://logstash.openstack.org/#dashboard/file/logstash.json?query=message%3A%5C%22NeutronAdminCredentialConfigurationInvalid%3A%20Networking%20client%20is%20experiencing%20an%20unauthorized%20exception.%5C%22%20AND%20message%3A%5C%22deallocate_for_instance%5C%22%20AND%20tags%3A%5C%22screen-n-cpu.txt%5C%22%20AND%20voting%3A1&from=7d

[Matt Riedemann (mriedem)]

This is where the error comes from:

https://github.com/openstack/nova/blob/d62783eb069ac1aa1df30af17653394427263c24/nova/network/neutronv2/api.py#L105-L112

[Matt Riedemann (mriedem)]

It could somehow be related to this change in neutronclient:

https://review.openstack.org/#/q/b8a05333ddc4e248e18080750e3cfa9cbedbca53

[Matt Riedemann (mriedem)]

Ignore comment 2, that change to neutronclient in master hasn't been released yet.

[Matt Riedemann (mriedem)]

It could also be this: https://review.openstack.org/#/c/407147/

[Matt Riedemann (mriedem)]

I think this is the token request in the keystone logs:

req-6a68c08b-0993-4e32-a9f6-e47fa90c5ffd

And looking at:

http://logs.openstack.org/08/418108/4/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/dafcfca/logs/apache/keystone.txt.gz#_2017-01-12_17_05_25_050

This is the auth context:

{
   'is_delegated_auth':False,
   'access_token_id':None,
   'user_id':u'808414769ae84ea6907e692a87380188',
   'roles':[
      u'service'
   ],
   'user_domain_id':u'default',
   'consumer_id':None,
   'trustee_id':None,
   'is_domain':False,
   'is_admin_project':True,
   'trustor_id':None,
   'token':<KeystoneToken (audit_id=0-BLgjm3QcSgkoLXVJ7INw,
   audit_chain_id=0-BLgjm3QcSgkoLXVJ7INw) at 0x7fea446a7050>,
   'project_id':u'078441a1151d46a2810e59c2d6c417a5',
   'trust_id':None,
   'project_domain_id':u'default'
}

And then there is this:

http://logs.openstack.org/08/418108/4/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/dafcfca/logs/apache/keystone.txt.gz#_2017-01-12_17_05_25_056

2017-01-12 17:05:25.056 2916 WARNING keystone.common.wsgi [req-6a68c08b-0993-4e32-a9f6-e47fa90c5ffd 808414769ae84ea6907e692a87380188 078441a1151d46a2810e59c2d6c417a5 - default default] Could not find project: 2140f03492484f8580c440e5a999ac6e

But that's not the same project id above in the auth context (078441a1151d46a2810e59c2d6c417a5).

^ could all be a red herring too.

[Armando Migliaccio (armando-migliaccio)]

Seeing another instance here:

http://logs.openstack.org/04/379804/11/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/d11cfa5/logs/screen-n-cpu.txt.gz?level=TRACE

[Armando Migliaccio (armando-migliaccio)]

https://review.openstack.org/#/c/420220/

[Armando Migliaccio (armando-migliaccio)]

Can't seem to figure out from logstash when this has popped up, it seems to go way before the log retention.

[Armando Migliaccio (armando-migliaccio)]

There was at least one instance where the error led to a gate failure:

http://logs.openstack.org/04/379804/11/gate/gate-tempest-dsvm-neutron-src-neutron-lib-ubuntu-xenial/d11cfa5/logs/screen-n-cpu.txt.gz?level=TRACE#_2017-01-13_22_50_45_903

[Sai Sindhur Malleni (smalleni)]

I am seeing this when using TripleO to deploy OpenStack over a large number of nodes (125). Any information that I can grab for you?