tempest.api.object_storage.test_container_acl.ObjectTestACLs.test_write_object_with_rights[gate,smoke] failed

Bug #1254405 reported by Ivan-Zhu
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Invalid
Undecided
Unassigned
OpenStack Object Storage (swift)
Fix Released
High
Peter Portante
tempest
Invalid
Undecided
Unassigned

Bug Description

failed on http://logs.openstack.org/69/43069/2/gate/gate-grenade-devstack-vm/dc8c793/testr_results.html.gz

The response code is 503, I think it's a keystone bug, but need a little more insight on it.
ft59.4: tempest.api.object_storage.test_container_acl.ObjectTestACLs.test_write_object_with_rights[gate,smoke]_StringException: Empty attachments:
  stderr
  stdout

pythonlogging:'': {{{
2013-11-23 09:38:47,817 Request: PUT http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756
2013-11-23 09:38:47,818 Request Headers: {'X-Auth-Token': '<Token omitted>'}
2013-11-23 09:38:47,834 Response Status: 201
2013-11-23 09:38:47,835 Response Headers: {'content-length': '0', 'x-trans-id': 'tx8f7716fbd9a64a4899b45-00529077a7', 'date': 'Sat, 23 Nov 2013 09:38:47 GMT', 'content-type': 'text/html; charset=UTF-8', 'connection': 'close'}
2013-11-23 09:38:47,835 Request: POST http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756
2013-11-23 09:38:47,835 Request Headers: {'X-Container-Write': 'test_tenant_-tempest-1562797677:test_user_-tempest-2057178357', 'X-Auth-Token': '<Token omitted>'}
2013-11-23 09:38:47,845 Response Status: 204
2013-11-23 09:38:47,845 Response Headers: {'content-length': '0', 'x-trans-id': 'tx4a8528db02f043ddbde43-00529077a7', 'date': 'Sat, 23 Nov 2013 09:38:47 GMT', 'content-type': 'text/html; charset=UTF-8', 'connection': 'close'}
2013-11-23 09:38:47,845 Request: PUT http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756/Object-tempest-846598070
2013-11-23 09:38:47,845 Request Headers: {'X-Auth-Token': '<Token omitted>'}
2013-11-23 09:38:47,846 Request Body: data
2013-11-23 09:38:47,864 Response Status: 201
2013-11-23 09:38:47,864 Response Headers: {'content-length': '0', 'last-modified': 'Sat, 23 Nov 2013 09:38:47 GMT', 'connection': 'close', 'etag': '8d777f385d3dfec8815d20f7496026dc', 'x-trans-id': 'tx185bcdcc5d884ed39b5a5-00529077a7', 'date': 'Sat, 23 Nov 2013 09:38:47 GMT', 'content-type': 'text/html; charset=UTF-8'}
2013-11-23 09:38:47,865 Request: GET http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756?format=json&limit=9999
2013-11-23 09:38:47,865 Request Headers: {'X-Auth-Token': '<Token omitted>'}
2013-11-23 09:38:47,877 Response Status: 200
2013-11-23 09:38:47,878 Response Headers: {'content-length': '185', 'x-container-object-count': '1', 'x-container-write': 'test_tenant_-tempest-1562797677:test_user_-tempest-2057178357', 'accept-ranges': 'bytes', 'date': 'Sat, 23 Nov 2013 09:38:47 GMT', 'connection': 'close', 'x-timestamp': '1385199527.82633', 'x-trans-id': 'tx07ecbc88de3c44e98fee8-00529077a7', 'x-container-bytes-used': '4', 'content-type': 'application/json; charset=utf-8', 'content-location': u'http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756?format=json&limit=9999'}
2013-11-23 09:38:47,878 Response Body: [{"hash": "8d777f385d3dfec8815d20f7496026dc", "last_modified": "2013-11-23T09:38:47.854800", "bytes": 4, "name": "Object-tempest-846598070", "content_type": "application/octet-stream"}]
2013-11-23 09:38:47,878 Request: DELETE http://127.0.0.1:8080/v1/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756/Object-tempest-846598070
2013-11-23 09:38:47,878 Request Headers: {'X-Auth-Token': '<Token omitted>'}
2013-11-23 09:38:47,891 Response Status: 503
2013-11-23 09:38:47,891 Response Headers: {'content-length': '118', 'x-trans-id': 'txdb6be9b4235d41cfabb9d-00529077a7', 'date': 'Sat, 23 Nov 2013 09:38:47 GMT', 'content-type': 'text/html; charset=UTF-8', 'connection': 'close'}
2013-11-23 09:38:47,891 Response Body: <html><h1>Service Unavailable</h1><p>The server is currently unavailable. Please try again at a later time.</p></html>
}}}

Traceback (most recent call last):
  File "tempest/api/object_storage/test_container_acl.py", line 46, in tearDown
    self.delete_containers([self.container_name])
  File "tempest/api/object_storage/base.py", line 119, in delete_containers
    object_client.delete_object(cont, obj['name'])
  File "tempest/services/object_storage/object_client.py", line 47, in delete_object
    resp, body = self.delete(url)
  File "tempest/common/rest_client.py", line 308, in delete
    return self.request('DELETE', url, headers)
  File "tempest/common/rest_client.py", line 436, in request
    resp, resp_body)
  File "tempest/common/rest_client.py", line 527, in _error_checker
    raise exceptions.RestClientException(str(resp.status))
RestClientException: An unknown exception occurred
Details: 503

Revision history for this message
Dolph Mathews (dolph) wrote :

keystone isn't capable of returning 503's itself... it also looks like this is a failed request to swift.

Changed in keystone:
status: New → Invalid
Changed in swift:
assignee: nobody → Peter Portante (peter-a-portante)
Changed in swift:
status: New → Confirmed
importance: Undecided → High
Revision history for this message
Peter Portante (peter-a-portante) wrote :

This appears to be some kind of race condition. It is kind of hard to debug this particular one because we don't appear to have all the logs from the proxy server. Not sure why, but we only see the object and container server data for this operation.

The sequence of events is:

1. Container create of: TestContainer-tempest-122946756
    a. Auto account-create of: AUTH_3673914f25b046aa815ff03fd0f035fd
2. POST Container TestContainer-tempest-122946756
3. HEAD Container TestContainer-tempest-122946756
4. Object PUT TestContainer-tempest-122946756/Object-tempest-846598070
    a. container PUT object
    b. PUT object response
5. GET Container, json format
6. DELETE object - 500 Error, .data file not found

Nov 23 09:38:47 devstack-precise-hpcloud-az2-726791 object-server: ERROR __call__ error with DELETE /sdb1/237/AUTH_3673914f25b046aa815ff03fd0f035fd/TestContainer-tempest-122946756/Object-tempest-846598070 :
Traceback (most recent call last):
  File "/opt/stack/new/swift/swift/obj/server.py", line 665, in __call__
    res = method(req)
  File "/opt/stack/new/swift/swift/common/utils.py", line 1919, in wrapped
    return func(*a, **kw)
  File "/opt/stack/new/swift/swift/common/utils.py", line 687, in _timing_stats
    resp = func(ctrl, *args, **kwargs)
  File "/opt/stack/new/swift/swift/obj/server.py", line 613, in DELETE
    disk_file.delete(req_timestamp)
  File "/opt/stack/new/swift/swift/obj/diskfile.py", line 1364, in delete
    deleter.put({'X-Timestamp': timestamp})
  File "/opt/stack/new/swift/swift/obj/diskfile.py", line 686, in put
    self._finalize_put, metadata, target_path)
  File "/opt/stack/new/swift/swift/common/utils.py", line 2216, in force_run_in_thread
    return self._run_in_eventlet_tpool(func, *args, **kwargs)
  File "/opt/stack/new/swift/swift/common/utils.py", line 2199, in _run_in_eventlet_tpool
    raise result
OSError: [Errno 2] No such file or directory: '/opt/stack/data/swift/1/sdb1/objects/237/7a0/768dbb513bd1ee5ace0d0f9650d097a0/1385199527.85480.data' (txn: txdb6be9b4235d41cfabb9d-00529077a7)

Revision history for this message
Peter Portante (peter-a-portante) wrote :

So the proxy-server logs did not get rolled into rsyslog for some reason, but the failure is in: http://logs.openstack.org/69/43069/2/gate/gate-grenade-devstack-vm/dc8c793/logs/new/screen-s-proxy.txt.gz

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to swift (master)

Fix proposed to branch: master
Review: https://review.openstack.org/58188

Changed in swift:
status: Confirmed → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to swift (master)

Reviewed: https://review.openstack.org/58188
Committed: http://github.com/openstack/swift/commit/2c0bbaf05c06968cc0376f34acbfb09e72603d47
Submitter: Jenkins
Branch: master

commit 2c0bbaf05c06968cc0376f34acbfb09e72603d47
Author: Peter Portante <email address hidden>
Date: Sun Nov 24 23:29:53 2013 -0500

    Protect against hash cleanup errors on PUTs

    In http://launchpad.net/bugs/1254405 an exception occurs when
    finalizing the PUT of an object, but it is obscured by the thread pool
    code, so we don't see the actual line where it originated. However,
    there are two possible functions where this exception could originate:

        1. renamer()
        2. hash_cleanup_listdir()

    If this is an error in renamer(), there is some other waky problem
    where the temporary file has been removed. It is likely that this is a
    problem where a file name from os.listdir ends up disappearing (but
    even this is a rare occurence). Regardless, it is not clear that we
    really want an error from hash_cleanup_listdir() from affecting the
    return result of the PUT.

    To that end, we squelsh OSErrors from hash_cleanup_listdir() for
    now. One might argue for all errors, but since os.unlink() and
    os.listdir() raise OSError today, that is probably sufficient.

    Even that we use "Closes-Bug" below, it is not clear it can even be
    determined that this closes that bug report.

    Change-Id: I2f55df835c387e4d17cffda74c04c9994aebbe1f
    Closes-Bug: 1254405
    Signed-off-by: Peter Portante <email address hidden>

Changed in swift:
status: In Progress → Fix Committed
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to swift (feature/ec)

Fix proposed to branch: feature/ec
Review: https://review.openstack.org/59766

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to swift (feature/ec)
Download full text (43.6 KiB)

Reviewed: https://review.openstack.org/59766
Committed: http://github.com/openstack/swift/commit/239f88a42b00a71a07860f953d00771c8aef4305
Submitter: Jenkins
Branch: feature/ec

commit 8a64bff2dc28b43b3ed4fa7b65da1a9ea29677cc
Author: Samuel Merritt <email address hidden>
Date: Wed Nov 27 17:23:59 2013 -0800

    Report transaction ID in failure exceptions

    This way, when something fails in Jenkins, you have some chance of
    searching the logs for the relevant transaction.

    Change-Id: I3cf606cb4963e32b5c6ac3deda08e73541b3ff7d

commit e0147e60d800fd67bc05bc4299c315f1761bd60b
Author: Peter Portante <email address hidden>
Date: Fri Nov 22 16:59:09 2013 -0500

    Add a unit test to verify proxy logging fields

    Also bring unit test coverage to 100% (well, at least every line is
    reported as "covered").

    Change-Id: I659d0c02008368897b1307a7a5c9aaba73b80588
    Signed-off-by: Peter Portante <email address hidden>

commit 87cd5598476d0835c526918a9e1f03fe2d698866
Author: Alex Gaynor <email address hidden>
Date: Sun Nov 24 20:24:45 2013 -0600

    Account for a platform difference in semaphores

    On OS X (and probably other Operating Systems) it isn't possible to
    introspect the value of a semaphore. Account for this by skipping a
    test about this.

    Change-Id: I97824f9fc4e36de4f7a62c8ce53865e6977dfdfe

commit 3c7c355120a3ebe5c3f47e62176cec8cab824143
Author: Peter Portante <email address hidden>
Date: Mon Nov 25 13:30:41 2013 -0500

    Use TCP_NODELAY for created sockets.

    Mark Seger at HP has been looking at small objects, 1 and 2 KB size,
    and with Rick Jones' help noticed that TCP protocol traces showed
    effects from the Nagel algorithm client-to-server and
    server-to-client.

    This patch just addresses our WSGI server responses, but does not
    address out-bound connections from the various servers.

    Change-Id: I11f86df1f56fba1c6ab6084dc1f580c395f072dc
    Signed-off-by: Peter Portante <email address hidden>

commit 39032c359f01a5e397fce2eb8326b961c9673607
Author: Darrell Bishop <email address hidden>
Date: Wed Nov 27 12:07:42 2013 -0500

    Add HTML reporting for test branch coverage.

    When including branch coverage results, also generate HTML reports into
    a "cover" subdirectory under the directory in which .unittests resides
    (i.e. known location at the top of the swift tree).

    Change-Id: I493d74f38755f7bf0d7043052585efb27840b238

commit 0ba071f27c009e1d028189e812f722e8583a07ee
Author: Darrell Bishop <email address hidden>
Date: Tue Nov 26 15:08:13 2013 -0500

    Fix bug in obj updater run_once().

    The "not" in front of the ismount() call got accidentally dropped in a
    recent change. This patch adds it back along with a few more tests.

    Note that this bug only showed up on an SAIO during probe tests because
    I used actually-mounted (virtual) "disks". So keep that in mind when
    building SAIOs for development/testing.

    Change-Id: Ia193f3c4b73203605954036863575c22ddab6b03

commit edc9f62ed6c537c4c112cf552310705b99fa08b8
Author: Peter Portante <peter.portante@redha...

Thierry Carrez (ttx)
Changed in swift:
milestone: none → 1.11.0
status: Fix Committed → Fix Released
Changed in tempest:
status: New → Invalid
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.