Comment 14 for bug 1443913

Revision history for this message
Mike Fedosin (mfedosin) wrote :

I just investigated this issue a little bit... Basing on the attached logs the sequence was:
0. Glance api got a request with valid token on the creation of a new image.
1. Adding an instance with status 'queued' to the DB with registry server. Here the authorization with the token was passed and then new image instance appeared.
https://github.com/openstack/glance/blob/stable/juno/glance/api/v1/images.py#L547
2. Then there was a check with the second request to the registry. And authorization was succeed, too.
https://github.com/openstack/glance/blob/stable/juno/glance/api/v1/images.py#L774
3. But on the next operation, when we wanted to update image status from 'queued' to 'saving' to begin uploading, we had authorization error with 404 response code from Keystone.
https://github.com/openstack/glance/blob/stable/juno/glance/api/v1/images.py#L618

The problem is that the token could not expire. These 3 operation were performed less than a second, just before uploading the file.
From attached logs I found the following:

2015-04-14T04:01:48.246451+00:00 debug: 2015-04-14 04:01:48.246 16570 DEBUG urllib3.connectionpool [-] "GET /v3/auth/tokens HTTP/1.1" 404 115 _make_request /usr/lib/python2.7/dist-packages/urllib3/connectionpool.py:430
2015-04-14T04:01:48.247693+00:00 debug: 2015-04-14 04:01:48.247 16570 DEBUG keystoneclient.session [-] RESP: _http_log_response /usr/lib/python2.7/dist-packages/keystoneclient/session.py:182
2015-04-14T04:01:48.247693+00:00 debug: 2015-04-14 04:01:48.247 16570 DEBUG keystoneclient.session [-] Request returned failure status: 404 request /usr/lib/python2.7/dist-packages/keystoneclient/session.py:345
2015-04-14T04:01:48.249078+00:00 warning: 2015-04-14 04:01:48.248 16570 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2015-04-14T04:01:48.249078+00:00 warning: 2015-04-14 04:01:48.248 16570 WARNING keystonemiddleware.auth_token [-] Identity response: {"error": {"message": "Could not find token: d90482e1854a46019815f322e94bbe75", "code": 404, "title": "Not Found"}}
2015-04-14T04:01:48.249078+00:00 debug: 2015-04-14 04:01:48.248 16570 DEBUG keystonemiddleware.auth_token [-] Token validation failure. _validate_token /usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:889
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token Traceback (most recent call last):
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 880, in _validate_token
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token expires = _get_token_expiration(data)
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token File "/usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py", line 436, in _get_token_expiration
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token raise InvalidToken('Token authorization failed')
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token InvalidToken: Token authorization failed
2015-04-14 04:01:48.248 16570 TRACE keystonemiddleware.auth_token
2015-04-14T04:01:48.250276+00:00 debug: 2015-04-14 04:01:48.250 16570 DEBUG keystonemiddleware.auth_token [-] Marking token as unauthorized in cache store_invalid /usr/lib/python2.7/dist-packages/keystonemiddleware/auth_token.py:1713
2015-04-14T04:01:48.250276+00:00 warning: 2015-04-14 04:01:48.250 16570 WARNING keystonemiddleware.auth_token [-] Authorization failed for token
2015-04-14T04:01:48.251786+00:00 info: 2015-04-14 04:01:48.250 16570 INFO keystonemiddleware.auth_token [-] Invalid user token - rejecting request
2015-04-14T04:01:48.251786+00:00 info: 2015-04-14 04:01:48.251 16570 INFO glance.wsgi.server [-] 10.109.2.2 - - [14/Apr/2015 04:01:48] "POST /images HTTP/1.1" 401 212 3.050594

I think we should ask keystone team about their suggestions on that matter.