Actions
Bug #58965
openradosgw: Stale entries in bucket indexes following successful DELETE request
Status:
New
Priority:
Normal
Assignee:
-
Category:
-
Target version:
-
% Done:
0%
Description
We observe stale entries in the bucket indexes following a DELETE request from radosgw client:
- The DELETE request completes successfully and is acknowledged to the client with an HTTP 204;
- The object being deleted is removed from OSDs storing it;
- A stale entry remains in the bucket index.
As a result, the object appears to exist when listing the bucket contents but GET or DELETE requests fail.
- s3cmd ls:
# s3cmd ls s3://the-faulty-bucket/locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf
2023-03-06 04:24 168 s3://the-faulty-bucket/locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf
- s3cmd get (with partial debug information
# s3cmd ls --debug s3://the-faulty-bucket/locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf
2023-03-06 04:24 168 s3://the-faulty-bucket/locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467
- `radosgw-admin bucket list` does not report any object with that name
# radosgw-admin bucket list --bucket=the-faulty-bucket | grep lock
[...empty...]
... while `bi list` shows stale entries
# radosgw-admin bi list --bucket=the-faulty-bucket | grep locks
"idx": "locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf",
"name": "locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf",
{
"type": "plain",
"idx": "locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf",
"entry": {
"name": "locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf",
"instance": "",
"ver": {
"pool": 7,
"epoch": 1065591
},
"locator": "",
"exists": "true",
"meta": {
"category": 1,
"size": 168,
"mtime": "2023-03-06T04:24:57.909779Z",
"etag": "59335d38d7238bf925eff2b2bf005f8c",
"storage_class": "",
"owner": "the-owner",
"owner_display_name": "the-owner-display",
"content_type": "application/octet-stream",
"accounted_size": 168,
"user_data": "",
"appendable": "false"
},
"tag": "fe32212d-631b-44fe-8d35-03f5a3551af1.263211606.4868844033",
"flags": 0,
"pending_map": [],
"versioned_epoch": 0
}
},
The radosgw log (in full debug mode) shows the primary osd (osd.1433, we use EC 4+2) returns `2 - No such file or directory` when trying to ge the object from disk
2023-03-10T17:14:55.532+0100 7f91beecd700 2 req 7383713 0s s3:get_obj recalculating target
2023-03-10T17:14:55.532+0100 7f91beecd700 2 req 7383713 0s s3:get_obj reading permissions
2023-03-10T17:14:55.532+0100 7f91beecd700 20 get_obj_state: rctx=0x7f92c0db5300 obj=the-faulty-bucket:locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf state=0x55fed37781e8 s->prefetch_data=0
2023-03-10T17:14:55.532+0100 7f91beecd700 20 WARNING: blocking librados call
2023-03-10T17:14:55.532+0100 7f91beecd700 1 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0).connect
2023-03-10T17:14:55.532+0100 7f91beecd700 1 -- 188.184.51.27:0/2032106363 --> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] -- osd_op(unknown.0.0:34421132 10.d61s0 10:86b7763e:::fe32212d-631b-44fe-8d35-03f5a3551af1.126432956.20_locks%2ffdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf:head [getxattrs,stat] snapc 0=[] ondisk+read+known_if_redirected e1131194) v8 -- 0x55fed9ef0a00 con 0x55fed9927c00
2023-03-10T17:14:55.532+0100 7f91beecd700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=START_CONNECT pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0).send_message enqueueing message m=0x55fed9ef0a00 type=42 osd_op(client.263487217.0:34421132 10.d61s0 10:86b7763e:::fe32212d-631b-44fe-8d35-03f5a3551af1.126432956.20_locks%2ffdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf:head [getxattrs,stat] snapc 0=[] ondisk+read+known_if_redirected e1131194) v8
2023-03-10T17:14:55.533+0100 7f92ad8aa700 1 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 rx=0 tx=0)._handle_peer_banner_payload supported=1 required=0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_hello received hello: peer_type=4 peer_addr_for_me=v2:188.184.51.27:31286/0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=HELLO_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_hello getsockname says I am 188.184.51.27:31286 when talking to v2:188.184.51.22:6968/11926
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 unknown :-1 s=AUTH_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_auth_reply_more auth reply more len=32
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=SESSION_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).send_client_ident sending identification: addrs=188.184.51.27:0/2032106363 target=v2:188.184.51.22:6968/11926 gid=263487217 global_seq=6407549 features_supported=3f01cfb8ffedffff features_required=800000000001000 flags=1 cookie=0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=SESSION_CONNECTING pgs=0 cs=0 l=1 rev1=1 rx=0 tx=0).handle_server_ident received server identification: addrs=[v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] gid=1433 global_seq=164102 features_supported=3f01cfb8ffedffff features_required=e01021042240000 flags=1 cookie=0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 1 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=READY pgs=164102 cs=0 l=1 rev1=1 rx=0 tx=0).ready entity=osd.1433 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=READY pgs=164102 cs=0 l=1 rev1=1 rx=0 tx=0).write_message sending message m=0x55fed9ef0a00 seq=1 osd_op(client.263487217.0:34421132 10.d61s0 10:86b7763e:::fe32212d-631b-44fe-8d35-03f5a3551af1.126432956.20_locks%2ffdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf:head [getxattrs,stat] snapc 0=[] ondisk+read+known_if_redirected e1131194) v8
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=THROTTLE_DONE pgs=164102 cs=0 l=1 rev1=1 rx=0 tx=0).handle_message got 306 + 0 + 0 byte message. envelope type=43 src osd.1433 off 0
2023-03-10T17:14:55.533+0100 7f92ad8aa700 5 --2- 188.184.51.27:0/2032106363 >> [v2:188.184.51.22:6968/11926,v1:188.184.51.22:6969/11926] conn(0x55fed9927c00 0x55fed5217400 crc :-1 s=READ_MESSAGE_COMPLETE pgs=164102 cs=0 l=1 rev1=1 rx=0 tx=0).handle_message received message m=0x55fed851cd80 seq=1 from=osd.1433 type=43 osd_op_reply(34421132 fe32212d-631b-44fe-8d35-03f5a3551af1.126432956.20_locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf [getxattrs,stat] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8
2023-03-10T17:14:55.533+0100 7f92ad8aa700 1 -- 188.184.51.27:0/2032106363 <== osd.1433 v2:188.184.51.22:6968/11926 1 ==== osd_op_reply(34421132 fe32212d-631b-44fe-8d35-03f5a3551af1.126432956.20_locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf [getxattrs,stat] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 306+0+0 (crc 0 0 0) 0x55fed851cd80 con 0x55fed9927c00
2023-03-10T17:14:55.534+0100 7f91beecd700 10 req 7383713 0.002000007s s3:get_obj read_permissions on :the-faulty-bucket[fe32212d-631b-44fe-8d35-03f5a3551af1.160079962.205]):locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf only_bucket=0 ret=-2
2023-03-10T17:14:55.534+0100 7f91beecd700 1 op->ERRORHANDLER: err_no=-2 new_err_no=-2
2023-03-10T17:14:55.534+0100 7f91beecd700 2 req 7383713 0.002000007s s3:get_obj op status=0
2023-03-10T17:14:55.534+0100 7f91beecd700 2 req 7383713 0.002000007s s3:get_obj http status=404
2023-03-10T17:14:55.534+0100 7f91beecd700 1 ====== req done req=0x7f92c0db66d0 op status=0 http_status=404 latency=0.002000007s ======
2023-03-10T17:14:55.534+0100 7f91beecd700 1 beast: 0x7f92c0db66d0: 2001:1458:d00:2::100:f0 - - [2023-03-10T17:14:55.534469+0100] "HEAD /locks/fdc7820899311db708d81a739bb3bfc34a8d0e31806f2c76d467cef0013ff8cf HTTP/1.1" 404 0 - - -
2023-03-10T17:14:55.547+0100 7f92397c2700 20 failed to read header: end of stream
2023-03-10T17:14:55.547+0100 7f9238fc1700 20 failed to read header: end of stream
Updated by Enrico Bocchi about 1 year ago
Trying to find a solution for this, we experimented with `radosgw-admin bucket check`, which does not seem to identify the issue.
# radosgw-admin bucket check --bucket=the-faulty-bucket
[]
# radosgw-admin bucket check --bucket=the-faulty-bucket --check-objects
[]
The only way to remove the stale entry with `bucket check` is to set the `--check-objects --fix` flags (the following log snipped is taken from another stale object w.r.t. the logs above):
2023-03-09T15:07:16.955+0100 7f170a8111c0 20 RGWRados::cls_bucket_list_ordered currently processing locks/ce92f49e2b5433cfa388611ea623399983b7913a7a73194e020d459077f2c43c from shard 0
2023-03-09T15:07:16.955+0100 7f170a8111c0 20 get_obj_state: rctx=0x7ffd83bb04f0 obj=the-other-faulty-bucket:locks/ce92f49e2b5433cfa388611ea623399983b7913a7a73194e020d459077f2c43c state=0x55fd49046778 s->prefetch_data=0
2023-03-09T15:07:16.955+0100 7f170a8111c0 1 -- 188.184.18.68:0/442836255 --> [v2:188.184.18.80:6816/1445130,v1:188.184.18.80:6818/1445130] -- osd_op(unknown.0.0:9111 10.1946s0 10:629a7eb6:::fe32212d-631b-44fe-8d35-03f5a3551af1.15576132.2563_locks%2fce92f49e2b5433cfa388611ea623399983b7913a7a73194e020d459077f2c43c:head [getxattrs,stat] snapc 0=[] ondisk+read+known_if_redirected e1129519) v8 -- 0x55fd49077d60 con 0x55fd487d87f0
2023-03-09T15:07:16.955+0100 7f16f8f4c700 1 -- 188.184.18.68:0/442836255 <== osd.304 v2:188.184.18.80:6816/1445130 5 ==== osd_op_reply(9111 fe32212d-631b-44fe-8d35-03f5a3551af1.15576132.2563_locks/ce92f49e2b5433cfa388611ea623399983b7913a7a73194e020d459077f2c43c [getxattrs,stat] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) v8 ==== 307+0+0 (crc 0 0 0) 0x7f16f00b9040 con 0x55fd487d87f0
2023-03-09T15:07:16.955+0100 7f170a8111c0 10 RGWRados::cls_bucket_list_ordered: skipping locks/ce92f49e2b5433cfa388611ea623399983b7913a7a73194e020d459077f2c43c[]Updated by Jonas Nemeikšis 7 months ago
This scenario identical affected us too.
Ceph version: 16.2.13
One more fact we also use Restic and stale entries locks/*
Updated by Konstantin Shalygin 5 months ago
- Source set to Community (user)
- Affected Versions v16.2.13 added
Updated by Matthew Darwin 5 months ago
We see the same issue. We are on quincy (seen same issue on pacific when we were on that before).
Updated by Jonas Nemeikšis about 1 month ago
I've detected that this issue appears when rgw/cluster gets high count requests, but not every time and I cannot debug logs.
Updated by Kai Stian Olstad about 1 month ago
We also hit this with Ceph v17.2.7.
It was a object of 545 bytes created and then deleted after 4 minutes.
Actions