Bug 2270529

Summary: [rgw][s3-tests]: test_object_anon_put_write_access failed with "An error occurred (XAmzContentSHA256Mismatch) when calling the PutObject operation"
Product: [Red Hat Storage] Red Hat Ceph Storage Reporter: Matt Benjamin (redhat) <mbenjamin>
Component: RGWAssignee: Matt Benjamin (redhat) <mbenjamin>
Status: CLOSED ERRATA QA Contact: Hemanth Sai <hmaheswa>
Severity: high Docs Contact: Disha Walvekar <dwalveka>
Priority: unspecified    
Version: 7.0CC: akraj, ceph-eng-bugs, cephqe-warriors, dwalveka, hmaheswa, mkasturi, tserlin, vereddy
Target Milestone: ---Keywords: Automation, Regression
Target Release: 7.0z2   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: ceph-18.2.0-190.el9cp Doc Type: Bug Fix
Doc Text:
Previously, one valid-form of 0-length trailing chunk boundary formatting was not handled. Due to this, RGW failed to correctly recognize the start of the trailing chunk, leading to the 403 error. With this fix, improved trailing chunk boundary detection is implemented and the unexpected 403 error in the anonymous access case no longer reproduces.
 Story Points: ---
Clone Of: 2266411 Environment:
Last Closed: 2024-05-07 12:09:25 UTC Type: ---
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On: 2266411    
Bug Blocks: 2267614, 2270485, 2298578, 2298579    

Description Matt Benjamin (redhat) 2024-03-20 19:56:45 UTC 
+++ This bug was initially created as a clone of Bug #2266411 +++

Description of problem:
s3-tests: test_object_anon_put_write_access failed with "botocore.exceptions.ClientError: An error occurred (XAmzContentSHA256Mismatch) when calling the PutObject operation: None"


2024-02-12 14:07:14,339 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'=================================== FAILURES ==================================='
2024-02-12 14:07:14,339 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'______________________ test_object_anon_put_write_access _______________________'
2024-02-12 14:07:14,340 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b''
2024-02-12 14:07:14,340 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    def test_object_anon_put_write_access():'
2024-02-12 14:07:14,341 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"        bucket_name = _setup_bucket_acl('public-read-write')"
2024-02-12 14:07:14,342 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        client = get_client()'
2024-02-12 14:07:14,342 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"        client.put_object(Bucket=bucket_name, Key='foo')"
2024-02-12 14:07:14,343 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,343 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        unauthenticated_client = get_unauthenticated_client()'
2024-02-12 14:07:14,344 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,345 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b">       response = unauthenticated_client.put_object(Bucket=bucket_name, Key='foo', Body='foo')"
2024-02-12 14:07:14,345 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b''
2024-02-12 14:07:14,346 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b's3tests_boto3/functional/test_s3.py:3393: '
2024-02-12 14:07:14,346 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ '
2024-02-12 14:07:14,347 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'.tox/py/lib/python3.9/site-packages/botocore/client.py:514: in _api_call'
2024-02-12 14:07:14,347 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    return self._make_api_call(operation_name, kwargs)'
2024-02-12 14:07:14,348 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ '
2024-02-12 14:07:14,349 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b''
2024-02-12 14:07:14,349 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'self = <botocore.client.S3 object at 0x7ff88e413340>'
2024-02-12 14:07:14,350 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"operation_name = 'PutObject'"
2024-02-12 14:07:14,351 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"api_params = {'Body': <_io.BytesIO object at 0x7ff88d319540>, 'Bucket': 'test-v8m6qqm4dx2oyev5bjz3fzmo-217', 'Key': 'foo'}"
2024-02-12 14:07:14,352 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b''
2024-02-12 14:07:14,352 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    def _make_api_call(self, operation_name, api_params):'
2024-02-12 14:07:14,353 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        operation_model = self._service_model.operation_model(operation_name)'
2024-02-12 14:07:14,353 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        service_name = self._service_model.service_name'
2024-02-12 14:07:14,354 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        history_recorder.record('
2024-02-12 14:07:14,355 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'API_CALL',"
2024-02-12 14:07:14,355 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            {'
2024-02-12 14:07:14,356 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"                'service': service_name,"
2024-02-12 14:07:14,356 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"                'operation': operation_name,"
2024-02-12 14:07:14,357 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"                'params': api_params,"
2024-02-12 14:07:14,358 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            },'
2024-02-12 14:07:14,358 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        )'
2024-02-12 14:07:14,359 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        if operation_model.deprecated:'
2024-02-12 14:07:14,359 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            logger.debug('
2024-02-12 14:07:14,360 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"                'Warning: %s.%s() is deprecated', service_name, operation_name"
2024-02-12 14:07:14,360 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            )'
2024-02-12 14:07:14,361 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        request_context = {'
2024-02-12 14:07:14,362 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'client_region': self.meta.region_name,"
2024-02-12 14:07:14,362 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'client_config': self.meta.config,"
2024-02-12 14:07:14,363 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'has_streaming_input': operation_model.has_streaming_input,"
2024-02-12 14:07:14,363 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'auth_type': operation_model.auth_type,"
2024-02-12 14:07:14,364 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        }'
2024-02-12 14:07:14,365 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        request_dict = self._convert_to_request_dict('
2024-02-12 14:07:14,365 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            api'
2024-02-12 14:07:14,366 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'_params, operation_model, context=request_context'
2024-02-12 14:07:14,366 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        )'
2024-02-12 14:07:14,367 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        resolve_checksum_context(request_dict, operation_model, api_params)'
2024-02-12 14:07:14,368 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,368 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        service_id = self._service_model.service_id.hyphenize()'
2024-02-12 14:07:14,369 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        handler, event_response = self.meta.events.emit_until_response('
2024-02-12 14:07:14,369 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'before-call.{service_id}.{operation_name}'.format("
2024-02-12 14:07:14,370 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'                service_id=service_id, operation_name=operation_name'
2024-02-12 14:07:14,370 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            ),'
2024-02-12 14:07:14,371 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            model=operation_model,'
2024-02-12 14:07:14,372 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            params=request_dict,'
2024-02-12 14:07:14,372 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            request_signer=self._request_signer,'
2024-02-12 14:07:14,373 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            context=request_context,'
2024-02-12 14:07:14,373 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        )'
2024-02-12 14:07:14,374 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,375 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        if event_response is not None:'
2024-02-12 14:07:14,375 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            http, parsed_response = event_response'
2024-02-12 14:07:14,376 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        else:'
2024-02-12 14:07:14,376 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            apply_request_checksum(request_dict)'
2024-02-12 14:07:14,377 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            http, parsed_response = self._make_request('
2024-02-12 14:07:14,377 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'                operation_model, request_dict, request_context'
2024-02-12 14:07:14,378 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            )'
2024-02-12 14:07:14,379 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,379 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        self.meta.events.emit('
2024-02-12 14:07:14,380 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b"            'after-call.{service_id}.{operation_name}'.format("
2024-02-12 14:07:14,380 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'                service_id=service_id, operat'
2024-02-12 14:07:14,381 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'ion_name=operation_name'
2024-02-12 14:07:14,381 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            ),'
2024-02-12 14:07:14,382 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            http_response=http,'
2024-02-12 14:07:14,383 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            parsed=parsed_response,'
2024-02-12 14:07:14,383 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            model=operation_model,'
2024-02-12 14:07:14,384 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            context=request_context,'
2024-02-12 14:07:14,384 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        )'
2024-02-12 14:07:14,385 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'    '
2024-02-12 14:07:14,386 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'        if http.status_code >= 300:'
2024-02-12 14:07:14,387 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            error_code = parsed_response.get("Error", {}).get("Code")'
2024-02-12 14:07:14,387 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'            error_class = self.exceptions.from_code(error_code)'
2024-02-12 14:07:14,388 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'>           raise error_class(parsed_response, operation_name)'
2024-02-12 14:07:14,388 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'E           botocore.exceptions.ClientError: An error occurred (XAmzContentSHA256Mismatch) when calling the PutObject operation: None'
2024-02-12 14:07:14,389 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b''
2024-02-12 14:07:14,390 (cephci.test_s3) [DEBUG] - cephci.Weekly.rgw.23.cephci.ceph.ceph.py:1528 - b'.tox/py/lib/python3.9/site-packages/botocore/client.py:938: ClientError'






failure logs on 7.0 and 7.1:

http://magna002.ceph.redhat.com/cephci-jenkins/test-runs/18.2.0-152/Weekly/rgw/25/sanity_rgw/execute_s3tests_0.log

http://magna006.ceph.redhat.com/cephci-jenkins/test-runs/18.2.1-11/Weekly/rgw/23/sanity_rgw/execute_s3tests_0.log



pass logs on pacific and quincy:

http://magna002.ceph.redhat.com/cephci-jenkins/test-runs/16.2.10-248/Weekly/rgw/11/tier-2_rgw_ssl_s3tests/execute_s3tests_0.log

http://magna002.ceph.redhat.com/cephci-jenkins/test-runs/16.2.10-248/Weekly/rgw/11/tier-2_rgw_regression/execute_s3tests_0.log

http://magna002.ceph.redhat.com/cephci-jenkins/test-runs/17.2.6-196/Weekly/rgw/24/tier-2_rgw_regression/execute_s3tests_0.log

http://magna002.ceph.redhat.com/cephci-jenkins/test-runs/17.2.6-196/Weekly/rgw/24/tier-2_rgw_ssl_s3tests/execute_s3tests_0.log


Version-Release number of selected component (if applicable):
ceph Version 18.2.0-152.el9cp

How reproducible:
always

Steps to Reproduce:
1.deploy rhcs cluster 7.0 with rgw daemon
2.clone and configure s3tests repo
3.execute s3tests

Actual results:
test_object_anon_put_write_access failed with XAmzContentSHA256Mismatch

Expected results:
expected the test passed

Additional info:

--- Additional comment from RHEL Program Management on 2024-02-27 19:00:07 UTC ---

This bug report has Keywords: Regression or TestBlocker.

Since no regressions or test blockers are allowed between releases, it is being proposed as a blocker for this release.

Please resolve \triage ASAP.

--- Additional comment from Matt Benjamin (redhat) on 2024-03-19 15:14:55 UTC ---

This should be retested with the most recent 7.1 baseline.

Matt

--- Additional comment from errata-xmlrpc on 2024-03-19 15:25:16 UTC ---

This bug has been added to advisory RHBA-2024:126567 by Thomas Serlin (tserlin)

--- Additional comment from errata-xmlrpc on 2024-03-19 15:25:17 UTC ---

Bug report changed to ON_QA status by Errata System.
A QE request has been submitted for advisory RHBA-2024:126567-01
https://errata.engineering.redhat.com/advisory/126567

--- Additional comment from errata-xmlrpc on 2024-03-19 15:25:29 UTC ---

This bug has been added to advisory RHBA-2024:126567 by Thomas Serlin (tserlin)

--- Additional comment from Matt Benjamin (redhat) on 2024-03-20 19:37:36 UTC ---

oops!

I completed this upstream but had not backported the fix for 7.1, so I'm updating here

commit 8d18a83ccc29de79b745bb103c891436059c498e (HEAD -> ceph-7.1-rhel-patches, rhgitlab/ceph-7.1-rhel-patches)
Author: matt benjamin <mbenjamin>
Date:   Sat Mar 2 13:49:52 2024 -0500

    rgw_sigv4: handle '0;' as trailer-chunk boundary
    
    https://tracker.ceph.com/issues/64676
    Resolves: rhbz#2266411
    
    Signed-off-by: matt benjamin <mbenjamin>
    (cherry picked from commit ef1111a17084f6672fd40e366f92f8168a09d0a0)
Comment 11 errata-xmlrpc 2024-05-07 12:09:25 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (Red Hat Ceph Storage 7.0 Bug Fix update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2024:2743
Comment 12 Red Hat Bugzilla 2024-11-16 04:25:32 UTC 
The needinfo request[s] on this closed bug have been removed as they have been unresolved for 120 days