500 Internal Server Error in Swift3 and client (Cyberduck 4.7.3) gets 503 Errors

Bug #1529008 reported by Charles Hsu
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Swift3
Incomplete
Undecided
Unassigned

Bug Description

I just tested swift3 and keystone integration with Cyberduck 4.7.3 multipart upload.
I upload a single object (250MB size) to Swift cluster. I tried to upload it 10 times (with different object name); everything is good in first four uploads, but I got error when I executed 5nd uploads. Here is all logs.

 vagrant@dev21:/var/log/swift$ sudo grep txbf8bd6caf7d641d6bde95 all.log
 Dec 24 04:54:09 localhost proxy-server: Calling Swift3 Middleware (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:09 localhost proxy-server: {'access_key': '09bf8d2817b14ac8ac8e0e86117b32d9', 'account': None, 'bucket_in_host': None, 'user_id': None, 'slo_enabled': True, 'token': 'UFVUCgphcHBsaWNhdGlvbi9vY3RldC1zdHJlYW0KVGh1LCAyNCBEZWMgMjAxNSAwNDo1NTo1OCBHTVQKL3Rlc3QvMjUwbWI4P3BhcnROdW1iZXI9MiZ1cGxvYWRJZD1aRFF5WTJFellqa3ROR1V3TlMwME5qRTNMVGt5TW1NdE1URXpObUl3TlRKaU5qSmk=', '_params_cache': {'partNumber': '2', 'uploadId': 'ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi'}, 'headers': <swift.common.swob.HeaderEnvironProxy object at 0x7f33e8b65250>, 'object_name': '250mb8', 'environ': {'HTTP_AUTHORIZATION': 'AWS 09bf8d2817b14ac8ac8e0e86117b32d9:s/AoxlD8k4WA1ZsWFysWOcavsNM=', 'SCRIPT_NAME': '', 'swift.trans_id': 'txbf8bd6caf7d641d6bde95-00567b7a71', 'swift.account/250mb8': {'status': 404, 'container_count': 0, 'bytes': None, 'total_object_count': None, 'meta': {}, 'sysmeta': {}}, 'swift.proxy_access_log_made': True, 'REQUEST_METHOD': 'PUT', 'PATH_INFO': '/test/250mb8', 'SERVER_PROTOCOL': 'HTTP/1.0', 'QUERY_STRING': 'uploadId=ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi&partNumber=2', 'REMOTE_ADDR': '192.168.200.100', 'CONTENT_LENGTH': '10485760', 'HTTP_USER_AGENT': 'Cyberduck/4.7.3.18402 (Mac OS X/10.11.2) (x86_64)', 'HTTP_CONNECTION': 'Keep-Alive', 'eventlet.posthooks': [], 'RAW_PATH_INFO': '/test/250mb8', 'REMOTE_PORT': '53541', 'eventlet.input': <eventlet.wsgi.Input object at 0x7f33e8c63d90>, 'wsgi.url_scheme': 'http', 'SERVER_PORT': '80', 'swift.leave_relative_location': True, 'swiftstack.auth.nuacct_db': {}, 'HTTP_DATE': 'Thu, 24 Dec 2015 04:55:58 GMT', 'HTTP_HOST': '192.168.200.21:80', 'wsgi.multithread': True, 'swiftstack.auth.users_db': {'test': {'s3key': '1da1e40e1fd46ee2487a4ac8dac2424f', 'storageURL': 'http://192.168.200.21/v1/AUTH_test', 'groups': [], 'key': 'scrypt\x00\r\x00\x00\x00\x08\x00\x00\x00\x01\x1eb\xf9L\xcc@N$\xdd\x875\x80\xec\x97\xbaKQd\xab\xee%\x16D\x86(|\xb2>\x9c\xaea\nDeD_;\n\xcdOv\x8e\x85T&\x807\x8d7\x8c\xe8iO\x9dv\x90|10\xa5\x00\xaaf\xf0\x8c`I\xc5\x90W{\xa2\xa4P\xc1a>\xe6B\xa9=\xf4\xbe\x95>n\x88T+C\x189\x06\x8e\xd6\xe1\xcc0\xcf\x92\x83\xe4""\x9aO,d\xa8\x8ft\xf0o\x81z\xddW\xe9\xbd8{\x97\xbf\xc5\xbep\xe5\xbb/\xfeF\xfd\x9f\x1b\xf1in\xd0\xd3\xc3G$\x97\x14\xe8\x92/9\xab\xe8\xe7\xa5\x0b\xb79\x19\xda\xf7\xe31\xe2R\xd16\x14\xbf,\xa5\x06\xc7\xe4_\xd7\x92\r\x94'}, 'demo': {'s3key': '1a796aae5ceffb98bd9f0bf386fcc354', 'storageURL': 'http://192.168.200.21/v1/AUTH_demo', 'groups': ['.reseller_admin'], 'key': 'scrypt\x00\r\x00\x00\x00\x08\x00\x00\x00\x01\xd0N.\x98R\xb9\xf3\x95\xa8\x90\x99P\xf2\xd3\x00\xde\x86*f;1\x99\x96\xd6\x19z;{\x11]\x84\x90\xe4+\x8e~0CV\xcc\xbe\x19\xf8N\xa6\xf9\xf81\xaf\xcf\xad\xe9\x8c\xdem\x08\xc8\x89\xaf\xda\xac\x1c\x7f)\xa8\x9e5\xd1\xfb\x97\x83\x08)2\x81\xbc\x1a5\xdf\xebB\xedo \xd3\xc2i\x9c\xeb\x0f\xda\xfb\xba\xa7\x8dqP\xcc\xb0\xa5\xf9\xf3\xfd%QL\x12\x90\xcfV\xcd\t\xb3\xffT|t\x88\xde\xa1\x01\xb4.\xa0\x17p\xe0\xc7U\x0b\xb0\xea_u\xe1\xeaYdj\x1a|\xea\x05\xc3\x85\xe0R!\x15\xcfV\xa4tH\xcd\xd4\xa2g#\xefG\xef\x16\xe2,fL:5\x9dj\xdc\x87\xe4Z$'}, 't2': {'s3key': '987153214a2a0ec7d9ece2b575f684f3', 'storageURL': 'http://192.168.200.21/v1/AUTH_t2', 'groups': [], 'key': "scrypt\x00\x0b\x00\x00\x00\x08\x00\x00\x00\x01E\xcd\xa3\x0cl=\x1c\x9b<'\xf5\xa6\xb7\xdd>s\xe1\x18:p~2w\x7f[u\xc9\x83\xb1x<\x88\x98\xec\xad\x13\x02X\x8c\x08\x9bfD\xee\x99{3$\x18\xf8\x12\x92'8\x81u.Z\xa6\x82\xe8\x11\x8b\xd1x3\xaa'`\\\xd3Og\xf5AS\x15h\x1aX\xe61\xa61YG\xda\xa9\x14\x141\xc0^\x04V\xaa\x89\x8c\xe9\xf1z\xda\xef\xa6\x91_\xa9\xdc\xd3\xff\xc7\xf6~\xefw\x8epA\xbc\xe5i\x9eT\xa5\x9c?K\xd1\xbcZ1\x040%\x06\xf0\xbd\x0e?\x1d\xdf\x90\x0fa\x93\xd0\xb1/\xa7Q\xd0#\x82I\x84}\x85\xb5R\xdd\xa04\xa8\xbb\xe8\xdbr\x8bqU\x94&\xf7\xcb\x1c8"}}, 'HTTP_EXPECT': '100-continue', 'wsgi.version': (1, 0), 'SERVER_NAME': '192.168.200.21', 'GATEWAY_INTERFACE': 'CGI/1.1', 'wsgi.run_once': False, 'wsgi.errors': <swift.common.utils.LoggerFileObject object at 0x7f33e8b5ae50>, 'wsgi.multiprocess': False, 'wsgi.input': <swift.common.utils.InputProxy object at 0x7f33e80b8c50>, 'CONTENT_TYPE': 'application/octet-stream', 'swift.cache': <swift.common.memcached.MemcacheRing object at 0x7f33e8c22150>}, 'container_name': 'test'}
 Dec 24 04:54:09 localhost proxy-server: authtoken: Removing headers from request environment: X-Service-Catalog,X-Identity-Status,X-Service-Identity-Status,X-Roles,X-Service-Roles,X-Domain-Name,X-Service-Domain-Name,X-Project-Id,X-Service-Project-Id,X-Project-Domain-Name,X-Service-Project-Domain-Name,X-User-Id,X-Service-User-Id,X-User-Name,X-Service-User-Name,X-Project-Name,X-Service-Project-Name,X-User-Domain-Id,X-Service-User-Domain-Id,X-Domain-Id,X-Service-Domain-Id,X-User-Domain-Name,X-Service-User-Domain-Name,X-Project-Domain-Id,X-Service-Project-Domain-Id,X-Role,X-User,X-Tenant-Name,X-Tenant-Id,X-Tenant (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:09 localhost proxy-server: authtoken: Authenticating user token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost proxy-server: authtoken: Storing token in cache (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost proxy-server: authtoken: Authenticating service token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost proxy-server: authtoken: Received request from user: user_id 556d012f9dd5457e8abccf2642a6e4ab, project_id f3d9676e873e433eb1ed0a2bd2acee0f, roles _member_,admin service: user_id None, project_id None, roles None (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost proxy-server: Using identity: {'roles': [u'_member_', u'admin'], 'user': u'swift', 'tenant': (u'f3d9676e873e433eb1ed0a2bd2acee0f', u'service')} (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost proxy-server: allow user with role(s) admin,_member_ as account admin (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:10 localhost container-server: 192.168.200.21 - - [24/Dec/2015:04:54:10 +0000] "HEAD /d5/10906/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test" 204 - "HEAD http://192.168.200.21/v1/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test" "txbf8bd6caf7d641d6bde95-00567b7a71" "proxy-server 14975" 0.0031 "-" 14908 0
 Dec 24 04:54:11 localhost proxy-server: authtoken: Removing headers from request environment: X-Service-Catalog,X-Identity-Status,X-Service-Identity-Status,X-Roles,X-Service-Roles,X-Domain-Name,X-Service-Domain-Name,X-Project-Id,X-Service-Project-Id,X-Project-Domain-Name,X-Service-Project-Domain-Name,X-User-Id,X-Service-User-Id,X-User-Name,X-Service-User-Name,X-Project-Name,X-Service-Project-Name,X-User-Domain-Id,X-Service-User-Domain-Id,X-Domain-Id,X-Service-Domain-Id,X-User-Domain-Name,X-Service-User-Domain-Name,X-Project-Domain-Id,X-Service-Project-Domain-Id,X-Role,X-User,X-Tenant-Name,X-Tenant-Id,X-Tenant (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:11 localhost proxy-server: authtoken: Authenticating user token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost proxy-server: authtoken: Storing token in cache (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost proxy-server: authtoken: Authenticating service token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost proxy-server: authtoken: Received request from user: user_id 556d012f9dd5457e8abccf2642a6e4ab, project_id f3d9676e873e433eb1ed0a2bd2acee0f, roles _member_,admin service: user_id None, project_id None, roles None (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost proxy-server: Using identity: {'roles': [u'_member_', u'admin'], 'user': u'swift', 'tenant': (u'f3d9676e873e433eb1ed0a2bd2acee0f', u'service')} (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost proxy-server: allow user with role(s) admin,_member_ as account admin (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:12 localhost object-server: 192.168.200.21 - - [24/Dec/2015:04:54:12 +0000] "HEAD /d4/11064/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi" 200 - "HEAD http://192.168.200.21/v1/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi" "txbf8bd6caf7d641d6bde95-00567b7a71" "proxy-server 14975" 0.0011 "-" 14922 0
 Dec 24 04:54:13 localhost proxy-server: authtoken: Removing headers from request environment: X-Service-Catalog,X-Identity-Status,X-Service-Identity-Status,X-Roles,X-Service-Roles,X-Domain-Name,X-Service-Domain-Name,X-Project-Id,X-Service-Project-Id,X-Project-Domain-Name,X-Service-Project-Domain-Name,X-User-Id,X-Service-User-Id,X-User-Name,X-Service-User-Name,X-Project-Name,X-Service-Project-Name,X-User-Domain-Id,X-Service-User-Domain-Id,X-Domain-Id,X-Service-Domain-Id,X-User-Domain-Name,X-Service-User-Domain-Name,X-Project-Domain-Id,X-Service-Project-Domain-Id,X-Role,X-User,X-Tenant-Name,X-Tenant-Id,X-Tenant (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:13 localhost proxy-server: authtoken: Authenticating user token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:14 localhost proxy-server: authtoken: Storing token in cache (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:14 localhost proxy-server: authtoken: Authenticating service token (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:14 localhost proxy-server: authtoken: Received request from user: user_id 556d012f9dd5457e8abccf2642a6e4ab, project_id f3d9676e873e433eb1ed0a2bd2acee0f, roles _member_,admin service: user_id None, project_id None, roles None (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:14 localhost proxy-server: Using identity: {'roles': [u'_member_', u'admin'], 'user': u'swift', 'tenant': (u'f3d9676e873e433eb1ed0a2bd2acee0f', u'service')} (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:14 localhost proxy-server: allow user with role(s) admin,_member_ as account admin (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:26 localhost proxy-server: Object PUT returning 503 for [503, 503] (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:26 localhost proxy-server: 500 Internal Server Error: #012Traceback (most recent call last):#012 File "/usr/lib/python2.7/dist-packages/swift3/middleware.py", line 81, in __call__#012 resp = self.handle_request(req)#012 File "/usr/lib/python2.7/dist-packages/swift3/middleware.py", line 104, in handle_request#012 res = getattr(controller, req.method)(req)#012 File "/usr/lib/python2.7/dist-packages/swift3/controllers/base.py", line 59, in wrapped#012 return func(self, req)#012 File "/usr/lib/python2.7/dist-packages/swift3/controllers/base.py", line 71, in check_container#012 return func(self, req)#012 File "/usr/lib/python2.7/dist-packages/swift3/controllers/multi_upload.py", line 151, in PUT#012 resp = req.get_response(self.app)#012 File "/usr/lib/python2.7/dist-packages/swift3/request.py", line 707, in get_response#012 headers, body, query)#012 File "/usr/lib/python2.7/dist-packages/swift3/request.py", line 692, in _get_response#012 raise InternalError('unexpected status code %d' % status)#012InternalError: 500 Internal Server Error (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)
 Dec 24 04:54:26 localhost proxy-server: 192.168.200.100 192.168.200.100 24/Dec/2015/04/54/26 PUT /test/250mb8%3FuploadId%3DZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi%26partNumber%3D2 HTTP/1.0 500 - Cyberduck/4.7.3.18402%20%28Mac%20OS%20X/10.11.2%29%20%28x86_64%29 - 10485760 182 - txbf8bd6caf7d641d6bde95-00567b7a71 - 17.5081 - - 1450932849.186001062 1450932866.694092035 -
 Dec 24 04:54:28 localhost container-server: 192.168.200.21 - - [24/Dec/2015:04:54:28 +0000] "PUT /d4/52942/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" 201 - "PUT http://192.168.200.21/d4/25558/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" "txbf8bd6caf7d641d6bde95-00567b7a71" "object-server 14922" 0.0023 "-" 14908 0
 Dec 24 04:54:28 localhost container-server: 192.168.200.21 - - [24/Dec/2015:04:54:28 +0000] "PUT /d5/52942/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" 201 - "PUT http://192.168.200.21/d5/25558/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" "txbf8bd6caf7d641d6bde95-00567b7a71" "object-server 14922" 0.0011 "-" 14908 0
 Dec 24 04:54:28 localhost object-server: 192.168.200.21 - - [24/Dec/2015:04:54:28 +0000] "PUT /d4/25558/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" 201 - "PUT http://192.168.200.21/v1/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" "txbf8bd6caf7d641d6bde95-00567b7a71" "proxy-server 14975" 13.7264 "-" 14922 0
 Dec 24 04:54:28 localhost object-server: 192.168.200.21 - - [24/Dec/2015:04:54:28 +0000] "PUT /d5/25558/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" 201 - "PUT http://192.168.200.21/v1/KEY_f3d9676e873e433eb1ed0a2bd2acee0f/test%2Bsegments/250mb8/ZDQyY2EzYjktNGUwNS00NjE3LTkyMmMtMTEzNmIwNTJiNjJi/2" "txbf8bd6caf7d641d6bde95-00567b7a71" "proxy-server 14975" 13.7315 "-" 14922 0

Revision history for this message
Charles Hsu (charles0126) wrote :
Revision history for this message
Kota Tsuyuzaki (tsuyuzaki-kota) wrote :

Hello Charles, does this happen always?

Looks like proxy-server (behinds of swift3) got two 503 statuses and it seems to trigger the error response.

 Dec 24 04:54:26 localhost proxy-server: Object PUT returning 503 for [503, 503] (txn: txbf8bd6caf7d641d6bde95-00567b7a71) (client_ip: 192.168.200.100)

i.e. it seems that something wrong occurred at Swift layer.

Am I missing something?

Revision history for this message
Charles Hsu (charles0126) wrote :

Hi Kota,

Yes, that's correct. But the node is on my local VM, so I assume 503 won't happen.
Maybe I need to reproduce this env again and post more detail on here.

Tim Burke (1-tim-z)
Changed in swift3:
status: New → Incomplete
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.