Seemingly interesting entries in the rgw daemon that is responsible
for shard 30.
behind shards: [30,35]
oldest incremental change not applied:
2024-09-09T10:03:53.033852+0000 [30]
(lots of these are happening)
(it is very annoying that all requests are indicated with an
address that seems to get reused all the time)
Sep 09 10:24:28 ham1-000215 radosgw[2104175]: ====== starting new
request req=0x7f6a325e5660 =====
Sep 09 10:24:28 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a325e5660 op status=0 http_status=200 latency=0.000000000s
======
Sep 09 10:24:28 ham1-000215 radosgw[2104175]: beast:
0x7f6a325e5660: 10.34.32.5 - anonymous [09/Sep/2024:10:24:28.426
+0000] "GET / HTTP/1.1" 200 231 - "nginx/1.25.5 (health check
radosgw_ok)" - latency=0.000000000s
(lots of these are happening)
Sep 09 10:24:39 ham1-000215 radosgw[2104175]: ====== starting new
request req=0x7f6a325e5660 =====
Sep 09 10:24:39 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a325e5660 op status=0 http_status=200 latency=0.000000000s
======
Sep 09 10:24:39 ham1-000215 radosgw[2104175]: beast:
0x7f6a325e5660: 10.34.32.21 - ceph-rgw-sync-backup
[09/Sep/2024:10:24:39.599 +0000] "GET
/admin/log/?type=data&id=84&info&rgwx-zonegroup=8a84e62c-0958-4e2e-8d61-58af9051e063
HTTP/1.1" 200 38 - - - latency=0.000000000s
(there are a few of these, spread through the log)
Sep 09 07:39:55 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
Sep 09 07:40:35 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
Sep 09 07:41:35 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
Sep 09 09:57:36 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
Sep 09 09:59:16 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
Sep 09 10:02:56 ham1-000215 radosgw[2104175]:
RGW-SYNC:data:sync:shard[30]: incremental sync on
triliobackup-ham1:fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1:1shard:
30on gen 0
(no more reports about that; the time 10:03:53.033852+0000 "time of
the oldest incremental change not applied" is ~1 minute after this)
(here is some sort of WARNING - it occurs every day, is this the
trigger of the lack of progress? The last one occurs before the
last of the messages above. Unfortunately the req number doesn't
occur anywhere else in the log so it's not very helpful.)
Sep 09 09:58:07 ham1-000215 radosgw[2104175]: ====== starting new
request req=0x7f6a32666660 =====
Sep 09 09:58:07 ham1-000215 radosgw[2104175]: req
10197104386188992433 0.008000183s s3:complete_multipart WARNING:
failed to unlock
fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1__multipart_workload_c50c59c2-66d0-4c22-87a9-7ac557b1df50/snapshot_b855da51-1f07-4ca5-9cbe-6cfd4e0faf9b/vm_id_843d7585-8a86-467e-b903-27b1b0c38473/vm_res_id_1fd68158-768f-4ea4-90b0-04d857f7fc49_vda/c36ca5b3-008b-4ede-af0d-1e1c59679f23.2~kC-ezzxlX43AoVgGmbT1c5ccxoTyeZv.meta
Sep 09 09:58:07 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a32666660 op status=0 http_status=200 latency=0.008000183s
======
Sep 09 09:58:07 ham1-000215 radosgw[2104175]: beast:
0x7f6a32666660: 10.34.32.21 - ceph-radosgw-trilio-backup
[09/Sep/2024:09:58:07.718 +0000] "POST
/workload_c50c59c2-66d0-4c22-87a9-7ac557b1df50/snapshot_b855da51-1f07-4ca5-9cbe-6cfd4e0faf9b/vm_id_843d7585-8a86-467e-b903-27b1b0c38473/vm_res_id_1fd68158-768f-4ea4-90b0-04d857f7fc49_vda/c36ca5b3-008b-4ede-af0d-1e1c59679f23?uploadId=2~kC-ezzxlX43AoVgGmbT1c5ccxoTyeZv
HTTP/1.1" 200 754 - "s3fs/1.90 (commit hash unknown;
GnuTLS(gcrypt))" - latency=0.008000183s
Sep 09 10:01:25 ham1-000215 radosgw[2104175]: ====== starting new
request req=0x7f6a32666660 =====
Sep 09 10:01:25 ham1-000215 radosgw[2104175]: req
13832955583618729439 0.008000182s s3:complete_multipart WARNING:
failed to unlock
fab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1__multipart_workload_c50c59c2-66d0-4c22-87a9-7ac557b1df50/snapshot_8d03fbde-d351-4353-8798-8f84eff675cc/vm_id_843d7585-8a86-467e-b903-27b1b0c38473/vm_res_id_4ff90160-f943-427c-8527-07beced85f59_vda/09716dab-c5d6-4a33-9057-b18429bed3d9.2~tUXO0LVUMkzHEvcdAyYVXSMqOvydOux.meta
Sep 09 10:01:25 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a32666660 op status=0 http_status=200 latency=0.012000274s
======
Sep 09 10:01:25 ham1-000215 radosgw[2104175]: beast:
0x7f6a32666660: 10.34.32.5 - ceph-radosgw-trilio-backup
[09/Sep/2024:10:01:25.003 +0000] "POST
/workload_c50c59c2-66d0-4c22-87a9-7ac557b1df50/snapshot_8d03fbde-d351-4353-8798-8f84eff675cc/vm_id_843d7585-8a86-467e-b903-27b1b0c38473/vm_res_id_4ff90160-f943-427c-8527-07beced85f59_vda/09716dab-c5d6-4a33-9057-b18429bed3d9?uploadId=2~tUXO0LVUMkzHEvcdAyYVXSMqOvydOux
HTTP/1.1" 200 754 - "s3fs/1.90 (commit hash unknown;
GnuTLS(gcrypt))" - latency=0.012000274s
(here is some error - what is error -2? it could be a negative
"ENOENT 2 No such file or directory". This fits with the 404.)
Sep 09 10:03:59 ham1-000215 radosgw[2104175]: ====== starting new
request req=0x7f6a325e5660 =====
Sep 09 10:03:59 ham1-000215 radosgw[2104175]: req
8299556935383576414 0.004000092s op->ERRORHANDLER: err_no=-2
new_err_no=-2
Sep 09 10:03:59 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a325e5660 op status=0 http_status=404 latency=0.004000092s
======
Sep 09 10:03:59 ham1-000215 radosgw[2104175]: beast:
0x7f6a325e5660: 10.34.32.21 - ceph-radosgw-trilio-backup
[09/Sep/2024:10:03:59.514 +0000] "HEAD
/contego_tasks/snapshot_b855da51-1f07-4ca5-9cbe-6cfd4e0faf9b
HTTP/1.1" 404 0 - "s3fs/1.90 (commit hash unknown; GnuTLS(gcrypt))"
- latency=0.004000092s
(just before the restart; some request seems to be stuck for 1309 s)
Sep 09 10:24:42 ham1-000215 systemd[1]: Stopping Ceph
rgw.ham1-backup.ham1-000215.eptemh for
fc678131-d3f5-48f0-91f4-d81e2029f637...
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: received signal:
Terminated from /dev/init -- /usr/bin/radosgw -n
client.rgw.ham1-backup.ham1-000215.eptemh -f --setuser ceph
--setgroup ceph --default-log-to-file=false
--default-log-to-journald=true --default-log-to-stderr=false (PID:
1) UID: 0
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: handle_sigterm
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: handle_sigterm set
alarm for 120
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: shutting down
Sep 09 10:24:43 ham1-000215
ceph-fc678131-d3f5-48f0-91f4-d81e2029f637-rgw-ham1-backup-ham1-000215-eptemh[2104169]:
2024-09-09T10:24:43.391+0000 7f6b63134640 -1 received signal:
Terminated from /dev/init -- /usr/bin/radosgw -n
client.rgw.ham1-backup.ham1-000215.eptemh -f --setuser ceph
--setgroup ceph --default-log-to-file=false
--default-log-to-journald=true --default-log-to-stderr=false (PID:
1) UID: 0
Sep 09 10:24:43 ham1-000215
ceph-fc678131-d3f5-48f0-91f4-d81e2029f637-rgw-ham1-backup-ham1-000215-eptemh[2104169]:
2024-09-09T10:24:43.391+0000 7f6b6699f880 -1 shutting down
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: req
823990580885441354 1309.589843750s s3:get_obj iterate_obj() failed
with -125
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: ====== req done
req=0x7f6a32666660 op status=-125 http_status=200
latency=1309.589843750s ======
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: beast:
0x7f6a32666660: 10.34.32.21 - ceph-rgw-sync-backup
[09/Sep/2024:10:02:53.801 +0000] "GET
/triliobackup-ham1/workload_c50c59c2-66d0-4c22-87a9-7ac557b1df50%2Fsnapshot_8d03fbde-d351-4353-8798-8f84eff675cc%2Fvm_id_843d7585-8a86-467e-b903-27b1b0c38473%2Fvm_res_id_4ff90160-f943-427c-8527-07beced85f59_vda%2F09716dab-c5d6-4a33-9057-b18429bed3d9?rgwx-zonegroup=8a84e62c-0958-4e2e-8d61-58af9051e063&rgwx-prepend-metadata=true&rgwx-sync-manifest&rgwx-sync-cloudtiered&rgwx-skip-decrypt&rgwx-if-not-replicated-to=7521c29d-e7f6-4812-9d0f-e1223ae425a4%3Atriliobackup-ham1%3Afab149a7-8bf6-4231-aaf7-1fb6e2e2d4ca.68875820.1
HTTP/1.1" 200 3347057253 - - - latency=1309.589843750s
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: RGW-SYNC:meta: ERROR:
failed to fetch all metadata keys
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: rgw rados thread:
ERROR: failed to run sync
Sep 09 10:24:43 ham1-000215 radosgw[2104175]: final shutdown
On 08.08.24 08:31, Eugen Block wrote:
>> Redeploying stuff seems like a much too big hammer to get
things going again. Surely there must be something more reasonable?
>
> wouldn't a restart suffice?
Probably, but when we were handling this the first time around, a
redeploy was the first thing that we tried and actually made a
difference, so for the time being I stuck with it.
> Do you see anything in the 'radosgw-admin sync error list'?
Maybe an error prevents the sync from continuing?
We did some experiments today. There were entries in 'radosgw-admin
sync error list' but only for other shard numbers. Those looked like
{
"shard_id": 1,
"entries": [
{
"id": "1_1722601657.174881_2599019.1",
"section": "data",
"name": "tbackup-zone1:blah:4/workload_blah/
snapshot_blah/vm_id_blah/vm_res_id_fblah_vda/blah",
"timestamp": "2024-08-02T12:27:37.174881Z",
"info": {
"source_zone":
"blah-blah-blah-blah-e8db1c51b705",
"error_code": 11,
"message": "failed to sync object(11) Resource
temporarily unavailable"
}
},
It seems that the first part, "tbackup-zone1" is the actual bucket
name. The second part between colons seems to be some long ID that
seemed the same in other mentions of the bucket. And the final
part, "4" here, varied.
The object that is mentioned seemed to be deleted when I checked
them later.
Today we had 2 shards behind: [30,39].
# radosgw-admin data sync status --rgw-realm backup --source-zone
zone1- backup --shard-id 30
{
"shard_id": 30,
"marker": {
"status": "incremental-sync",
"marker": "00000000000000000000:00000000000000447240",
"next_step_marker": "",
"total_entries": 0,
"pos": 0,
"timestamp": "2024-08-08T10:28:40.756653Z"
},
"pending_buckets": [
"tbackup-zone1:blah:1"
],
"recovering_buckets": [],
"current_time": "2024-08-08T11:30:47Z"
}
The other shard number had the same pending bucket.
(Timestamps might not be exactly right because I ran commands many
times and I copied this from terminal history later)
What I tried today was
radosgw-admin bucket sync init --bucket="tbackup-zone1"
--rgw-realm backup --source-zone=zone1-backup
followed by a "sync run", started in the background.
That didn't seem to have an immediate effect, but after some
minutes we got from 'radosgw-admin sync status --rgw-realm backup':
current time 2024-08-08T10:49:18Z
syncing
full sync: 0/128 shards
incremental sync: 128/128 shards
data is behind on 2 shards
behind shards: [30,39]
oldest incremental change not applied:
2024-08-08T10:28:41.601323+0000 [39]
1 shards are recovering
recovering shards: [36]
Unfortunately you can't see from this if the recovering makes any
progress.
Interestingly, the output from 'radosgw-admin sync error list
--rgw- realm backup' only goes up to shard 31... and for higher
numbers the output is simply "[]" instead of "
[
{
"shard_id": 30,
"entries": []
}
]".
I think it was at this point that we decided to restart a single
rgw daemon on the other side. I don't know if we were "lucky" but
this resulted in a change:
# radosgw-admin sync status --rgw-realm backup
realm xxxxxxxx-xxxx-xxxx-xxxx-8ddf4576ebab (backup)
zonegroup xxxxxxxx-xxxx-xxxx-xxxx-58af9051e063 (backup)
zone xxxxxxxx-xxxx-xxxx-xxxx-e1223ae425a4 (zone2-backup)
current time 2024-08-08T11:52:47Z
zonegroup features enabled: resharding
disabled: compress-encrypted
metadata sync no sync (zone is master)
data sync source: xxxxxxxx-xxxx-xxxx-xxxx-e8db1c51b705
(zone1- backup)
syncing
full sync: 0/128 shards
incremental sync: 128/128 shards
3 shards are recovering
recovering shards: [30,36,39]
After that it took another hour or so until the recovery was
finished. Probably the "radosgw-admin bucket sync run ... &"
command finished then too but after so long I wasn't looking all
the time.
Now I am very curious if this fixed something permanently, or if we
get the same situation again tomorrow. I guess we will find out. We
are alerting on the sync getting behind...
>
> Zitat von Olaf Seibert <o.seibert@xxxxxxxxxxxx>:
>
>> Hi all,
>>
>> we have some Ceph clusters with RGW replication between them.
It seems that in the last month at least, it gets stuck at around
the same time ~every day. Not 100% the same time, and also not 100%
of the days, but in the more recent days seem to happen more, and
for longer.
>>
>> With "stuck" I mean that the "oldest incremental change not
applied" is getting 5 or more minutes old, and not changing. In the
past this seemed to resolve itself in a short time, but recently it
didn't. It remained stuck at the same place for several hours.
Also, on several different occasions I noticed that the shard
number in question was the same.
>>
>> We are using Ceph 18.2.2, image id 719d4c40e096.
>>
>> The output on one end looks like this (I redacted out some of
the data because I don't know how much of the naming would be
sensitive information):
>>
>> root@zone2:/# radosgw-admin sync status --rgw-realm backup
>> realm xxxxxxxx-xxxx-xxxx-xxxx-8ddf4576ebab (backup)
>> zonegroup xxxxxxxx-xxxx-xxxx-xxxx-58af9051e063 (backup)
>> zone xxxxxxxx-xxxx-xxxx-xxxx-e1223ae425a4
(zone2-backup)
>> current time 2024-08-04T10:22:00Z
>> zonegroup features enabled: resharding
>> disabled: compress-encrypted
>> metadata sync no sync (zone is master)
>> data sync source: xxxxxxxx-xxxx-xxxx-xxxx-e8db1c51b705
(zone1- backup)
>> syncing
>> full sync: 0/128 shards
>> incremental sync: 128/128 shards
>> data is behind on 3 shards
>> behind shards: [30,90,95]
>> oldest incremental change not applied:
2024-08-04T10:05:54.015403+0000 [30]
>>
>> while on the other side it looks ok (not more than half a
minute behind):
>>
>> root@zone1:/# radosgw-admin sync status --rgw-realm backup
>> realm xxxxxxxx-xxxx-xxxx-xxxx-8ddf4576ebab (backup)
>> zonegroup xxxxxxxx-xxxx-xxxx-xxxx-58af9051e063 (backup)
>> zone xxxxxxxx-xxxx-xxxx-xxxx-e8db1c51b705
(zone1-backup)
>> current time 2024-08-04T10:23:05Z
>> zonegroup features enabled: resharding
>> disabled: compress-encrypted
>> metadata sync syncing
>> full sync: 0/64 shards
>> incremental sync: 64/64 shards
>> metadata is caught up with master
>> data sync source: xxxxxxxx-xxxx-xxxx-xxxx-e1223ae425a4
(zone2- backup)
>> syncing
>> full sync: 0/128 shards
>> incremental sync: 128/128 shards
>> data is behind on 4 shards
>> behind shards: [89,92,95,98]
>> oldest incremental change not applied:
2024-08-04T10:22:53.175975+0000 [95]
>>
>>
>> With some experimenting, we found that redeploying the RGWs on
this side resolves the situation: "ceph orch redeploy
rgw.zone1-backup". The shards go into "Recovering" state and after
a short time it is "caught up with source" as well.
>>
>> Redeploying stuff seems like a much too big hammer to get
things going again. Surely there must be something more reasonable?
>>
>> Also, any ideas about how we can find out what is causing this?
It may be that some customer has some job running every 24 hours,
but that shouldn't cause the replication to get stuck.
>>