The issue has been detected and reproduced in MOS 9.2.
If upload of a large file to Glance backed by Swift takes longer than token expiration time, upload will fail; additionally, removal of stale chunks will also fail.
2017-11-08 21:15:54.065 25295 DEBUG swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] REQ: curl -i http://172.16.35.3:8080/v1/AUTH_4e57396886874de39a23c17b37b2f146/glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00096 -X PUT -H "Content-Type: " -H "X-Auth-Token: gAAAAABaA3OSzGmG..." http_log /usr/lib/python2.7/dist-packages/swiftclient/client.py:164
2017-11-08 21:15:54.065 25295 DEBUG swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] RESP STATUS: 201 Created http_log /usr/lib/python2.7/dist-packages/swiftclient/client.py:165
2017-11-08 21:15:54.066 25295 DEBUG swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] RESP HEADERS: {u'Content-Length': u'0', u'Last-Modified': u'Wed, 08 Nov 2017 21:15:54 GMT', u'Connection': u'close', u'Etag': u'a820665457bab94a114ca9acbe3cb2ae', u'X-Trans-Id': u'txb66297eeaa0c457fb1418-005a037409', u'Date': u'Wed, 08 Nov 2017 21:15:54 GMT', u'Content-Type': u'text/html; charset=UTF-8'} http_log /usr/lib/python2.7/dist-packages/swiftclient/client.py:166
2017-11-08 21:15:54.066 25295 DEBUG glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Wrote chunk 85f17d98-8ea8-43b6-b157-497fee7f4752-00096 (96/?) of length 25600000 to Swift returning MD5 of content: a820665457bab94a114ca9acbe3cb2ae add /usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py:619
2017-11-08 21:15:54.067 25295 DEBUG keystoneclient.auth.identity.v3.base [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Making authentication request to http://172.16.35.3:5000//v3/auth/tokens get_auth_ref /usr/lib/python2.7/dist-packages/keystoneclient/auth/identity/v3/base.py:188
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Error during chunked upload to backend, deleting stale chunks
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store Traceback (most recent call last):
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py", line 596, in add
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store content_length=content_length)
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1709, in put_object
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store response_dict=response_dict)
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1601, in _retry
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store reset_func(func, *args, **kwargs)
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1689, in _default_reset
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store % (container, obj))
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store ClientException: put_object('glance', '85f17d98-8ea8-43b6-b157-497fee7f4752-00097', ...) failure and no ability to reset contents for reupload.
2017-11-08 21:15:55.138 25295 ERROR glance_store._drivers.swift.store
2017-11-08 21:15:55.146 25295 DEBUG keystoneclient.auth.identity.v3.base [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Making authentication request to http://172.16.35.3:5000//v3/auth/tokens get_auth_ref /usr/lib/python2.7/dist-packages/keystoneclient/auth/identity/v3/base.py:188
2017-11-08 21:15:55.213 25295 DEBUG glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Deleting chunk 85f17d98-8ea8-43b6-b157-497fee7f4752-00001 _delete_stale_chunks /usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py:515
2017-11-08 21:15:55.226 25295 INFO swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] REQ: curl -i http://172.16.35.3:8080/v1/AUTH_4e57396886874de39a23c17b37b2f146/glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00001 DELETE -H "X-Auth-Token: gAAAAABaA3OSzGmG..."
2017-11-08 21:15:55.227 25295 INFO swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] RESP STATUS: 401 Unauthorized
2017-11-08 21:15:55.228 25295 INFO swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] RESP HEADERS: {u'Content-Length': u'131', u'Connection': u'close', u'X-Trans-Id': u'tx84533772b90a430aaf506-005a03740b', u'Date': u'Wed, 08 Nov 2017 21:15:55 GMT', u'Content-Type': u'text/html; charset=UTF-8', u'Www-Authenticate': u'Swift realm="AUTH_4e57396886874de39a23c17b37b2f146", Keystone uri=\'http://172.16.35.3:5000/\''}
2017-11-08 21:15:55.229 25295 INFO swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] RESP BODY: <html><h1>Unauthorized</h1><p>This server could not verify that you are authorized to access the document you requested.</p></html>
2017-11-08 21:15:55.230 25295 ERROR swiftclient [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Object DELETE failed: http://172.16.35.3:8080/v1/AUTH_4e57396886874de39a23c17b37b2f146/glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00001 401 Unauthorized [first 60 chars of response] <html><h1>Unauthorized</h1><p>This server could not verify t
2017-11-08 21:15:55.230 25295 ERROR swiftclient Traceback (most recent call last):
2017-11-08 21:15:55.230 25295 ERROR swiftclient File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1565, in _retry
2017-11-08 21:15:55.230 25295 ERROR swiftclient service_token=self.service_token, **kwargs)
2017-11-08 21:15:55.230 25295 ERROR swiftclient File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1382, in delete_object
2017-11-08 21:15:55.230 25295 ERROR swiftclient http_response_content=body)
2017-11-08 21:15:55.230 25295 ERROR swiftclient ClientException: Object DELETE failed: http://172.16.35.3:8080/v1/AUTH_4e57396886874de39a23c17b37b2f146/glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00001 401 Unauthorized [first 60 chars of response] <html><h1>Unauthorized</h1><p>This server could not verify t
2017-11-08 21:15:55.230 25295 ERROR swiftclient
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Failed to delete orphaned chunk glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00001
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store Traceback (most recent call last):
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py", line 517, in _delete_stale_chunks
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store connection.delete_object(container, chunk)
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1721, in delete_object
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store response_dict=response_dict)
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1565, in _retry
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store service_token=self.service_token, **kwargs)
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1382, in delete_object
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store http_response_content=body)
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store ClientException: Object DELETE failed: http://172.16.35.3:8080/v1/AUTH_4e57396886874de39a23c17b37b2f146/glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00001 401 Unauthorized [first 60 chars of response] <html><h1>Unauthorized</h1><p>This server could not verify t
2017-11-08 21:15:55.231 25295 ERROR glance_store._drivers.swift.store
2017-11-08 21:15:55.233 25295 DEBUG glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Deleting chunk 85f17d98-8ea8-43b6-b157-497fee7f4752-00002 _delete_stale_chunks /usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py:515
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store [req-cabcbf58-1683-40e0-99cc-9ab5d5cac77d 96fd9869b3654fb8a645b4c7f8d0fc6a 4e57396886874de39a23c17b37b2f146 - - -] Failed to delete orphaned chunk glance/85f17d98-8ea8-43b6-b157-497fee7f4752-00002
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store Traceback (most recent call last):
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/glance_store/_drivers/swift/store.py", line 517, in _delete_stale_chunks
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store connection.delete_object(container, chunk)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1721, in delete_object
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store response_dict=response_dict)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1553, in _retry
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store self.url, self.token = self.get_auth()
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 1507, in get_auth
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store timeout=self.timeout)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 593, in get_auth
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store timeout=timeout)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 453, in get_auth_1_0
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store timeout=timeout)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 444, in http_connection
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store conn = HTTPConnection(*arg, **kwarg)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/dist-packages/swiftclient/client.py", line 350, in __init__
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store self.parsed_url = urlparse(url)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/urlparse.py", line 143, in urlparse
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store tuple = urlsplit(url, scheme, allow_fragments)
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store File "/usr/lib/python2.7/urlparse.py", line 182, in urlsplit
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store i = url.find(':')
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store AttributeError: 'NoneType' object has no attribute 'find'
2017-11-08 21:15:55.234 25295 ERROR glance_store._drivers.swift.store
And so on...
I've found several issues in glance_store code while debugging this problem.
1 -
https://github.com/openstack/glance_store/blob/master/glance_store/_drivers/swift/connection_manager.py#L83 every connection request (chunk upload request for ex.) goes through this line and then the returned auth object expiry is checked - https://github.com/openstack/glance_store/blob/master/glance_store/_drivers/swift/connection_manager.py#L87
However, the returned object is NOT the current token, but a new token. This new token is not propagated to "salf.connection" object, which keeps using the old token. Therefore this check at line 87 is useless and always returns False, unless token expiration is lower than the self.store.conf.glance_store.swift_store_expire_soon_interval - i.e. if you set token expiration in Keystone to a very low value this function will always return True, otherwise - always return False.
As a workaround, this if clause can be removed, which will force token renewal for every connection to swift, and resolve the issue. This is not optimal of course.
2 -
After glance fails to upload, it tries to delete stale chunks. However, it fails to do so with the first chunk due to 401 (same issue as above I guess?) and after that is starts failing due to another issue - for some reason the auth_version of the connection = 1, even though in /etc/glance/glance-swift.conf there is auth_version = 3. This causes swiftclient to use get_auth_1_0 function and then it fails due to connection.auth_url being None. So somehow connection object for Swift is not initialized correctly in Glance. I have not done nuch research into that issue, except extracting connection's auth_url and auth_version values here - https://github.com/openstack/glance_store/blob/master/glance_store/_drivers/swift/store.py#L867.
Attached is a debugging patch which provides enough data to confirm my findings. It patches both glance_store and keystoneclient to print more debug data in glance-api.log
How to reproduce:
1. in keystone config, set expiration = 120, restart apache2
2. start uploading a large (5G+, depending on cluster performance) file to Glance
related upstream bug - https:/