Hitting "Authentication required" on migration when building network info model (token expired)

[Ludovic Beliveau]

Description
===========

I observed this issue a few times, mainly while doing stress testing of cold migration.

Neutron returns this error (see stack trace):
Unauthorized: Authentication required

Steps to reproduce
==================

1) Boot multiple vms (5-6)
2) Stress test cold migration: migrate all vms, once confirmed, redo again, over and over

Actual result
=============

2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] Traceback (most recent call last):
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 4271, in finish_resize
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] disk_info, image_meta)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/compute/manager.py", line 4210, in _finish_resize
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] network_info = self.network_api.get_instance_nw_info(context, instance)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/network/base_api.py", line 253, in get_instance_nw_info
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] result = self._get_instance_nw_info(context, instance, **kwargs)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 994, in _get_instance_nw_info
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] preexisting_port_ids)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1787, in _build_network_info_model
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] context, instance, networks, port_ids)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 1017, in _gather_port_ids_and_networks
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] net_ids)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/nova/network/neutronv2/api.py", line 207, in _get_available_networks
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] nets = neutron.list_networks(**search_opts).get('networks', [])
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 105, in with_params
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] ret = self.function(instance, *args, **kwargs)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 730, in list_networks
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] **_params)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 384, in list
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] for r in self._pagination(collection, path, **params):
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 399, in _pagination
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] res = self.get(path, params=params)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 369, in get
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] headers=headers, params=params)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 346, in retry_request
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] headers=headers, params=params)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 309, in do_request
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] self._handle_fault_response(status_code, replybody, resp)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 284, in _handle_fault_response
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] exception_handler_v20(status_code, error_body)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] File "/usr/lib/python2.7/site-packages/neutronclient/v2_0/client.py", line 92, in exception_handler_v20
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] request_ids=request_ids)
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] Unauthorized: Authentication required
2016-09-02 13:53:14.887 61968 ERROR nova.compute.manager [instance: da6e6dd9-6042-478f-9886-c88d332eb4e3] Neutron server returns request_ids: ['req-ad48fbe3-8405-4393-9251-ca5fa20c9653']

Environment
===========

Mitaka

[Sean Dague (sdague)]

How long does any individual migration take to occur? (longest time)

Are you getting new tokens before each API call, or are you running with tokens that you keep recycling?

[Sean Dague (sdague)]

It is a known problem that when talking to services on a user's behalf (such as glance, cinder, neutron) and using a Token, that it could expire when making sub requests on behalf of the user. By default Keystone Token expiration time is 1 hour.

There is no definitive solution at this point for this problem. A number of ideas have been discussed during summit sessions around non expiring token types (would need keystone changes). However we may want to decide that for some class of known long standing operations that Nova will reject them if the token expiration is too close (much like traveling on a passport that is near expiration). That may be able to mitigate this.

[Ludovic Beliveau (ludovic-beliveau)]

As a side note, I came across this havana commit that fixed a similar issue (but it's not clear at this point if this would fix this particular issue: https://review.openstack.org/#/c/54736

[Ludovic Beliveau (ludovic-beliveau)]

Sean, to answer your question, even when executing multiple migrations in parallel (actually 4 vms migrating at the same time, over and over), the longest migration I have observed took around 30 secs. to execute.

Also, looks like this might be related to the fact when using the CLI, a new token is used. But when using horizon, I see the same token being recycled.

[Sean Dague (sdague)]

This is a long standing issue with Keystone architecture. There is no real fix at this stage. The work around is to increase token timeouts in keystone.