OpenStack Object Storage (swift)

test_create_object_with_transfer_encoding failing since 20th Nov for

Bug #1905432 reported by Ghanshyam Mann
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
OpenStack Object Storage (swift)
Invalid
Undecided
Unassigned
tempest
Fix Released
Undecided
Martin Kopec

Bug Description

test_create_object_with_transfer_encoding is failing for UnexpectedContentType since Nov 20th

- https://zuul.openstack.org/builds?job_name=tempest-integrated-storage

Tempest gets the API error response but due to content-type as 'content-type': 'text/html; charset=iso-8859-1 ' tempest does not parse the response error code

- https://zuul.opendev.org/t/openstack/build/ba6d3a85d49443afb439f08af07456b6/log/controller/logs/tempest_log.txt#6235

tempest condition for valid content-type
- https://github.com/openstack/tempest/blob/9ca8827ff52bf1a94a860ac5503702ad059ca18d/tempest/lib/common/rest_client.py#L774-L785

The first thing to check is if the 'content-type': 'text/html; charset=iso-8859-1 ' return from swift is correct or not.

2nd thing we need to check what exact error this API return which causing this test to fail consistently.

Failure can be seen in tempest-integrated-object-storage job or tempest-integrated-storage

- https://zuul.openstack.org/builds?job_name=tempest-integrated-object-storage
- https://zuul.openstack.org/builds?job_name=tempest-integrated-storage

Revision history for this message
Ghanshyam Mann (ghanshyammann) wrote :

I am adding a debugging patch to allow this new content-type from tempest side and see the actual error.

Revision history for this message
Ghanshyam Mann (ghanshyammann) wrote :

debugging patch: https://review.opendev.org/c/openstack/tempest/+/764020

Revision history for this message
Ghanshyam Mann (ghanshyammann) wrote :

it failing with 50

 tempest.lib.exceptions.ServerFault: Got server fault
Details: b'<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">\n<html><head>\n<title>500 Internal Server Error</title>\n</head><body>\n<h1>Internal Server Error</h1>\n<p>The server encountered an internal error or\nmisconfiguration and was unable to complete\nyour request.</p>\n<p>Please contact the server administrator at \n [no address given] to inform them of the time this error occurred,\n and the actions you performed just before this error.</p>\n<p>More information about this error may be available\nin the server error log.</p>\n<hr>\n<address>Apache/2.4.41 (Ubuntu) Server at 10.209.38.200 Port 8080</address>\n</body></html>\n'

Revision history for this message
Ghanshyam Mann (ghanshyammann) wrote :

* its failing with 500 error from swift

Revision history for this message
Tim Burke (1-tim-z) wrote :
Download full text (4.4 KiB)

Apache's tls-proxy_access_log.txt log has

2020-11-24 21:29:12.540 [-] 10.209.38.200 "GET /v1/AUTH_f02f6800364d41db9322eb0b6c1ed55e/tempest-TestContainer-57357202/tempest-TestObject-674071726 HTTP/1.1" 200 1024
2020-11-24 21:29:12.017 [-] 10.209.38.200 "DELETE /volume/v3/3a115fee76b248418018a3f6a8537029/attachments/e995b5ad-46ba-4ae3-9111-bbc8f1f9c32a HTTP/1.1" 200 19
2020-11-24 21:29:12.568 [-] 10.209.38.200 "PUT /v1/AUTH_f02f6800364d41db9322eb0b6c1ed55e/tempest-TestContainer-57357202/tempest-TestObject-2147229064 HTTP/1.1" 500 612
2020-11-24 21:29:12.596 [-] 10.209.38.200 "PUT /v1/AUTH_f02f6800364d41db9322eb0b6c1ed55e/tempest-TestContainer-57357202/tempest-TestObject-31266280 HTTP/1.1" 201 -

But Swift's proxy logs only have

Nov 24 21:29:12.554307 ubuntu-focal-rax-dfw-0021910027 swift-proxy-server[80900]: proxy-server: 10.209.38.200 10.209.38.200 24/Nov/2020/21/29/12 GET /v1/AUTH_f02f6800364d41db9322eb0b6c1ed55e/tempest-TestContainer-57357202/tempest-TestObject-674071726 HTTP/1.0 200 - python-urllib3/1.26.2 gAAAAABfvXsm... - 1024 - txc38b7fc798f94e35b4c50-005fbd7b28 - 0.0118 - - 1606253352.541810036 1606253352.553643703 0
Nov 24 21:29:12.599428 ubuntu-focal-rax-dfw-0021910027 proxy-server[80900]: Authenticating user token
Nov 24 21:29:12.599777 ubuntu-focal-rax-dfw-0021910027 swift-proxy-server[80900]: proxy-server: Authenticating user token
Nov 24 21:29:12.600137 ubuntu-focal-rax-dfw-0021910027 proxy-server[80900]: Validating token access rules against request
Nov 24 21:29:12.600290 ubuntu-focal-rax-dfw-0021910027 swift-proxy-server[80900]: proxy-server: Validating token access rules against request
Nov 24 21:29:12.600472 ubuntu-focal-rax-dfw-0021910027 proxy-server[80900]: Received request from user: user_id 2f570e5e26744d0dad006374660e9f19, project_id f02f6800364d41db9322eb0b6c1ed55e, roles reader,member
Nov 24 21:29:12.600660 ubuntu-focal-rax-dfw-0021910027 swift-proxy-server[80900]: proxy-server: Received request from user: user_id 2f570e5e26744d0dad006374660e9f19, project_id f02f6800364d41db9322eb0b6c1ed55e, roles reader,member
Nov 24 21:29:12.600856 ubuntu-focal-rax-dfw-0021910027 proxy-server[80900]: Using identity: {'user': ('2f570e5e26744d0dad006374660e9f19', 'tempest-ObjectTest-1675783227'), 'tenant': ('f02f6800364d41db9322eb0b6c1ed55e', 'tempest-ObjectTest-1675783227'), 'roles': ['reader', 'member'], 'service_roles': [], 'user_domain': ('default', 'Default'), 'project_domain': ('default', 'Default'), 'auth_version': 3} (txn: txc52014b2a61042589ab99-005fbd7b28)
Nov 24 21:29:12.601087 ubuntu-focal-rax-dfw-0021910027 swift-proxy-server[80900]: proxy-server: Using identity: {'user': ('2f570e5e26744d0dad006374660e9f19', 'tempest-ObjectTest-1675783227'), 'tenant': ('f02f6800364d41db9322eb0b6c1ed55e', 'tempest-ObjectTest-1675783227'), 'roles': ['reader', 'member'], 'service_roles': [], 'user_domain': ('default', 'Default'), 'project_domain': ('default', 'Default'), 'auth_version': 3} (txn: txc52014b2a61042589ab99-005fbd7b28)
Nov 24 21:29:12.602511 ubuntu-focal-rax-dfw-0021910027 proxy-server[80900]: allow user with role(s) member as account admin (txn: txc52014b2a61042589ab99-005fbd7b28) (client_ip: 10.209.38.200)
Nov 24 21:29:12.6026...

Read more...

Revision history for this message
Tim Burke (1-tim-z) wrote :

Oh hey! Buried in tls-proxy_error_log.txt and only found by searching for the timestamp from the access log, truncated to the tenth-of-a-second:

2020-11-24 21:29:12.569193 [proxy_http:error] [pid 82341:tid 140247123883776] [client 10.209.38.200:50022] [frontend 10.209.38.200:8080] AH01093: chunked, chunked Transfer-Encoding is not supported

From https://github.com/apache/httpd/blob/2.4.41/modules/proxy/mod_proxy_http.c#L612-L625 it seems like the client is sending a header like

  Transfer-Encoding: chunked, chunked

Looks like a client bug.

Changed in swift:
status: New → Invalid
Revision history for this message
Martin Kopec (mkopec) wrote :

Meanwhile the test is skipped to unblock CI: https://review.opendev.org/c/openstack/tempest/+/764061

Revision history for this message
Martin Kopec (mkopec) wrote :

Hmm, I don't see any change around the time frame in the test or the swift client. Is it for sure the client's fault?

Tempest forms the request by:
resp, resp_body = self.raw_request(req_url, method, headers=req_headers, body=req_body, chunked=chunked)

where:
>>> req_url
'<hostname>:<port>/v1/AUTH_4ca059edfed3498abcd9ccc3dcc0b92a/tempest-TestContainer-1630726519/tempest
-TestObject-346282012'
>>> method
'PUT'
>>> req_headers
{'Transfer-Encoding': 'chunked', 'X-Auth-Token': '<token>'}
>>> req_body
<generator object chunkify at 0x7f6d4c442048>
>>> chunked
True

and the response:
>>> vars(resp)
{'status': 500, 'reason': 'Internal Server Error', 'version': 11}
>>> resp_body
b'<!DOCTYPE HTML PUBLIC "-//IETF//DTD HTML 2.0//EN">\n<html><head>\n<title>500 Internal Server
Error</title>\n</head><body>\n<h1>Internal Server Error</h1>\n<p>The server encountered an internal error
or\nmisconfiguration and was unable to complete\nyour request.</p>\n<p>Please contact the server administrator at \n
[no address given] to inform them of the time this error occurred,\n and the actions you performed just before this
error.</p>\n<p>More information about this error may be available\nin the server error log.</p>\n</body></html>\n'

Wasn't merged any change in swift around 20th Nov which would change/affect its api?

Revision history for this message
Martin Kopec (mkopec) wrote :

https://review.opendev.org/c/openstack/tempest/+/812256

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to tempest (master)

Reviewed: https://review.opendev.org/c/openstack/tempest/+/812256
Committed: https://opendev.org/openstack/tempest/commit/a7bcabc8976e6e646d5e4379e3289b43586261c1
Submitter: "Zuul (22348)"
Branch: master

commit a7bcabc8976e6e646d5e4379e3289b43586261c1
Author: Martin Kopec <email address hidden>
Date: Sat Oct 2 18:20:41 2021 +0000

    Mark unstable test_create_object_with_transfer_encoding

    Let's try to unskip test_create_object_with_transfer_encoding
    and see if it's still failing. The commit marks the test as
    unstable so that it doesn't fail a check/gate job in case the
    test fails again.

    Related-Bug: #1905432
    Change-Id: I84ad0a3a699cc0c04b2ce173edceb1df46f8c7a1

Martin Kopec (mkopec)
Changed in tempest:
assignee: nobody → Martin Kopec (mkopec)
status: New → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix proposed to tempest (master)

Related fix proposed to branch: master
Review: https://review.opendev.org/c/openstack/tempest/+/849506

Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Related fix merged to tempest (master)

Reviewed: https://review.opendev.org/c/openstack/tempest/+/849506
Committed: https://opendev.org/openstack/tempest/commit/be58876debad775d59c72a99daba86d61816bed1
Submitter: "Zuul (22348)"
Branch: master

commit be58876debad775d59c72a99daba86d61816bed1
Author: Roman Popelka <email address hidden>
Date: Tue Jul 12 14:36:10 2022 +0200

    Remove unstable_test decorator

    Removing unstable_test decorator from
    test_create_object_with_transfer_encoding method.

    The test seems to be passing in most of the jobs,
    therefore there is no need to have the decorator anymore.

    Related-Bug: #1905432
    Closes-Bug: #1905432
    Change-Id: Iad12907914148b4185f4620dd5607b7d2aa09a02

Revision history for this message
Martin Kopec (mkopec) wrote :

marking this as Fix Released as it appears that the test is fixed, feel free to reopen in case this starts failing again

Changed in tempest:
status: In Progress → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/tempest 32.0.0

This issue was fixed in the openstack/tempest 32.0.0 release.

To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

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