Congress periodically polls openstack services to obtain data.
When an authentication token expires, Congress catches the error and sets a refreshed token (for Glance, Ironic, and Murano). That way, subsequent polls should succeed until the new token expires and gets refreshed (implementation: https://review.openstack.org/#/c/160063/).
The mechanism works fine for Ironic and Murano, but the refresh does not appear to work for Glance. Congress gets a new token from keystone and sets glanceclient/v2/client.py:Client.http_client.auth_token to the new token, but according to Glance log, Glance continues to use the same expired client. Strangely, the same request id is also repeated on each new authentication attempt (see partial log below).
Perhaps there is some kind of caching on the Glance side that causes Glance to re-use the information from an older authentication request.
Perhaps the way Congress sets a new token isn’t supported by glanceclient?
I am not sure whether it's a Congress bug or a Glance bug, so I'm filing this report and hoping someone could provide more insight. Thanks!
Partial Glance log (g-api.log) showing repeated failed authentication with same token (fb9f6586046d470f8ce3535f6a10e5d7) and same req id (req-e37fbe6b-46ae-441c-97fb-d2bc764eced3):
// Running Glance master commit 39c327fa6d345625d12cc56f7ad5f0a4ceba3d8f with Devstack
2016-03-28 21:24:09.294 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mDetermining version of request: GET /v2/images Accept: */*[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:46[00m
2016-03-28 21:24:09.294 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mUsing url versioning[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:58[00m
2016-03-28 21:24:09.294 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mMatched version: v2[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70[00m
2016-03-28 21:24:09.294 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mnew path /v2/images[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:71[00m
2016-03-28 21:24:09.315 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:09.315 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mIdentity response: {"error": {"message": "Could not find token: fb9f6586046d470f8ce3535f6a10e5d7", "code": 404, "title": "Not Found"}}[00m
2016-03-28 21:24:09.315 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:09.316 [00;36mINFO eventlet.wsgi.server [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;36m] [01;35m[00;36m192.168.218.145 - - [28/Mar/2016 21:24:09] "GET /v2/images?limit=20 HTTP/1.1" 401 571 0.022925[00m
2016-03-28 21:24:19.449 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mDetermining version of request: GET /v2/images Accept: */*[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:46[00m
2016-03-28 21:24:19.450 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mUsing url versioning[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:58[00m
2016-03-28 21:24:19.450 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mMatched version: v2[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70[00m
2016-03-28 21:24:19.450 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mnew path /v2/images[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:71[00m
2016-03-28 21:24:19.473 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:19.474 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mIdentity response: {"error": {"message": "Could not find token: fb9f6586046d470f8ce3535f6a10e5d7", "code": 404, "title": "Not Found"}}[00m
2016-03-28 21:24:19.474 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:19.475 [00;36mINFO eventlet.wsgi.server [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;36m] [01;35m[00;36m192.168.218.145 - - [28/Mar/2016 21:24:19] "GET /v2/images?limit=20 HTTP/1.1" 401 571 0.026222[00m
2016-03-28 21:24:29.587 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mDetermining version of request: GET /v2/images Accept: */*[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:46[00m
2016-03-28 21:24:29.587 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mUsing url versioning[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:58[00m
2016-03-28 21:24:29.587 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mMatched version: v2[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70[00m
2016-03-28 21:24:29.587 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mnew path /v2/images[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:71[00m
2016-03-28 21:24:29.606 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:29.606 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mIdentity response: {"error": {"message": "Could not find token: fb9f6586046d470f8ce3535f6a10e5d7", "code": 404, "title": "Not Found"}}[00m
2016-03-28 21:24:29.606 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:29.607 [00;36mINFO eventlet.wsgi.server [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;36m] [01;35m[00;36m192.168.218.145 - - [28/Mar/2016 21:24:29] "GET /v2/images?limit=20 HTTP/1.1" 401 571 0.020783[00m
2016-03-28 21:24:39.691 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mDetermining version of request: GET /v2/images Accept: */*[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:46[00m
2016-03-28 21:24:39.691 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mUsing url versioning[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:58[00m
2016-03-28 21:24:39.691 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mMatched version: v2[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:70[00m
2016-03-28 21:24:39.692 [00;32mDEBUG glance.api.middleware.version_negotiation [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;32m] [01;35m[00;32mnew path /v2/images[00m [00;33mfrom (pid=117297) process_request /opt/stack/glance/glance/api/middleware/version_negotiation.py:71[00m
2016-03-28 21:24:39.710 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:39.710 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mIdentity response: {"error": {"message": "Could not find token: fb9f6586046d470f8ce3535f6a10e5d7", "code": 404, "title": "Not Found"}}[00m
2016-03-28 21:24:39.711 [01;33mWARNING keystonemiddleware.auth_token [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[01;33m] [01;35m[01;33mAuthorization failed for token[00m
2016-03-28 21:24:39.712 [00;36mINFO eventlet.wsgi.server [[01;36mreq-e37fbe6b-46ae-441c-97fb-d2bc764eced3 [00;36m5ebc986213fe4ee492067069e8936375 7fe79b95e66646ffac9b9da6ef0a3506[00;36m] [01;35m[00;36m192.168.218.145 - - [28/Mar/2016 21:24:39] "GET /v2/images?limit=20 HTTP/1.1" 401 571 0.020942[00m
Corresponding congress.log (filtered):
// Each message shows the newly obtained authentication token following each auth failure.
// Log from running this patch of Congress: https://review.openstack.org/#/c/298504/2 with Devstack
2016-03-28 21:24:09.445 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]Auth failed using token: fb9f6586046d470f8ce3535f6a10e5d7.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:108[00m
2016-03-28 21:24:09.445 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]New token set: 0e9c95138be44ac89310ec3fcf20b93c.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:110[00m
2016-03-28 21:24:19.582 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]Auth failed using token: 0e9c95138be44ac89310ec3fcf20b93c.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:108[00m
2016-03-28 21:24:19.582 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]New token set: d1b41674c99844d1902b25898c1237ce.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:110[00m
2016-03-28 21:24:29.686 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]Auth failed using token: d1b41674c99844d1902b25898c1237ce.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:108[00m
2016-03-28 21:24:29.687 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]New token set: 4bec1b485f6f47019ecfeffb6d8619cd.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:110[00m
2016-03-28 21:24:39.795 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]Auth failed using token: 4bec1b485f6f47019ecfeffb6d8619cd.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:108[00m
2016-03-28 21:24:39.796 [00;32mDEBUG congress.datasources.glancev2_driver [[00;36m-[00;32m] [01;35m[00;32m[ekcsdebug]New token set: 46bed5dcd05b4ae3b82b6c35ccf950a2.[00m [00;33mfrom (pid=26606) update_from_datasource /opt/stack/congress/congress/datasources/glancev2_driver.py:110[00m
That happens because X-Auth-Token header stored in request.Session entity.
The session was instantiated in http client initialization.
Honestly, I think keystone sessions is the right thing you need to use to instantiate glanceclient.
Right now you can several WA for the current approach:
1) Instantiate glanceclient when token expires
2) Instantiate httpclient when token expires
the third option is send self.auth_token each time somebody executes any action instead of storing it in session is also reasonable. I will try to propose a fix for that.