Project

General

Profile

Bug #55465 » 1.log

ren weiguo, 04/27/2022 08:17 AM

 
2022-04-26T21:57:34.782 INFO:rgw_multi.tests:create bucket zone=test-zone1 name=aoqodf-46
2022-04-26T21:57:34.820 INFO:rgw_multi.tests:create bucket zone=test-zone2 name=aoqodf-47
2022-04-26T21:57:34.916 INFO:rgw_multi.tests:create bucket zone=test-zone3 name=aoqodf-48
2022-04-26T21:57:35.186 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:35.187 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:35.188 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:35.695 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981455.607576_1010.1","last_update":"2022-04-26 13:57:35.607576Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:35.696 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone2 source_zone=test-zone1
2022-04-26T21:57:35.697 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:35.697 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:35.698 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:36.238 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":7098223210824665103},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981299.752736_907.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:54:59.752736Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:36.239 WARNING:rgw_multi.tests:data of zone test-zone2 behind zone test-zone1: shard=1 master=1_1650981455.607576_1010.1 target=1_1650981299.752736_907.1
2022-04-26T21:57:41.241 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:41.242 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:41.243 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:41.756 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":7098223210824665103},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.502772_1011.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.502772Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:41.757 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone2 source_zone=test-zone1
2022-04-26T21:57:41.758 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:41.758 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:41.759 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:42.268 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.502772_1011.1","last_update":"2022-04-26 13:57:36.502772Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:42.269 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone3 source_zone=test-zone1
2022-04-26T21:57:42.269 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:42.269 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:42.270 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:42.780 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":14501821185802160608},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.502772_1011.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.502772Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:42.780 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone3 source_zone=test-zone1
2022-04-26T21:57:42.780 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:42.780 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:42.781 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 datalog status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:43.253 INFO:teuthology.orchestra.run.plana001.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.582049_963.1","last_update":"2022-04-26 13:57:36.582049Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:43.254 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone1 source_zone=test-zone2
2022-04-26T21:57:43.255 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:43.255 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:43.256 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone2 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:43.737 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":15575674840284756678},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.582049_963.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.582049Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:43.738 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone1 source_zone=test-zone2
2022-04-26T21:57:43.738 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:43.738 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:43.739 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 datalog status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:44.254 INFO:teuthology.orchestra.run.plana001.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.582049_963.1","last_update":"2022-04-26 13:57:36.582049Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:44.255 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone3 source_zone=test-zone2
2022-04-26T21:57:44.256 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:44.256 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:44.257 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone2 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:44.791 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":4845208584981704144},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.582049_963.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.582049Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:44.792 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone3 source_zone=test-zone2
2022-04-26T21:57:44.792 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:44.792 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:44.793 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:45.303 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.298046_881.1","last_update":"2022-04-26 13:57:36.298046Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:45.303 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone1 source_zone=test-zone3
2022-04-26T21:57:45.304 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:45.304 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:45.304 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone3 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:45.808 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":8650972045503614890},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.298046_881.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.298046Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:45.809 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone1 source_zone=test-zone3
2022-04-26T21:57:45.809 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:45.809 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:45.809 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:46.301 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.298046_881.1","last_update":"2022-04-26 13:57:36.298046Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:46.301 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone2 source_zone=test-zone3
2022-04-26T21:57:46.301 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:46.302 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:46.302 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone3 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:46.808 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":3777563592681651088},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.298046_881.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.298046Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:46.809 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone2 source_zone=test-zone3
2022-04-26T21:57:46.810 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:46.810 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:46.811 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:47.285 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981463.253411_1019.1","last_update":"2022-04-26 13:57:43.253411Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:47.285 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'autotrim', '--cluster', 'c1', '--debug-rgw', '20', '--debug-ms', '0']
2022-04-26T21:57:47.285 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'autotrim', '--cluster', 'c1', '--debug-rgw', '20', '--debug-ms', '0']
2022-04-26T21:57:47.286 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog autotrim --cluster c1 --debug-rgw 20 --debug-ms 0
2022-04-26T21:57:47.601 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.618659 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.607 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.624608 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.607 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.624685 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.616 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.626537 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:57:47.617 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.626567 7f61cda4af80 20 realm test-realm 2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:57:47.617 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.626580 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.617 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.627657 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:57:47.618 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.627693 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.618 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.628638 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=10
2022-04-26T21:57:47.619 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.628680 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.619 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.630137 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=1293
2022-04-26T21:57:47.620 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.630241 7f61cda4af80 20 current period b1360a77-18f5-4b20-945a-6b281595c52e
2022-04-26T21:57:47.620 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.630249 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.621 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.631045 7f61cda4af80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:57:47.622 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.631066 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.622 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.631843 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.623 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.631929 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.623 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.632469 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:57:47.624 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.632505 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.624 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.633448 7f61cda4af80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:57:47.638 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640744 7f61cda4af80 20 RGWRados::pool_iterate: got periods.c62966ba-eb7b-4b46-8b5b-a77bb20b11b3.latest_epoch
2022-04-26T21:57:47.638 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640761 7f61cda4af80 20 RGWRados::pool_iterate: got periods.b1360a77-18f5-4b20-945a-6b281595c52e.1
2022-04-26T21:57:47.638 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640762 7f61cda4af80 20 RGWRados::pool_iterate: got default.zone.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:57:47.639 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640763 7f61cda4af80 20 RGWRados::pool_iterate: got zone_info.4bdfcde7-e65d-423e-813b-baf83d7ff087
2022-04-26T21:57:47.639 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640764 7f61cda4af80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.2
2022-04-26T21:57:47.639 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640766 7f61cda4af80 20 RGWRados::pool_iterate: got period_config.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:57:47.639 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640767 7f61cda4af80 20 RGWRados::pool_iterate: got periods.c62966ba-eb7b-4b46-8b5b-a77bb20b11b3.1
2022-04-26T21:57:47.639 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640768 7f61cda4af80 20 RGWRados::pool_iterate: got realms.2a7ca286-f8d4-414f-962c-a59e22ed85fd.control
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640769 7f61cda4af80 20 RGWRados::pool_iterate: got periods.cb30fa8f-4697-4113-b569-2bdff12a8c8d.latest_epoch
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640770 7f61cda4af80 20 RGWRados::pool_iterate: got zonegroup_info.test-zonegroup
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640772 7f61cda4af80 20 RGWRados::pool_iterate: got default.realm
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640773 7f61cda4af80 20 RGWRados::pool_iterate: got instances_info.test-zone1
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640774 7f61cda4af80 20 RGWRados::pool_iterate: got instances_names.test-zone1
2022-04-26T21:57:47.640 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640775 7f61cda4af80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.latest_epoch
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640778 7f61cda4af80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.1
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640779 7f61cda4af80 20 RGWRados::pool_iterate: got instances_info.default
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640781 7f61cda4af80 20 RGWRados::pool_iterate: got zonegroup_info.27ef2180-5eb9-4bc9-a8c4-4e9e494bf783
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640782 7f61cda4af80 20 RGWRados::pool_iterate: got instances_names.default
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640783 7f61cda4af80 20 RGWRados::pool_iterate: got default.zonegroup.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:57:47.641 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640784 7f61cda4af80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.3
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640785 7f61cda4af80 20 RGWRados::pool_iterate: got zone_names.test-zone3
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640786 7f61cda4af80 20 RGWRados::pool_iterate: got zone_info.85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640787 7f61cda4af80 20 RGWRados::pool_iterate: got periods.2a7ca286-f8d4-414f-962c-a59e22ed85fd:staging
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640789 7f61cda4af80 20 RGWRados::pool_iterate: got instances_names.test-zone3
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640790 7f61cda4af80 20 RGWRados::pool_iterate: got periods.cb30fa8f-4697-4113-b569-2bdff12a8c8d.1
2022-04-26T21:57:47.642 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640791 7f61cda4af80 20 RGWRados::pool_iterate: got zone_info.c2e95579-d813-43c7-b671-6451ec3a6d43
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640792 7f61cda4af80 20 RGWRados::pool_iterate: got zone_names.test-zone1
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640793 7f61cda4af80 20 RGWRados::pool_iterate: got zonegroups_names.test-zonegroup
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640794 7f61cda4af80 20 RGWRados::pool_iterate: got realms.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640796 7f61cda4af80 20 RGWRados::pool_iterate: got realms_names.test-realm
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640797 7f61cda4af80 20 RGWRados::pool_iterate: got periods.b1360a77-18f5-4b20-945a-6b281595c52e.latest_epoch
2022-04-26T21:57:47.643 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640798 7f61cda4af80 20 RGWRados::pool_iterate: got zone_names.default
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640799 7f61cda4af80 20 RGWRados::pool_iterate: got zonegroups_names.default
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640800 7f61cda4af80 20 RGWRados::pool_iterate: got instances_info.test-zone3
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.640822 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.642300 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.642327 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.644 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.643658 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=821
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.643699 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.644374 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.644389 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.645196 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=348
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.645225 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.645 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.645723 7f61cda4af80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.645738 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.646227 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.646243 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.646642 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.646663 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.646 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.647399 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=24
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.647415 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648202 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=764
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648219 7f61cda4af80 20 period zonegroup init ret 0
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648220 7f61cda4af80 20 period zonegroup name test-zonegroup
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648221 7f61cda4af80 20 using current period zonegroup test-zonegroup
2022-04-26T21:57:47.647 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648225 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648765 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.648776 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.649443 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.649463 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.650034 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:57:47.648 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.650048 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.651094 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=962
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.651116 7f61cda4af80 10 Cannot find current period zone using local zone
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.651118 7f61cda4af80 20 rados->read ofs=0 len=0
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.652148 7f61cda4af80 20 rados_obj.operate() r=0 bl.length=962
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.652180 7f61cda4af80 20 zone test-zone1
2022-04-26T21:57:47.649 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.652190 7f61cda4af80 20 generating connection object for zone test-zone2 id 1c709dbd-13da-4a3b-871f-39b1dcf0b20f
2022-04-26T21:57:47.650 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.652194 7f61cda4af80 20 generating connection object for zone test-zone3 id 85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:57:47.675 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694524 7f61cda4af80 20 add_watcher() i=0
2022-04-26T21:57:47.675 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694619 7f61cda4af80 20 add_watcher() i=1
2022-04-26T21:57:47.676 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694627 7f61cda4af80 20 add_watcher() i=2
2022-04-26T21:57:47.676 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694631 7f61cda4af80 20 add_watcher() i=3
2022-04-26T21:57:47.676 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694634 7f61cda4af80 20 add_watcher() i=4
2022-04-26T21:57:47.676 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.694638 7f61cda4af80 20 add_watcher() i=5
2022-04-26T21:57:47.677 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.695079 7f61cda4af80 20 add_watcher() i=6
2022-04-26T21:57:47.679 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.698487 7f61cda4af80 20 add_watcher() i=7
2022-04-26T21:57:47.679 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.698499 7f61cda4af80 2 all 8 watchers are set, enabling cache
2022-04-26T21:57:47.685 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.704679 7f61b0569700 2 RGWDataChangesLog::ChangesRenewThread: start
2022-04-26T21:57:47.688 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.707047 7f619f547700 20 reqs_thread_entry: start
2022-04-26T21:57:47.690 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.707568 7f619d543700 20 reqs_thread_entry: start
2022-04-26T21:57:47.690 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.707678 7f61cda4af80 20 init_complete bucket index max shards: 0
2022-04-26T21:57:47.690 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708086 7f619bd40700 20 reqs_thread_entry: start
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708232 7f619a53d700 20 reqs_thread_entry: start
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708247 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708255 7f61cda4af80 10 data trim: fetching sync status for zone 4bdfcde7-e65d-423e-813b-baf83d7ff087
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708274 7f61cda4af80 20 data trim: query sync status from 1c709dbd-13da-4a3b-871f-39b1dcf0b20f
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708289 7f61cda4af80 20 data trim: query sync status from 85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:57:47.691 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708298 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708300 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708301 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708302 7f61cda4af80 20 run: stack=0x7f61d0aebc20 is_blocked_by_stack()=0 is_sleeping=0 waiting_for_child()=1
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708308 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708378 7f61cda4af80 20 > HTTP_DATE -> Tue, 26 Apr 2022 13:57:47 +0000
2022-04-26T21:57:47.692 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708411 7f61cda4af80 10 get_canon_resource(): dest=/admin/log/
2022-04-26T21:57:47.693 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708413 7f61cda4af80 10 generated canonical header: GET
2022-04-26T21:57:47.693 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:57:47.693 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:57:47.693 INFO:teuthology.orchestra.run.plana002.stderr:Tue, 26 Apr 2022 13:57:47 +0000
2022-04-26T21:57:47.693 INFO:teuthology.orchestra.run.plana002.stderr:/admin/log/
2022-04-26T21:57:47.694 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708437 7f61cda4af80 15 generated auth header: AWS NIZ36PNBEDYNTX7V:qty3n/2qwKbhflMt1L0K9qfGnEc=
2022-04-26T21:57:47.694 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708454 7f61cda4af80 20 sending request to http://plana001.ceph.com:8000/admin/log/?type=data&status&source-zone=4bdfcde7-e65d-423e-813b-baf83d7ff087&rgwx-zonegroup=test-zonegroup
2022-04-26T21:57:47.694 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708469 7f61cda4af80 20 register_request mgr=0x7ffce17f3030 req_data->id=0, curl_handle=0x7f61d193b4e0
2022-04-26T21:57:47.694 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708483 7f61cda4af80 20 run: stack=0x7f61d0aeb680 is io blocked
2022-04-26T21:57:47.694 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708484 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708505 7f61cda4af80 20 > HTTP_DATE -> Tue, 26 Apr 2022 13:57:47 +0000
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708520 7f61cda4af80 10 get_canon_resource(): dest=/admin/log/
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708521 7f61cda4af80 10 generated canonical header: GET
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:57:47.695 INFO:teuthology.orchestra.run.plana002.stderr:Tue, 26 Apr 2022 13:57:47 +0000
2022-04-26T21:57:47.696 INFO:teuthology.orchestra.run.plana002.stderr:/admin/log/
2022-04-26T21:57:47.696 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708524 7f61cda4af80 15 generated auth header: AWS NIZ36PNBEDYNTX7V:qty3n/2qwKbhflMt1L0K9qfGnEc=
2022-04-26T21:57:47.696 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708504 7f619a53d700 20 link_request req_data=0x7f61d0b07e00 req_data->id=0, curl_handle=0x7f61d193b4e0
2022-04-26T21:57:47.696 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708540 7f61cda4af80 20 sending request to http://plana002.ceph.com:8001/admin/log/?type=data&status&source-zone=4bdfcde7-e65d-423e-813b-baf83d7ff087&rgwx-zonegroup=test-zonegroup
2022-04-26T21:57:47.696 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708624 7f61cda4af80 20 register_request mgr=0x7ffce17f3030 req_data->id=1, curl_handle=0x7f61d193b540
2022-04-26T21:57:47.697 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.708633 7f61cda4af80 20 run: stack=0x7f61d0aebe60 is io blocked
2022-04-26T21:57:47.697 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.709192 7f619a53d700 20 link_request req_data=0x7f61d1804200 req_data->id=1, curl_handle=0x7f61d193b540
2022-04-26T21:57:47.700 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712590 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.700 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712599 7f619a53d700 10 received header:HTTP/1.1 200 OK
2022-04-26T21:57:47.700 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712609 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712610 7f619a53d700 10 received header:x-amz-request-id: tx0000000000000000000d9-006267fa5b-19a8-test-zone3
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712617 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712617 7f619a53d700 10 received header:Content-Length: 649
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712620 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712620 7f619a53d700 10 received header:Date: Tue, 26 Apr 2022 13:57:47 GMT
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712626 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.701 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712627 7f619a53d700 10 received header:Connection: Keep-Alive
2022-04-26T21:57:47.702 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712629 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.702 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712629 7f619a53d700 10 received header:
2022-04-26T21:57:47.702 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.712742 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.702 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713435 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.702 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713445 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713447 7f61cda4af80 20 cr:s=0x7f61d0aebe60:op=0x7f61d193ec00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713449 7f61cda4af80 15 stack 0x7f61d0aebe60 end
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713455 7f61cda4af80 20 run: stack=0x7f61d0aebe60 is done
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713457 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.713459 7f61cda4af80 20 run: stack=0x7f61d0aebc20 is_blocked_by_stack()=0 is_sleeping=0 waiting_for_child()=1
2022-04-26T21:57:47.703 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715153 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715162 7f619a53d700 10 received header:HTTP/1.1 200 OK
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715163 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715163 7f619a53d700 10 received header:x-amz-request-id: tx00000000000000000009d-006267fa5b-169b-test-zone2
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715167 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715167 7f619a53d700 10 received header:Content-Length: 648
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715168 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.704 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715168 7f619a53d700 10 received header:Date: Tue, 26 Apr 2022 13:57:47 GMT
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715170 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715171 7f619a53d700 10 received header:Connection: Keep-Alive
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715178 7f619a53d700 10 receive_http_header
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715178 7f619a53d700 10 received header:
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.715550 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.705 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716038 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716047 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716049 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716050 7f61cda4af80 15 stack 0x7f61d0aeb680 end
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716053 7f61cda4af80 20 run: stack=0x7f61d0aeb680 is done
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716055 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.706 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716058 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.707 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716059 7f61cda4af80 10 data trim: trimming log shards
2022-04-26T21:57:47.707 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716063 7f61cda4af80 10 data trim: trimming log shard 1 at marker=1_1650981456.502772_1011.1 last_trim=
2022-04-26T21:57:47.707 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716108 7f61cda4af80 20 run: stack=0x7f61d0aebc20 is_blocked_by_stack()=1 is_sleeping=0 waiting_for_child()=0
2022-04-26T21:57:47.707 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716116 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.707 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716119 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.708 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.716188 7f61cda4af80 20 run: stack=0x7f61d0aeb680 is io blocked
2022-04-26T21:57:47.708 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726349 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.708 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726360 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.708 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726361 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726362 7f61cda4af80 20 cr:s=0x7f61d0aeb680:op=0x7f61d193e600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726362 7f61cda4af80 15 stack 0x7f61d0aeb680 end
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726368 7f61cda4af80 20 run: stack=0x7f61d0aeb680 is done
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726369 7f61cda4af80 20 cr:s=0x7f61d0aebc20:op=0x7f61d193e000:13DataLogTrimCR: operate()
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726370 7f61cda4af80 15 stack 0x7f61d0aebc20 end
2022-04-26T21:57:47.709 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.726371 7f61cda4af80 20 run: stack=0x7f61d0aebc20 is done
2022-04-26T21:57:47.713 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.732496 7f61cda4af80 20 remove_watcher() i=0
2022-04-26T21:57:47.713 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.732505 7f61cda4af80 2 removed watcher, disabling cache
2022-04-26T21:57:47.717 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.735680 7f61cda4af80 20 remove_watcher() i=1
2022-04-26T21:57:47.720 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.739421 7f61cda4af80 20 remove_watcher() i=2
2022-04-26T21:57:47.724 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.743552 7f61cda4af80 20 remove_watcher() i=3
2022-04-26T21:57:47.728 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.747552 7f61cda4af80 20 remove_watcher() i=4
2022-04-26T21:57:47.732 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.751593 7f61cda4af80 20 remove_watcher() i=5
2022-04-26T21:57:47.737 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.755750 7f61cda4af80 20 remove_watcher() i=6
2022-04-26T21:57:47.740 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:57:47.759121 7f61cda4af80 20 remove_watcher() i=7
2022-04-26T21:57:47.749 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'list', '--shard-id', '1', '--max-entries', '1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:47.749 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'list', '--shard-id', '1', '--max-entries', '1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:47.749 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog list --shard-id 1 --max-entries 1 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:48.289 INFO:teuthology.orchestra.run.plana002.stdout:[{"entity_type":"bucket","key":"aoqodf-47:4bdfcde7-e65d-423e-813b-baf83d7ff087.6562.4","timestamp":"2022-04-26 13:57:43.253411Z"}]
2022-04-26T21:57:48.291 INFO:rgw_multi.tests:zone=test-zone1 need datasync
2022-04-26T21:57:48.291 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:48.292 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:48.293 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:48.780 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981463.253411_1019.1","last_update":"2022-04-26 13:57:43.253411Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:57:48.781 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone2 source_zone=test-zone1
2022-04-26T21:57:48.782 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:48.782 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:48.783 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:49.314 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":7098223210824665103},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.502772_1011.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.502772Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:49.316 WARNING:rgw_multi.tests:data of zone test-zone2 behind zone test-zone1: shard=1 master=1_1650981463.253411_1019.1 target=1_1650981456.502772_1011.1
2022-04-26T21:57:54.317 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:54.318 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:57:54.319 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:57:55.881 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":7098223210824665103},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.502772_1011.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.502772Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:57:55.882 WARNING:rgw_multi.tests:data of zone test-zone2 behind zone test-zone1: shard=1 master=1_1650981463.253411_1019.1 target=1_1650981456.502772_1011.1
2022-04-26T21:58:00.884 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:00.885 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:00.886 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:01.412 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":7098223210824665103},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981463.253411_1019.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:43.253411Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:01.414 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone2 source_zone=test-zone1
2022-04-26T21:58:01.414 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:01.415 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:01.416 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:01.922 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981463.253411_1019.1","last_update":"2022-04-26 13:57:43.253411Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:58:01.922 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone3 source_zone=test-zone1
2022-04-26T21:58:01.923 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:01.923 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:01.923 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone1 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:02.425 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":14501821185802160608},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981463.253411_1019.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:43.253411Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:02.426 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone3 source_zone=test-zone1
2022-04-26T21:58:02.426 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:02.426 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:02.426 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 datalog status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:02.902 INFO:teuthology.orchestra.run.plana001.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.582049_963.1","last_update":"2022-04-26 13:57:36.582049Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:58:02.903 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone1 source_zone=test-zone2
2022-04-26T21:58:02.904 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:02.905 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:02.905 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone2 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:03.428 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":15575674840284756678},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.582049_963.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.582049Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:03.428 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone1 source_zone=test-zone2
2022-04-26T21:58:03.429 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:03.429 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'datalog', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:03.429 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 datalog status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:03.923 INFO:teuthology.orchestra.run.plana001.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.582049_963.1","last_update":"2022-04-26 13:57:36.582049Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:58:03.924 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone3 source_zone=test-zone2
2022-04-26T21:58:03.924 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:03.925 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone2', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:03.926 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone2 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:04.425 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":4845208584981704144},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.582049_963.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.582049Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:04.427 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone3 source_zone=test-zone2
2022-04-26T21:58:04.427 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:04.428 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:04.429 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:04.888 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.298046_881.1","last_update":"2022-04-26 13:57:36.298046Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:58:04.889 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone1 source_zone=test-zone3
2022-04-26T21:58:04.889 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:04.889 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'data', 'sync', 'status', '--rgw-zone', 'test-zone1', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:04.889 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 data sync status --rgw-zone test-zone1 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone3 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:05.373 INFO:teuthology.orchestra.run.plana002.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":8650972045503614890},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.298046_881.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.298046Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:05.373 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone1 source_zone=test-zone3
2022-04-26T21:58:05.373 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:05.374 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'status', '--rgw-zone', 'test-zone3', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:05.374 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog status --rgw-zone test-zone3 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:05.890 INFO:teuthology.orchestra.run.plana002.stdout:[{"marker":"","last_update":"0.000000"},{"marker":"1_1650981456.298046_881.1","last_update":"2022-04-26 13:57:36.298046Z"},{"marker":"","last_update":"0.000000"},{"marker":"","last_update":"0.000000"}]
2022-04-26T21:58:05.891 INFO:rgw_multi.tests:starting data checkpoint for target_zone=test-zone2 source_zone=test-zone3
2022-04-26T21:58:05.891 INFO:tasks.util.rgw:rgwadmin: c2.client.0 : ['data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:05.891 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c2', 'data', 'sync', 'status', '--rgw-zone', 'test-zone2', '--rgw-zonegroup', 'test-zonegroup', '--rgw-realm', 'test-realm', '--source-zone', 'test-zone3', '--cluster', 'c2', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:05.891 DEBUG:teuthology.orchestra.run.plana001:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c2 data sync status --rgw-zone test-zone2 --rgw-zonegroup test-zonegroup --rgw-realm test-realm --source-zone test-zone3 --cluster c2 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:06.395 INFO:teuthology.orchestra.run.plana001.stdout:{"sync_status":{"info":{"status":"sync","num_shards":4,"instance_id":3777563592681651088},"markers":[{"key":0,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":1,"val":{"status":"incremental-sync","marker":"1_1650981456.298046_881.1","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"2022-04-26 13:57:36.298046Z"}},{"key":2,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}},{"key":3,"val":{"status":"incremental-sync","marker":"","next_step_marker":"","total_entries":0,"pos":0,"timestamp":"0.000000"}}]},"full_sync":{"total":0,"complete":0}}
2022-04-26T21:58:06.397 INFO:rgw_multi.tests:finished data checkpoint for target_zone=test-zone2 source_zone=test-zone3
2022-04-26T21:58:06.397 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'autotrim', '--cluster', 'c1', '--debug-rgw', '20', '--debug-ms', '0']
2022-04-26T21:58:06.398 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'autotrim', '--cluster', 'c1', '--debug-rgw', '20', '--debug-ms', '0']
2022-04-26T21:58:06.399 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog autotrim --cluster c1 --debug-rgw 20 --debug-ms 0
2022-04-26T21:58:06.733 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.749419 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.738 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.756434 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.739 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.756476 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.741 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.759704 7f193e03df80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:58:06.741 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.759718 7f193e03df80 20 realm test-realm 2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:58:06.742 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.759726 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.743 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.761483 7f193e03df80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:58:06.744 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.761498 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.747 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.763189 7f193e03df80 20 rados_obj.operate() r=0 bl.length=10
2022-04-26T21:58:06.748 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.763214 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.748 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.764369 7f193e03df80 20 rados_obj.operate() r=0 bl.length=1293
2022-04-26T21:58:06.749 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.764431 7f193e03df80 20 current period b1360a77-18f5-4b20-945a-6b281595c52e
2022-04-26T21:58:06.749 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.764435 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.749 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.765700 7f193e03df80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:58:06.750 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.765712 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.751 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.767048 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.752 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.767068 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.752 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.768041 7f193e03df80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:58:06.752 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.768060 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.752 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.769218 7f193e03df80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:58:06.776 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778426 7f193e03df80 20 RGWRados::pool_iterate: got periods.c62966ba-eb7b-4b46-8b5b-a77bb20b11b3.latest_epoch
2022-04-26T21:58:06.777 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778438 7f193e03df80 20 RGWRados::pool_iterate: got periods.b1360a77-18f5-4b20-945a-6b281595c52e.1
2022-04-26T21:58:06.777 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778439 7f193e03df80 20 RGWRados::pool_iterate: got default.zone.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:58:06.778 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778439 7f193e03df80 20 RGWRados::pool_iterate: got zone_info.4bdfcde7-e65d-423e-813b-baf83d7ff087
2022-04-26T21:58:06.778 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778439 7f193e03df80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.2
2022-04-26T21:58:06.778 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778440 7f193e03df80 20 RGWRados::pool_iterate: got period_config.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:58:06.779 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778440 7f193e03df80 20 RGWRados::pool_iterate: got periods.c62966ba-eb7b-4b46-8b5b-a77bb20b11b3.1
2022-04-26T21:58:06.779 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778441 7f193e03df80 20 RGWRados::pool_iterate: got realms.2a7ca286-f8d4-414f-962c-a59e22ed85fd.control
2022-04-26T21:58:06.779 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778441 7f193e03df80 20 RGWRados::pool_iterate: got periods.cb30fa8f-4697-4113-b569-2bdff12a8c8d.latest_epoch
2022-04-26T21:58:06.780 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778441 7f193e03df80 20 RGWRados::pool_iterate: got zonegroup_info.test-zonegroup
2022-04-26T21:58:06.780 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778442 7f193e03df80 20 RGWRados::pool_iterate: got default.realm
2022-04-26T21:58:06.781 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778442 7f193e03df80 20 RGWRados::pool_iterate: got instances_info.test-zone1
2022-04-26T21:58:06.781 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778442 7f193e03df80 20 RGWRados::pool_iterate: got instances_names.test-zone1
2022-04-26T21:58:06.781 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778443 7f193e03df80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.latest_epoch
2022-04-26T21:58:06.781 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778443 7f193e03df80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.1
2022-04-26T21:58:06.782 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778443 7f193e03df80 20 RGWRados::pool_iterate: got instances_info.default
2022-04-26T21:58:06.782 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778444 7f193e03df80 20 RGWRados::pool_iterate: got zonegroup_info.27ef2180-5eb9-4bc9-a8c4-4e9e494bf783
2022-04-26T21:58:06.782 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778444 7f193e03df80 20 RGWRados::pool_iterate: got instances_names.default
2022-04-26T21:58:06.782 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778445 7f193e03df80 20 RGWRados::pool_iterate: got default.zonegroup.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:58:06.782 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778445 7f193e03df80 20 RGWRados::pool_iterate: got periods.1845171f-ef46-4f26-8b04-bb14d6e19bc6.3
2022-04-26T21:58:06.783 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778445 7f193e03df80 20 RGWRados::pool_iterate: got zone_names.test-zone3
2022-04-26T21:58:06.783 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778446 7f193e03df80 20 RGWRados::pool_iterate: got zone_info.85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:58:06.783 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778446 7f193e03df80 20 RGWRados::pool_iterate: got periods.2a7ca286-f8d4-414f-962c-a59e22ed85fd:staging
2022-04-26T21:58:06.783 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778447 7f193e03df80 20 RGWRados::pool_iterate: got instances_names.test-zone3
2022-04-26T21:58:06.783 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778449 7f193e03df80 20 RGWRados::pool_iterate: got periods.cb30fa8f-4697-4113-b569-2bdff12a8c8d.1
2022-04-26T21:58:06.784 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778450 7f193e03df80 20 RGWRados::pool_iterate: got zone_info.c2e95579-d813-43c7-b671-6451ec3a6d43
2022-04-26T21:58:06.784 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778450 7f193e03df80 20 RGWRados::pool_iterate: got zone_names.test-zone1
2022-04-26T21:58:06.784 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778450 7f193e03df80 20 RGWRados::pool_iterate: got zonegroups_names.test-zonegroup
2022-04-26T21:58:06.784 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778452 7f193e03df80 20 RGWRados::pool_iterate: got realms.2a7ca286-f8d4-414f-962c-a59e22ed85fd
2022-04-26T21:58:06.784 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778452 7f193e03df80 20 RGWRados::pool_iterate: got realms_names.test-realm
2022-04-26T21:58:06.785 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778453 7f193e03df80 20 RGWRados::pool_iterate: got periods.b1360a77-18f5-4b20-945a-6b281595c52e.latest_epoch
2022-04-26T21:58:06.785 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778455 7f193e03df80 20 RGWRados::pool_iterate: got zone_names.default
2022-04-26T21:58:06.785 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778457 7f193e03df80 20 RGWRados::pool_iterate: got zonegroups_names.default
2022-04-26T21:58:06.785 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778458 7f193e03df80 20 RGWRados::pool_iterate: got instances_info.test-zone3
2022-04-26T21:58:06.785 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.778490 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.786 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.779717 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.786 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.779736 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.786 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.780791 7f193e03df80 20 rados_obj.operate() r=0 bl.length=821
2022-04-26T21:58:06.786 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.780832 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.786 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.781280 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.787 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.781297 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.787 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.782192 7f193e03df80 20 rados_obj.operate() r=0 bl.length=348
2022-04-26T21:58:06.787 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.782217 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.787 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.782784 7f193e03df80 20 rados_obj.operate() r=-2 bl.length=0
2022-04-26T21:58:06.787 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.782798 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.788 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.784734 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.788 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.784753 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.788 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.785243 7f193e03df80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:58:06.788 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.785260 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.788 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787058 7f193e03df80 20 rados_obj.operate() r=0 bl.length=24
2022-04-26T21:58:06.789 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787073 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.789 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787929 7f193e03df80 20 rados_obj.operate() r=0 bl.length=764
2022-04-26T21:58:06.789 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787948 7f193e03df80 20 period zonegroup init ret 0
2022-04-26T21:58:06.789 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787948 7f193e03df80 20 period zonegroup name test-zonegroup
2022-04-26T21:58:06.789 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787949 7f193e03df80 20 using current period zonegroup test-zonegroup
2022-04-26T21:58:06.790 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.787953 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.790 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.789635 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.790 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.789650 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.790 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.790372 7f193e03df80 20 rados_obj.operate() r=0 bl.length=110
2022-04-26T21:58:06.790 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.790393 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.791189 7f193e03df80 20 rados_obj.operate() r=0 bl.length=46
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.791204 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.792555 7f193e03df80 20 rados_obj.operate() r=0 bl.length=962
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.792574 7f193e03df80 10 Cannot find current period zone using local zone
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.792594 7f193e03df80 20 rados->read ofs=0 len=0
2022-04-26T21:58:06.791 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.793978 7f193e03df80 20 rados_obj.operate() r=0 bl.length=962
2022-04-26T21:58:06.792 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.794000 7f193e03df80 20 zone test-zone1
2022-04-26T21:58:06.792 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.794009 7f193e03df80 20 generating connection object for zone test-zone2 id 1c709dbd-13da-4a3b-871f-39b1dcf0b20f
2022-04-26T21:58:06.792 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.794010 7f193e03df80 20 generating connection object for zone test-zone3 id 85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:58:06.821 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840234 7f193e03df80 20 add_watcher() i=0
2022-04-26T21:58:06.821 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840240 7f193e03df80 20 add_watcher() i=1
2022-04-26T21:58:06.822 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840241 7f193e03df80 20 add_watcher() i=2
2022-04-26T21:58:06.822 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840241 7f193e03df80 20 add_watcher() i=3
2022-04-26T21:58:06.822 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840242 7f193e03df80 20 add_watcher() i=4
2022-04-26T21:58:06.822 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840243 7f193e03df80 20 add_watcher() i=5
2022-04-26T21:58:06.823 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.840711 7f193e03df80 20 add_watcher() i=6
2022-04-26T21:58:06.825 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.844369 7f193e03df80 20 add_watcher() i=7
2022-04-26T21:58:06.826 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.844374 7f193e03df80 2 all 8 watchers are set, enabling cache
2022-04-26T21:58:06.831 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.850169 7f1920b5c700 2 RGWDataChangesLog::ChangesRenewThread: start
2022-04-26T21:58:06.838 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.852467 7f190fb3a700 20 reqs_thread_entry: start
2022-04-26T21:58:06.838 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.852687 7f190db36700 20 reqs_thread_entry: start
2022-04-26T21:58:06.838 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.852724 7f193e03df80 20 init_complete bucket index max shards: 0
2022-04-26T21:58:06.838 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853385 7f190c333700 20 reqs_thread_entry: start
2022-04-26T21:58:06.838 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853539 7f190ab30700 20 reqs_thread_entry: start
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853559 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853568 7f193e03df80 10 data trim: fetching sync status for zone 4bdfcde7-e65d-423e-813b-baf83d7ff087
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853575 7f193e03df80 20 data trim: query sync status from 1c709dbd-13da-4a3b-871f-39b1dcf0b20f
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853589 7f193e03df80 20 data trim: query sync status from 85506ecb-0937-4c5e-9eb8-f48246309a52
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853602 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:06.839 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853605 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853606 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853608 7f193e03df80 20 run: stack=0x7f1940a59d40 is_blocked_by_stack()=0 is_sleeping=0 waiting_for_child()=1
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853613 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853682 7f193e03df80 20 > HTTP_DATE -> Tue, 26 Apr 2022 13:58:06 +0000
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853717 7f193e03df80 10 get_canon_resource(): dest=/admin/log/
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853718 7f193e03df80 10 generated canonical header: GET
2022-04-26T21:58:06.840 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:Tue, 26 Apr 2022 13:58:06 +0000
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:/admin/log/
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853743 7f193e03df80 15 generated auth header: AWS NIZ36PNBEDYNTX7V:DQiTxEKjZU/SfEYV4lB4BVZputM=
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853758 7f193e03df80 20 sending request to http://plana001.ceph.com:8000/admin/log/?type=data&status&source-zone=4bdfcde7-e65d-423e-813b-baf83d7ff087&rgwx-zonegroup=test-zonegroup
2022-04-26T21:58:06.841 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853784 7f193e03df80 20 register_request mgr=0x7ffcc342ccd0 req_data->id=0, curl_handle=0x7f19418a1560
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853792 7f193e03df80 20 run: stack=0x7f1940a599e0 is io blocked
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853796 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853818 7f193e03df80 20 > HTTP_DATE -> Tue, 26 Apr 2022 13:58:06 +0000
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853829 7f193e03df80 10 get_canon_resource(): dest=/admin/log/
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853830 7f193e03df80 10 generated canonical header: GET
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:58:06.842 INFO:teuthology.orchestra.run.plana002.stderr:
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:Tue, 26 Apr 2022 13:58:06 +0000
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:/admin/log/
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853834 7f193e03df80 15 generated auth header: AWS NIZ36PNBEDYNTX7V:DQiTxEKjZU/SfEYV4lB4BVZputM=
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853850 7f193e03df80 20 sending request to http://plana002.ceph.com:8001/admin/log/?type=data&status&source-zone=4bdfcde7-e65d-423e-813b-baf83d7ff087&rgwx-zonegroup=test-zonegroup
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853854 7f193e03df80 20 register_request mgr=0x7ffcc342ccd0 req_data->id=1, curl_handle=0x7f19418a15c0
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.853858 7f193e03df80 20 run: stack=0x7f19418b0000 is io blocked
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.854041 7f190ab30700 20 link_request req_data=0x7f1941684600 req_data->id=0, curl_handle=0x7f19418a1560
2022-04-26T21:58:06.843 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:06.854177 7f190ab30700 20 link_request req_data=0x7f1940a75a00 req_data->id=1, curl_handle=0x7f19418a15c0
2022-04-26T21:58:07.849 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862627 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.849 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862643 7f190ab30700 10 received header:HTTP/1.1 200 OK
2022-04-26T21:58:07.850 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862667 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.851 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862669 7f190ab30700 10 received header:x-amz-request-id: tx0000000000000000000e8-006267fa6f-19a8-test-zone3
2022-04-26T21:58:07.851 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862687 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.852 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862689 7f190ab30700 10 received header:Content-Length: 649
2022-04-26T21:58:07.852 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862696 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.853 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862698 7f190ab30700 10 received header:Date: Tue, 26 Apr 2022 13:58:07 GMT
2022-04-26T21:58:07.853 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862709 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.854 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862711 7f190ab30700 10 received header:Connection: Keep-Alive
2022-04-26T21:58:07.854 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862716 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.855 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862718 7f190ab30700 10 received header:
2022-04-26T21:58:07.855 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.862938 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.856 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864173 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.856 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864197 7f190ab30700 10 received header:HTTP/1.1 200 OK
2022-04-26T21:58:07.857 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864202 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.857 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864203 7f190ab30700 10 received header:x-amz-request-id: tx0000000000000000000ac-006267fa6f-169b-test-zone2
2022-04-26T21:58:07.858 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864212 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.858 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864213 7f190ab30700 10 received header:Content-Length: 648
2022-04-26T21:58:07.858 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864216 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.859 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864217 7f190ab30700 10 received header:Date: Tue, 26 Apr 2022 13:58:07 GMT
2022-04-26T21:58:07.860 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864224 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.860 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864224 7f190ab30700 10 received header:Connection: Keep-Alive
2022-04-26T21:58:07.861 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864244 7f190ab30700 10 receive_http_header
2022-04-26T21:58:07.861 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864245 7f190ab30700 10 received header:
2022-04-26T21:58:07.861 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864558 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.862 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864586 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.862 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.864592 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.863 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865730 7f193e03df80 20 cr:s=0x7f19418b0000:op=0x7f19418a4c00:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.863 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865751 7f193e03df80 15 stack 0x7f19418b0000 end
2022-04-26T21:58:07.863 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865768 7f193e03df80 20 run: stack=0x7f19418b0000 is done
2022-04-26T21:58:07.864 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865773 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.864 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865777 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:07.865 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865783 7f193e03df80 20 run: stack=0x7f1940a59d40 is_blocked_by_stack()=0 is_sleeping=0 waiting_for_child()=1
2022-04-26T21:58:07.865 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865789 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.865 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865793 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:21RGWReadRESTResourceCRI20rgw_data_sync_statusE: operate()
2022-04-26T21:58:07.866 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865796 7f193e03df80 15 stack 0x7f1940a599e0 end
2022-04-26T21:58:07.866 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865800 7f193e03df80 20 run: stack=0x7f1940a599e0 is done
2022-04-26T21:58:07.866 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865803 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:07.867 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865808 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:07.867 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865811 7f193e03df80 10 data trim: trimming log shards
2022-04-26T21:58:07.868 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.865819 7f193e03df80 10 data trim: trimming log shard 1 at marker=1_1650981463.253411_1019.1 last_trim=
2022-04-26T21:58:07.868 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.866013 7f193e03df80 20 run: stack=0x7f1940a59d40 is_blocked_by_stack()=1 is_sleeping=0 waiting_for_child()=0
2022-04-26T21:58:07.868 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.866023 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.869 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.866033 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.869 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.866175 7f193e03df80 20 run: stack=0x7f1940a599e0 is io blocked
2022-04-26T21:58:07.870 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878378 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.871 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878410 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.871 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878415 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.871 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878419 7f193e03df80 20 cr:s=0x7f1940a599e0:op=0x7f19418a4600:16RGWSyncLogTrimCR: operate()
2022-04-26T21:58:07.871 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878422 7f193e03df80 15 stack 0x7f1940a599e0 end
2022-04-26T21:58:07.871 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878440 7f193e03df80 20 run: stack=0x7f1940a599e0 is done
2022-04-26T21:58:07.872 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878446 7f193e03df80 20 cr:s=0x7f1940a59d40:op=0x7f19418a4000:13DataLogTrimCR: operate()
2022-04-26T21:58:07.872 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878450 7f193e03df80 15 stack 0x7f1940a59d40 end
2022-04-26T21:58:07.872 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.878453 7f193e03df80 20 run: stack=0x7f1940a59d40 is done
2022-04-26T21:58:07.874 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.892171 7f193e03df80 20 remove_watcher() i=0
2022-04-26T21:58:07.875 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.892186 7f193e03df80 2 removed watcher, disabling cache
2022-04-26T21:58:07.879 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.897748 7f193e03df80 20 remove_watcher() i=1
2022-04-26T21:58:07.885 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.903533 7f193e03df80 20 remove_watcher() i=2
2022-04-26T21:58:07.892 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.910482 7f193e03df80 20 remove_watcher() i=3
2022-04-26T21:58:07.896 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.915456 7f193e03df80 20 remove_watcher() i=4
2022-04-26T21:58:07.901 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.920088 7f193e03df80 20 remove_watcher() i=5
2022-04-26T21:58:07.904 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.923537 7f193e03df80 20 remove_watcher() i=6
2022-04-26T21:58:07.909 INFO:teuthology.orchestra.run.plana002.stderr:2022-04-26 21:58:07.928143 7f193e03df80 20 remove_watcher() i=7
2022-04-26T21:58:07.918 INFO:tasks.util.rgw:rgwadmin: c1.client.0 : ['datalog', 'list', '--shard-id', '1', '--max-entries', '1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:07.919 DEBUG:tasks.util.rgw:rgwadmin: cmd=['adjust-ulimits', 'ceph-coverage', '/mnt/cephtest/archive/coverage', 'radosgw-admin', '--log-to-stderr', '--format', 'json', '-n', 'client.0', '--cluster', 'c1', 'datalog', 'list', '--shard-id', '1', '--max-entries', '1', '--cluster', 'c1', '--debug-rgw', '0', '--debug-ms', '0', '--rgw-cache-enabled', 'false']
2022-04-26T21:58:07.919 DEBUG:teuthology.orchestra.run.plana002:> adjust-ulimits ceph-coverage /mnt/cephtest/archive/coverage radosgw-admin --log-to-stderr --format json -n client.0 --cluster c1 datalog list --shard-id 1 --max-entries 1 --cluster c1 --debug-rgw 0 --debug-ms 0 --rgw-cache-enabled false
2022-04-26T21:58:08.379 INFO:teuthology.orchestra.run.plana002.stdout:[]
2022-04-26T21:58:08.380 INFO:tasks.rgw_multisite_tests:tasks.rgw_multi.tests.test_datalog_autotrim ... FAIL
(1-1/2)