test_create_object_with_transfer_encoding is failing on tripleo jobs

Bug #1982874 reported by Arx Cruz
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
tripleo
Fix Released
Critical
Unassigned

Bug Description

He is the history of this test: This test never ran before, it was always being skipped. Recently it seems this test was running fine (according upstream) and so it was unskipped on tempest commit https://github.com/openstack/tempest/commit/be58876debad775d59c72a99daba86d61816bed1

Here is the output of the failure:

ft1.13: tempest.api.object_storage.test_object_services.ObjectTest.test_create_object_with_transfer_encoding[id-4f84422a-e2f2-4403-b601-726a4220b54e]testtools.testresult.real._StringException: pythonlogging:'': {{{
2022-07-26 12:52:03,255 210485 INFO [tempest.lib.common.rest_client] Request (ObjectTest:test_create_object_with_transfer_encoding): 501 PUT http://192.168.24.3:8080/v1/AUTH_fab3880c6d974278896bddd421b039e1/tempest-TestContainer-1749106428/tempest-TestObject-286120140 0.006s
2022-07-26 12:52:03,255 210485 DEBUG [tempest.lib.common.rest_client] Request - Headers: {'Transfer-Encoding': 'chunked', 'X-Auth-Token': '<omitted>'}
        Body: <generator object chunkify at 0x7fac8c328270>
    Response - Headers: {'content-type': 'text/plain', 'content-length': '78', 'x-trans-id': 'tx4cfa0f2d87f24ba4a70fa-0062dfe373', 'x-openstack-request-id': 'tx4cfa0f2d87f24ba4a70fa-0062dfe373', 'date': 'Tue, 26 Jul 2022 12:52:03 GMT', 'connection': 'close', 'status': '501', 'content-location': 'http://192.168.24.3:8080/v1/AUTH_fab3880c6d974278896bddd421b039e1/tempest-TestContainer-1749106428/tempest-TestObject-286120140'}
        Body: b'Unsupported Transfer-Coding header value specified in Transfer-Encoding header'
}}}

Traceback (most recent call last):
  File "/usr/lib/python3.9/site-packages/tempest/api/object_storage/test_object_services.py", line 190, in test_create_object_with_transfer_encoding
    resp, _ = self.object_client.create_object(
  File "/usr/lib/python3.9/site-packages/tempest/lib/services/object_storage/object_client.py", line 51, in create_object
    resp, body = self.put(url, data, headers, chunked=chunked)
  File "/usr/lib/python3.9/site-packages/tempest/lib/common/rest_client.py", line 363, in put
    return self.request('PUT', url, extra_headers, headers, body, chunked)
  File "/usr/lib/python3.9/site-packages/tempest/lib/common/rest_client.py", line 720, in request
    self._error_checker(resp, resp_body)
  File "/usr/lib/python3.9/site-packages/tempest/lib/common/rest_client.py", line 893, in _error_checker
    raise exceptions.NotImplemented(resp_body, resp=resp,
tempest.lib.exceptions.NotImplemented: Got NotImplemented error
Details: b'Unsupported Transfer-Coding header value specified in Transfer-Encoding header'

Logs: https://logserver.rdoproject.org/63/44163/1/check/periodic-tripleo-ci-centos-9-standalone-full-tempest-api-tempest-master/5a1376b/logs/undercloud/var/log/tempest/stestr_results.html.gz

Basically opening the bug to track down and also to add this particular test on the skiplist

Revision history for this message
Christian Schwede (cschwede) wrote :

The error makes no sense from the logs we have. It would only raised in this place in the code: https://github.com/openstack/swift/blob/master/swift/common/swob.py#L866-L875

As you can see, this would only be the case if the transfer-encoding header contains a comma-separated list of strings. However, Tempest only sends a single string: https://github.com/openstack/tempest/blob/master/tempest/api/object_storage/test_object_services.py#L189-L195

This is also seen in the logs:
https://logserver.rdoproject.org/63/44163/1/check/periodic-tripleo-ci-centos-9-standalone-full-tempest-api-tempest-master/5a1376b/logs/undercloud/home/zuul/tempest/tempest.log.txt.gz
2022-07-26 12:52:03.255 210485 DEBUG tempest.lib.common.rest_client [tx4cfa0f2d87f24ba4a70fa-0062dfe373 tx4cfa0f2d87f24ba4a70fa-0062dfe373 ] Request - Headers: {'Transfer-Encoding': 'chunked', 'X-Auth-Token': '<omitted>'}

What happened inbetween, not visible in the logs?

Revision history for this message
Marios Andreou (marios-b) wrote (last edit ):
Revision history for this message
Marios Andreou (marios-b) wrote :

o/ Christian I have posted the revert for the test skip at [1].

We can use that with [2] to request a hold on the node (I have just done that).

Now we have to get lucky so that the job gets far enough and hits the issue ;)

I'll ping if we get a box and will add your keys (ones from your github profile otherwise you can tell me what in irc).

Nodes last for 24 hours but we can request again as needed.

[1] https://review.opendev.org/c/openstack/openstack-tempest-skiplist/+/852643
[2] https://review.rdoproject.org/r/c/testproject/+/44495

Revision history for this message
Marios Andreou (marios-b) wrote :

@Christian seems we got lucky ;)

The issue hit on the test @ [1].

test_create_object_with_transfer_encoding[id-4f84422a-e2f2-4403-b601-726a4220b54e]
 fail

We have a node and i added your keys, I'll add that info on the cix card momentarily

[1] https://logserver.rdoproject.org/95/44495/1/check/periodic-tripleo-ci-centos-9-standalone-full-tempest-api-tempest-master/2d1c668/logs/undercloud/var/log/tempest/stestr_results.html.gz

Revision history for this message
Christian Schwede (cschwede) wrote :

Eventually I solved this puzzle.

tcpdump showed that there are two transfer-encoding headers sent:

12:14:55.894667 IP 192.168.24.1.44722 > 192.168.24.1.8080: Flags [P.], seq 0:1579, ack 1, win 512, options [nop,nop,TS val 4247042889 ecr 4247042889], length 1579: HTTP: PUT /v1/AUTH_4871e691209040999d87900ffa281fd0/tempest-TestContainer-1848004873/tempest-TestObject-1748985446 HTTP/1.1
E.._T.@.@.................UQ...............
.$.I.$.IPUT /v1/AUTH_4871e691209040999d87900ffa281fd0/tempest-TestContainer-1848004873/tempest-TestObject-1748985446 HTTP/1.1
host: 192.168.24.3:8080
accept-encoding: identity
user-agent: python-urllib3/1.26.5
transfer-encoding: chunked
x-auth-token: gAAAAABjEKI_aAD_...
transfer-encoding: chunked
x-forwarded-proto: http
x-forwarded-port: 8080
x-forwarded-for: 192.168.24.3

While this is okay-ish according to RFC2616 (https://www.w3.org/Protocols/rfc2616/rfc2616-sec4.html#sec4.2), Swift will deliberately reject this if multiple headers are sent (https://github.com/openstack/swift/commit/5174b7f85dea42b6e0a50ee0a222637be0cea240).

Actually urllib3 adds the transfer-encoding header for chunked transfers, even if Tempest already set the header before (https://github.com/openstack/tempest/blob/master/tempest/api/object_storage/test_object_services.py#L189-L195).

However, this has been changed in urllib3 1.26.6 - while the installed version is 1.26.5 (https://github.com/urllib3/urllib3/blob/main/CHANGES.rst#1266-2021-06-25).

I updated urllib3 to 1.26.6 and the test is passing correctly then, with tcpdump showing only a single transfer-encoding header sent by Tempest/urllib3.

Revision history for this message
Christian Schwede (cschwede) wrote :

For reference, this commit is the change in urllib3 to not add a duplicate header if set before: https://github.com/urllib3/urllib3/commit/eb28aec79de922100b246f2ac1cd4625394ff70c

Revision history for this message
Soniya Murlidhar Vyas (svyas) wrote :

Thanks arx for working on this - test seems to be passing now

Revision history for this message
Arx Cruz (arxcruz) wrote :

I propose the patch, but it doesn't seems to be running yet on tripleo side, need to get https://review.opendev.org/c/openstack/tempest/+/857333 merged first

Revision history for this message
Marios Andreou (marios-b) wrote :

related patch:

"Remove branch for all tempest related projects" https://review.rdoproject.org/r/c/rdoinfo/+/45711

Ronelle Landy (rlandy)
Changed in tripleo:
status: Triaged → Fix Released
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix included in openstack/tempest 33.0.0

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

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.