Bug #47306: rgw: FAIL: test_all (tasks.mgr.dashboard.test_rgw.RgwBucketTest) - rgw - Ceph

Actions

Copy link

Bug #47306

closed

rgw: FAIL: test_all (tasks.mgr.dashboard.test_rgw.RgwBucketTest)

Added by Ernesto Puerta over 3 years ago. Updated over 3 years ago.

Status:

Resolved

Priority:

Immediate

Assignee:

Casey Bodley

Target version:

Ceph - v16.0.0

% Done:

Source:

Development

Tags:

Backport:

octopus, nautilus

Regression:

Severity:

1 - critical

Reviewed:

Affected Versions:

Ceph - v16.0.0

ceph-qa-suite:

Pull request ID:

37054

Crash signature (v1):

Crash signature (v2):

Description

The error report and why this is not a flapping one¶

2020-09-03 18:03:07,331.331 INFO:__main__:----------------------------------------------------------------------
2020-09-03 18:03:07,331.331 INFO:__main__:Traceback (most recent call last):
2020-09-03 18:03:07,331.331 INFO:__main__:  File "/home/jenkins-build/build/workspace/ceph-api/qa/tasks/mgr/dashboard/test_rgw.py", line 288, in test_all
2020-09-03 18:03:07,331.331 INFO:__main__:    self.assertEqual(len(data), 0)
2020-09-03 18:03:07,332.332 INFO:__main__:AssertionError: 1 != 0
2020-09-03 18:03:07,332.332 INFO:__main__:
2020-09-03 18:03:07,332.332 INFO:__main__:----------------------------------------------------------------------
2020-09-03 18:03:07,332.332 INFO:__main__:Ran 193 tests in 2142.009s
2020-09-03 18:03:07,332.332 INFO:__main__:
2020-09-03 18:03:07,332.332 INFO:__main__:

This error first appeared in PR https://github.com/ceph/ceph/pull/31663 (https://jenkins.ceph.com/job/ceph-api/2359/), which was merged with that error raising. All subsequent builds (99%) are consistently failing due to this.

RGW team (Casey and and J. Eric Ivancich) launched a revert PR to verify whether this was the reason. The PR reverted resulted in the same failure. This may mean:

This error was NOT caused by this PR. Chances are that: a dependency update caused (Python libraries, ceph-build, ...). This is partly discarded by the fact that this test is still passing in nautilus and, especially, octopus, which has similar dependencies.
This error WAS caused by this PR but 'reinforced' by a later PR (as other RGW PRs have happened later, see the list below). To discard this situation, the revert should be applied right after the original one. The list of RGW PRs merged with failed API tests is long:
- rgw: do initialization in init_processing() for range copy: Reverts failed [1] [2]
- ~~rgw: urlencode bucket name when forwarding request: Revert [1]~~
- ~~rgw: replace '+' with %20 in canonical query string for s3 v4 auth.: Revert [1]~~
- ~~rgw: Swift API anonymous access should 401: Revert [1]~~
- rgw: RGWObjVersionTracker tracks version over increments: Revert [1] (*CANDIDATE PR*, as reverting it made API tests pass).

Issue analysis¶

Failed API test (qa/tasks/mgr/dashboard/test_rgw.py:288): It's basically using MFA Deletes/TOTP. On removing a bucket, RGW is returning 200 while logging ERROR: could not remove bucket teuth-test-bucket // req 31 0.024000438s :remove_bucket remove_bucket returned ret=-125. 200 for DELETE means that the deletion was successful. However, a later bucket listing indeed shows that the bucket was not deleted.

Logs from radosgw:

2020-09-07T12:10:11.978+0000 7f0ca3937700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.054+0000 7f0c92915700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.076001385s ======
2020-09-07T12:10:12.054+0000 7f0c92915700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.054338+0000] "PUT /teuth-test-bucket HTTP/1.1" 200 880 - "python-requests/2.20.0" -
2020-09-07T12:10:12.175+0000 7f0c9691d700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.179+0000 7f0c9691d700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.004000073s ======
2020-09-07T12:10:12.179+0000 7f0c9691d700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.179340+0000] "GET /admin/bucket HTTP/1.1" 200 21 - "python-requests/2.20.0" -
2020-09-07T12:10:12.294+0000 7f0c91112700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.296+0000 7f0c9f92f700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.002000036s ======
2020-09-07T12:10:12.296+0000 7f0c9f92f700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.296342+0000] "GET /admin/bucket?bucket=teuth-test-bucket HTTP/1.1" 200 723 - "python-requests/2.20.0" -
2020-09-07T12:10:12.301+0000 7f0ca0931700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.302+0000 7f0ca0931700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.302+0000 7f0ca0931700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.302342+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 2 - "python-requests/2.20.0" -
2020-09-07T12:10:12.306+0000 7f0c9e92d700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.307+0000 7f0c9e92d700  1 ====== req done req=0x7f0ce8935640 op status=-2046 http_status=404 latency=0.001000018s ======
2020-09-07T12:10:12.307+0000 7f0c9e92d700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.307342+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:12.373+0000 7f0c98120700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.417+0000 7f0c98120700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.044000802s ======
2020-09-07T12:10:12.417+0000 7f0c98120700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.417344+0000] "PUT /admin/bucket?bucket=teuth-test-bucket&bucket-id=a98d0c78-a903-4fa3-9e14-032fb698e9ee.4769.1&uid=teuth-test-user HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:12.428+0000 7f0c98921700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.429+0000 7f0c98921700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.429+0000 7f0c98921700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.429344+0000] "GET /admin/user?uid=teuth-test-user HTTP/1.1" 200 1075 - "python-requests/2.20.0" -
2020-09-07T12:10:12.486+0000 7f0c8f90f700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.487+0000 7f0c8f90f700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.487+0000 7f0c8f90f700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.487345+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 2 - "python-requests/2.20.0" -
2020-09-07T12:10:12.497+0000 7f0c9d12a700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.513+0000 7f0c8b907700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.016000291s ======
2020-09-07T12:10:12.513+0000 7f0c8b907700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.513346+0000] "PUT /teuth-test-bucket?versioning HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:12.525+0000 7f0c8c909700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.527+0000 7f0c8c909700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0.002000037s ======
2020-09-07T12:10:12.527+0000 7f0c8c909700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.527346+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:12.573+0000 7f0c8b106700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.574+0000 7f0c8b106700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.574+0000 7f0c8b106700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.574347+0000] "GET /admin/bucket?bucket=teuth-test-bucket HTTP/1.1" 200 733 - "python-requests/2.20.0" -
2020-09-07T12:10:12.579+0000 7f0c89903700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.579+0000 7f0c89903700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0s ======
2020-09-07T12:10:12.579+0000 7f0c89903700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.579347+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 43 - "python-requests/2.20.0" -
2020-09-07T12:10:12.582+0000 7f0c860fc700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.583+0000 7f0c860fc700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0.001000018s ======
2020-09-07T12:10:12.583+0000 7f0c860fc700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.583347+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:12.688+0000 7f0c868fd700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.735+0000 7f0c868fd700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.047000857s ======
2020-09-07T12:10:12.735+0000 7f0c868fd700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.735350+0000] "PUT /admin/bucket?bucket=teuth-test-bucket&bucket-id=a98d0c78-a903-4fa3-9e14-032fb698e9ee.4769.1&uid=teuth-test-user HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:12.748+0000 7f0c8e90d700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.749+0000 7f0c7a8e5700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.749+0000 7f0c7a8e5700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.749350+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 43 - "python-requests/2.20.0" -
2020-09-07T12:10:12.758+0000 7f0c7e8ed700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.782+0000 7f0c788e1700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.024000438s ======
2020-09-07T12:10:12.782+0000 7f0c788e1700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.782351+0000] "PUT /teuth-test-bucket?versioning HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:12.787+0000 7f0c790e2700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.787+0000 7f0c790e2700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0s ======
2020-09-07T12:10:12.787+0000 7f0c790e2700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.787351+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:12.878+0000 7f0c780e0700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:12.879+0000 7f0c780e0700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:12.879+0000 7f0c780e0700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:12.879353+0000] "GET /admin/bucket?bucket=teuth-test-bucket HTTP/1.1" 200 733 - "python-requests/2.20.0" -
2020-09-07T12:10:12.884+0000 7f0c7f0ee700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.885+0000 7f0c7f0ee700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.001000019s ======
2020-09-07T12:10:12.885+0000 7f0c7f0ee700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.885353+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 42 - "python-requests/2.20.0" -
2020-09-07T12:10:12.890+0000 7f0caa945700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:12.890+0000 7f0caa945700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0s ======
2020-09-07T12:10:12.890+0000 7f0caa945700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:12.890353+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:15.947+0000 7f0c708d1700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:16.011+0000 7f0c6f0ce700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.064001167s ======
2020-09-07T12:10:16.011+0000 7f0c6f0ce700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:16.011410+0000] "PUT /admin/bucket?bucket=teuth-test-bucket&bucket-id=a98d0c78-a903-4fa3-9e14-032fb698e9ee.4769.1&uid=teuth-test-user HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:16.015+0000 7f0c838f7700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:16.016+0000 7f0c838f7700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.001000018s ======
2020-09-07T12:10:16.016+0000 7f0c838f7700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:16.016410+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 42 - "python-requests/2.20.0" -
2020-09-07T12:10:16.021+0000 7f0c830f6700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:16.042+0000 7f0c808f1700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0.021000383s ======
2020-09-07T12:10:16.042+0000 7f0c808f1700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:16.042410+0000] "PUT /teuth-test-bucket?versioning HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:16.047+0000 7f0c820f4700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:16.047+0000 7f0c820f4700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0s ======
2020-09-07T12:10:16.047+0000 7f0c820f4700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:16.047410+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:16.148+0000 7f0c698c3700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:16.150+0000 7f0c6e0cc700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.002000037s ======
2020-09-07T12:10:16.150+0000 7f0c6e0cc700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:16.150412+0000] "GET /admin/bucket?bucket=teuth-test-bucket HTTP/1.1" 200 733 - "python-requests/2.20.0" -
2020-09-07T12:10:16.155+0000 7f0c640b8700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:16.155+0000 7f0c638b7700  1 ====== req done req=0x7f0ce88b4640 op status=0 http_status=200 latency=0s ======
2020-09-07T12:10:16.155+0000 7f0c638b7700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:16.155412+0000] "GET /teuth-test-bucket?versioning HTTP/1.1" 200 45 - "python-requests/2.20.0" -
2020-09-07T12:10:16.162+0000 7f0c640b8700  1 ====== starting new request req=0x7f0ce88b4640 =====
2020-09-07T12:10:16.163+0000 7f0c640b8700  1 ====== req done req=0x7f0ce88b4640 op status=-2046 http_status=404 latency=0.001000019s ======
2020-09-07T12:10:16.163+0000 7f0c640b8700  1 beast: 0x7f0ce88b4640: 172.20.0.3 - - [2020-09-07T12:10:16.163412+0000] "GET /teuth-test-bucket?object-lock HTTP/1.1" 404 174 - "python-requests/2.20.0" -
2020-09-07T12:10:16.253+0000 7f0c610b2700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:16.277+0000 7f0c610b2700 -1 ERROR: could not remove bucket teuth-test-bucket
2020-09-07T12:10:16.277+0000 7f0c610b2700  0 req 31 0.024000438s :remove_bucket remove_bucket returned ret=-125
2020-09-07T12:10:16.277+0000 7f0c6d0ca700  1 ====== req done req=0x7f0ce8935640 op status=-125 http_status=200 latency=0.024000438s ======
2020-09-07T12:10:16.277+0000 7f0c6d0ca700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:16.277415+0000] "DELETE /admin/bucket?bucket=teuth-test-bucket&purge-objects=true HTTP/1.1" 200 0 - "python-requests/2.20.0" -
2020-09-07T12:10:16.348+0000 7f0c618b3700  1 ====== starting new request req=0x7f0ce8935640 =====
2020-09-07T12:10:16.353+0000 7f0c6b8c7700  1 ====== req done req=0x7f0ce8935640 op status=0 http_status=200 latency=0.005000092s ======
2020-09-07T12:10:16.353+0000 7f0c6b8c7700  1 beast: 0x7f0ce8935640: 172.20.0.3 - - [2020-09-07T12:10:16.353416+0000] "GET /admin/bucket HTTP/1.1" 200 21 - "python-requests/2.20.0" -

Files

Download all files

failures.png (555 KB) failures.png		Ernesto Puerta, 09/07/2020 08:22 AM
osd.0.log.gz (417 Bytes) osd.0.log.gz		Mark Kogan, 09/08/2020 04:29 PM
radosgw.8000.log.gz (7.14 KB) radosgw.8000.log.gz		Mark Kogan, 09/08/2020 04:29 PM

Related issues 2 (0 open — 2 closed)

Actions

Copy link

Also available in: Atom PDF

Project

General

Profile

Ceph » rgw

Custom queries

Bug #47306

rgw: FAIL: test_all (tasks.mgr.dashboard.test_rgw.RgwBucketTest)

The error report and why this is not a flapping one¶

Issue analysis¶

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Mark Kogan over 3 years ago

Updated by Casey Bodley over 3 years ago

Updated by Ernesto Puerta over 3 years ago

Updated by Laura Paduano over 3 years ago

Updated by Casey Bodley over 3 years ago

Updated by Casey Bodley over 3 years ago

Updated by Nathan Cutler over 3 years ago

Updated by Nathan Cutler over 3 years ago

Updated by Nathan Cutler over 3 years ago

Updated by Nathan Cutler over 3 years ago

Updated by Nathan Cutler over 3 years ago

Updated by Nathan Cutler over 3 years ago