Ceph » RADOS

Ran into another instance of this here:

/a/yuriw-2022-11-30_23:13:27-rados-wip-yuri2-testing-2022-11-30-0724-pacific-distro-default-smithi/7099593/

Same symptom, where the pid is killed without any other obvious clues. I don't think my observation in the mon log above means anything; what we really need to understand is what the pid is doing. However, grepping for the pid does not reveal any sort of trail. There is also no coredump or crash recorded.

The issue appears to be in the api_aio test as it gets started but doesn't complete.

$ grep "Global test environment set-up" teuthology.log |gawk '{print $3}'|sort
api_aio:
api_aio_pp:
api_asio:
api_cmd:
api_cmd_pp:
api_c_read_operations:
api_c_write_operations:
api_io:
api_io_pp:
api_list:
api_lock:
api_lock_pp:
api_misc:
api_misc_pp:
api_pool:
api_service:
api_service_pp:
api_snapshots:
api_snapshots_pp:
api_stat:
api_stat_pp:
api_tier_pp:
api_watch_notify:
api_watch_notify_pp:

$ grep "Global test environment tear-down" teuthology.log|gawk '{print $3}'|sort
api_aio_pp:
api_asio:
api_cmd:
api_cmd_pp:
api_c_read_operations:
api_c_write_operations:
api_io:
api_io_pp:
api_list:
api_lock:
api_lock_pp:
api_misc:
api_misc_pp:
api_pool:
api_service:
api_service_pp:
api_snapshots:
api_snapshots_pp:
api_stat:
api_stat_pp:
api_tier_pp:
api_watch_notify:
api_watch_notify_pp:

2022-12-01T05:48:21.847 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [==========] Running 40 tests from 2 test suites.
2022-12-01T05:48:21.847 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [----------] Global test environment set-up.
2022-12-01T05:48:21.847 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [----------] 24 tests from LibRadosAio
2022-12-01T05:48:21.847 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [ RUN      ] LibRadosAio.TooBig
2022-12-01T05:48:21.847 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [       OK ] LibRadosAio.TooBig (7105 ms)
2022-12-01T05:48:21.848 INFO:tasks.workunit.client.0.smithi090.stdout:                  api_aio: [ RUN      ] LibRadosAio.SimpleWrite
2022-12-01T05:48:21.848 INFO:tasks.workunit.client.0.smithi090.stderr:bash: line 1: 119798 Alarm clock             ceph_test_rados_api_aio 2>&1
2022-12-01T05:48:21.848 INFO:tasks.workunit.client.0.smithi090.stderr:     119799 Done                    | tee ceph_test_rados_api_aio.log
2022-12-01T05:48:21.849 INFO:tasks.workunit.client.0.smithi090.stderr:     119800 Done                    | sed "s/^/                  api_aio: /" 

Looks like the problem may be in the LibRadosAio.SimpleWrite test.
We could try a special test to run api_aio only?
If we can capture the ceph_test_rados_api_aio.log file it may tell us more?

in the case of 7097464 above the issue is with api_watch_notify so probably a different (and possibly known) issue?

2022-11-30T02:54:05.553 INFO:tasks.workunit.client.0.smithi018.stdout:         api_watch_notify: [----------] 10 tests from LibRadosWatchNotify (136446 ms total)
2022-11-30T02:54:05.553 INFO:tasks.workunit.client.0.smithi018.stdout:         api_watch_notify:
2022-11-30T02:54:05.553 INFO:tasks.workunit.client.0.smithi018.stdout:         api_watch_notify: [----------] 1 test from LibRadosWatchNotifyEC
2022-11-30T02:54:05.553 INFO:tasks.workunit.client.0.smithi018.stdout:         api_watch_notify: [ RUN      ] LibRadosWatchNotifyEC.WatchNotify
2022-11-30T02:54:05.554 INFO:tasks.workunit.client.0.smithi018.stderr:bash: line 1: 121010 Alarm clock             ceph_test_rados_api_watch_notify 2>&1
2022-11-30T02:54:05.554 INFO:tasks.workunit.client.0.smithi018.stderr:     121011 Done                    | tee ceph_test_rados_api_watch_notify.log
2022-11-30T02:54:05.554 INFO:tasks.workunit.client.0.smithi018.stderr:     121012 Done                    | sed "s/^/         api_watch_notify: /" 
2022-11-30T02:54:05.555 INFO:tasks.workunit.client.0.smithi018.stdout:error in api_watch_notify (121007)
2022-11-30T02:54:05.559 INFO:tasks.workunit.client.0.smithi018.stderr:+ echo 'error in api_watch_notify (121007)'

Thanks for your observations, Brad! I'm going to dedicate this Tracker to `LibRadosAio.SimpleWrite` and mark it as related to https://tracker.ceph.com/issues/57751.

Laura, i think it is different than that bug (57751), in that case all the osds are still up.
We can see that we never called watch_notify_test_cb for LibRadosWatchNotifyEC.WatchNotify and after a while we raised the Alarm.

We know the PID of api_watch_notify (121010) so we can find the pool name of that test: test-rados-api-smithi018-121010-13
we are trying to write object foo and watching him, watch_notify_test_cb supposed to post the semaphore &sem and release the Alarm, but we never got it on time.
PR https://github.com/ceph/ceph/pull/49109 will fix that, it will set the alarm to 2400 sec instead of 1200 sec. that will give us enough time to complete the write op and get the callback on time.

Basing comment #14 we have a "fix candidate" that might also with issue.
If that's correct, we may wait for merging it and then observe whether the symptoms described here persist.

/a/ksirivad-2022-12-22_17:58:01-rados-wip-ksirivad-testing-pacific-distro-default-smithi/7125137/

Kamoltat (Junior) Sirivadhna wrote:

/a/ksirivad-2022-12-22_17:58:01-rados-wip-ksirivad-testing-pacific-distro-default-smithi/7125137/

It looks like it is more related to: https://tracker.ceph.com/issues/21592

2022-12-22T20:55:04.563 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations: [       OK ] LibRadosCWriteOps.WriteSame (3018 ms)
2022-12-22T20:55:04.563 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations: [ RUN      ] LibRadosCWriteOps.CmpExt
2022-12-22T20:55:04.563 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations: /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.10-1548-g9523d2fc/rpm/el8/BUILD/ceph-16.2.10-1548-g9523d2fc/src/test/librados/c_write_operations.cc:269: Failure
2022-12-22T20:55:04.563 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations: Expected equality of these values:
2022-12-22T20:55:04.564 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations:   -4095 - 1
2022-12-22T20:55:04.564 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations:     Which is: -4096
2022-12-22T20:55:04.564 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations:   val
2022-12-22T20:55:04.564 INFO:tasks.workunit.client.0.smithi178.stdout:   api_c_write_operations:     Which is: 0

Laura Flores wrote:

/a/yuriw-2023-03-14_20:10:47-rados-wip-yuri-testing-2023-03-14-0714-reef-distro-default-smithi/7207033
[...]

I think we need to separate this issue from others, it looks like a real issue with AIO and not a test issue from first look.
we are doing osd_backoff and then continue with ping magic and never return to the AIO

ceph-osd.7.log.gz:2023-03-16T15:24:10.122+0000 7f1d0eb5f700  1 --2- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] >> 172.21.15.39:0/2511184891 conn(0x5584756c5000 0x558476a24580 crc :-1 s=READY pgs=4 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=client.4559 client_cookie=0 server_
ceph-osd.7.log.gz:2023-03-16T15:24:10.123+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 1 ==== osd_op(client.4559.0:2 33.6 33.7fc1f406 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e162) v8 ==== 212+0+128 (crc 0 0 
ceph-osd.7.log.gz:2023-03-16T15:24:10.125+0000 7f1cebf04700 10 osd.7 162 maybe_share_map con 0x5584756c5000 172.21.15.39:0/2511184891 map epoch 0 -> 162 (as per caller)
ceph-osd.7.log.gz:2023-03-16T15:24:10.130+0000 7f1ceff0c700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] --> 172.21.15.39:0/2511184891 -- osd_backoff(33.6 block id 1 [33:60000000::::0,33:68000000::::head) e162) v1 -- 0x558476f66000 con 0x5584756c5000
ceph-osd.7.log.gz:2023-03-16T15:24:10.132+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 2 ==== osd_backoff(33.6 ack-block id 1 [33:60000000::::0,33:68000000::::head) e162) v1 ==== 115+0+0 (crc 0 0 0) 0x558476f66000 con 0x5584756c50
ceph-osd.7.log.gz:2023-03-16T15:24:23.211+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 3 ==== ping magic: 0 v1 ==== 0+0+0 (crc 0 0 0) 0x55847750eb40 con 0x5584756c5000
ceph-osd.7.log.gz:2023-03-16T15:24:28.211+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 4 ==== ping magic: 0 v1 ==== 0+0+0 (crc 0 0 0) 0x55847750eb40 con 0x5584756c5000
ceph-osd.7.log.gz:2023-03-16T15:24:33.213+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 5 ==== ping magic: 0 v1 ==== 0+0+0 (crc 0 0 0) 0x55847750eb40 con 0x5584756c5000
ceph-osd.7.log.gz:2023-03-16T15:24:38.221+0000 7f1d0eb5f700  1 -- [v2:172.21.15.146:6826/112882,v1:172.21.15.146:6827/112882] <== client.4559 172.21.15.39:0/2511184891 6 ==== ping magic: 0 v1 ==== 0+0+0 (crc 0 0 0) 0x55847750eb40 con 0x5584756c5000

still digging the logs, but after we are sending aio_write, osd.7 showing added backoff on PG 33.6

2023-03-16T15:24:10.130+0000 7f1ceff0c700 10 osd.7 pg_epoch: 162 pg[33.6( empty local-lis/les=0/0 n=0 ec=161/161 lis/c=0/0 les/c/f=0/0/0 sis=161) [7] r=0 lpr=161 crt=0'0 mlcod 0'0 undersized+peered mbc={}] add_backoff session 0x5584769ec1e0 added Backoff(0x558476fcd680 33.6 1 new [33:60000000::::0,33:68000000::::head)  session 0x5584769ec1e0 pg 0x558476aec000)

removing it on 15:26:38.243
re-add it on 15:26:38.243
remove it on 15:38:03.365
re-add 15:38:03.374
remove 16:04:10.098
release 17:22:29.487

since the aio_write started on 15:24:10.093 and Alarm set for 2400 seconds its not enough probably with backoff, still checking why it too so much time to release

it looks like we have something wrong with backoff with peering in some cases.
from osd.7 - we added backoff after starting peering (2023-03-16T15:38:03.375)
removed that backoff at 2023-03-16T16:04:10.098
release that backoff only at 2023-03-16T17:22:29.487 (when completing recovery)
it sounds like we are missing the release for peering. Continue checking

After checking the logs, it looks like pg 33.6 on osd.7 was in peering state and we didn't had chance (Until Alarm poped after 2400 seconds) to complete the aio_write.
rados/test.sh with osd threshold may generate a lot of activity for peering, and it looks like we couldn't complete the write during that time.

Looks we should for PGs going out from the peering. Bump up.

/a/yuriw-2023-11-02_14:20:05-rados-wip-yuri6-testing-2023-11-01-0745-reef-distro-default-smithi/7444582

Laura Flores wrote:

/a/yuriw-2023-11-02_14:20:05-rados-wip-yuri6-testing-2023-11-01-0745-reef-distro-default-smithi/7444582

looks more related to https://tracker.ceph.com/issues/52657

Nitzan Mordechai wrote:

Laura Flores wrote:

/a/yuriw-2023-11-02_14:20:05-rados-wip-yuri6-testing-2023-11-01-0745-reef-distro-default-smithi/7444582

looks more related to https://tracker.ceph.com/issues/52657

You're right, I missed this bit:

2023-11-02T15:13:15.170 INFO:tasks.ceph.osd.1.smithi151.stderr:*** Caught signal (Aborted) **
2023-11-02T15:13:15.171 INFO:tasks.ceph.osd.1.smithi151.stderr: in thread 29299640 thread_name:tp_osd_tp
2023-11-02T15:13:15.276 INFO:tasks.ceph.osd.2.smithi151.stderr:ceph-osd: /home/jenkins-build/build/workspace/ceph-dev-new-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos9/DIST/centos9/MACHINE_SIZE/gigantic/release/18.2.0-1159-gb5a9486b/rpm/el9/BUILD/ceph-18.2.0-1159-gb5a9486b/src/messages/MOSDPGLog.h:104: virtual void MOSDPGLog::encode_payload(uint64_t): Assertion `HAVE_FEATURE(features, SERVER_NAUTILUS)' failed.
2023-11-02T15:13:15.385 INFO:tasks.ceph.osd.2.smithi151.stderr:*** Caught signal (Aborted) **
2023-11-02T15:13:15.386 INFO:tasks.ceph.osd.2.smithi151.stderr: in thread 25a92640 thread_name:tp_osd_tp
2023-11-02T15:13:15.485 INFO:tasks.ceph.osd.2.smithi151.stderr: ceph version 18.2.0-1159-gb5a9486b (b5a9486b4a6f144f83c51b7ec33111a2c86dc081) reef (stable)
2023-11-02T15:13:15.486 INFO:tasks.ceph.osd.2.smithi151.stderr: 1: /lib64/libc.so.6(+0x54db0) [0x549fdb0]
2023-11-02T15:13:15.486 INFO:tasks.ceph.osd.2.smithi151.stderr: 2: /lib64/libc.so.6(+0xa154c) [0x54ec54c]
2023-11-02T15:13:15.486 INFO:tasks.ceph.osd.2.smithi151.stderr: 3: raise()
2023-11-02T15:13:15.486 INFO:tasks.ceph.osd.2.smithi151.stderr: 4: abort()
2023-11-02T15:13:15.486 INFO:tasks.ceph.osd.2.smithi151.stderr: 5: /lib64/libc.so.6(+0x2871b) [0x547371b]
2023-11-02T15:13:15.487 INFO:tasks.ceph.osd.2.smithi151.stderr: 6: /lib64/libc.so.6(+0x4dca6) [0x5498ca6]
2023-11-02T15:13:15.487 INFO:tasks.ceph.osd.2.smithi151.stderr: 7: ceph-osd(+0x579611) [0x681611]
2023-11-02T15:13:15.487 INFO:tasks.ceph.osd.2.smithi151.stderr: 8: (Message::encode(unsigned long, int, bool)+0x2e) [0xcc19ee]
2023-11-02T15:13:15.487 INFO:tasks.ceph.osd.2.smithi151.stderr: 9: (ProtocolV2::send_message(Message*)+0x241) [0xe593e1]
2023-11-02T15:13:15.487 INFO:tasks.ceph.osd.2.smithi151.stderr: 10: (AsyncConnection::send_message(Message*)+0x266) [0xe3ceb6]
2023-11-02T15:13:15.488 INFO:tasks.ceph.osd.2.smithi151.stderr: 11: (PG::send_cluster_message(int, boost::intrusive_ptr<Message>, unsigned int, bool)+0xa8) [0x7357b8]
2023-11-02T15:13:15.488 INFO:tasks.ceph.osd.2.smithi151.stderr: 12: (PeeringState::activate(ceph::os::Transaction&, unsigned int, PeeringCtxWrapper&)+0x1543) [0x90e423]
2023-11-02T15:13:15.488 INFO:tasks.ceph.osd.2.smithi151.stderr: 13: (PeeringState::Active::Active(boost::statechart::state<PeeringState::Active, PeeringState::Primary, PeeringState::Activating, (boost::statechart::history_mode)0>::my_context)+0x248) [0x924998]
2023-11-02T15:13:15.488 INFO:tasks.ceph.osd.2.smithi151.stderr: 14: ceph-osd(+0x859c47) [0x961c47]

Shouldn't we update 52657 then?

The file was too long to search through with vim or less, but I found this using grep:

/a/lflores-2024-01-22_04:12:37-rados-wip-lflores-testing-2024-01-18-2129-distro-default-smithi/7525368

lflores@teuthology:/a/lflores-2024-01-22_04:12:37-rados-wip-lflores-testing-2024-01-18-2129-distro-default-smithi/7525368$ grep "Alarm clock" teuthology.log
2024-01-23T11:06:46.058 INFO:tasks.workunit.client.0.smithi008.stderr:bash: line 1: 49614 Alarm clock             ceph_test_rados_api_aio_pp --gtest_output=xml:/home/ubuntu/cephtest/archive/gtest_xml_report-api_aio_pp.xml 2>&1
lflores@teuthology:/a/lflores-2024-01-22_04:12:37-rados-wip-lflores-testing-2024-01-18-2129-distro-default-smithi/7525368$ grep "FAILED" teuthology.log
2024-01-23T11:35:00.099 INFO:tasks.workunit.client.0.smithi008.stdout:      api_watch_notify_pp: [  FAILED  ] LibRadosWatchNotifyPPTests/LibRadosWatchNotifyPP.AioWatchNotify2/1, where GetParam() = "cache" (192456 ms)

Laura Flores wrote:

The file was too long to search through with vim or less, but I found this using grep:

/a/lflores-2024-01-22_04:12:37-rados-wip-lflores-testing-2024-01-18-2129-distro-default-smithi/7525368
[...]

wow, something happened? 8.7Gb for teuthology.log its pretty high. no?
anyway. it looks like something slowed the test, the alarm was set to 2400:
TestAlarm() {
alarm(2400);
}

we can increase it, but, maybe i'll first watch for any changes that slowed it down

/a/lflores-2024-02-13_16:18:32-rados-wip-yuri5-testing-2024-02-12-1152-distro-default-smithi/7558384

2024-02-13T18:05:17.612 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: Running main() from gmock_main.cc
2024-02-13T18:05:17.612 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [==========] Running 42 tests from 2 test suites.
2024-02-13T18:05:17.613 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [----------] Global test environment set-up.
2024-02-13T18:05:17.613 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [----------] 26 tests from LibRadosAio
2024-02-13T18:05:17.613 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [ RUN      ] LibRadosAio.TooBig
2024-02-13T18:05:17.613 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [       OK ] LibRadosAio.TooBig (2459 ms)
2024-02-13T18:05:17.613 INFO:tasks.workunit.client.0.smithi084.stdout:                  api_aio: [ RUN      ] LibRadosAio.SimpleWrite
2024-02-13T18:05:17.614 INFO:teuthology.orchestra.run.smithi084.stderr:2024-02-13T18:05:17.600+0000 7f71197fa640  1 -- 172.21.15.84:0/278559395 <== mon.0 v2:172.21.15.84:3300/0 4 ==== mgrmap(e 5) v1 ==== 89788+0+0 (secure 0 0 0) 0x7f711004d3f0 con 0x7f711c06ba50
2024-02-13T18:05:17.614 INFO:tasks.workunit.client.0.smithi084.stderr:bash: line 1: 51563 Alarm clock             ceph_test_rados_api_aio --gtest_output=xml:/home/ubuntu/cephtest/archive/gtest_xml_report-api_aio.xml 2>&1
2024-02-13T18:05:17.615 INFO:tasks.workunit.client.0.smithi084.stderr:     51566 Done                    | tee ceph_test_rados_api_aio.log
2024-02-13T18:05:17.615 INFO:tasks.workunit.client.0.smithi084.stderr:     51568 Done                    | sed "s/^/                  api_aio: /" 
2024-02-13T18:05:17.619 INFO:teuthology.orchestra.run.smithi161.stdout:{

This one came with a few other symptoms:

/a/yuriw-2024-02-13_23:41:23-rados-wip-yuri6-testing-2024-02-13-0904-distro-default-smithi/7558996

2024-02-14T19:56:30.998 INFO:tasks.workunit.client.0.smithi088.stdout:                  api_aio: [ RUN      ] LibRadosAio.SimpleWrite
2024-02-14T19:56:30.999 INFO:tasks.workunit.client.0.smithi088.stderr:bash: line 1: 33891 Alarm clock             ceph_test_rados_api_aio --gtest_output=xml:/home/ubuntu/cephtest/archive/gtest_xml_report-api_aio.xml 2>&1
2024-02-14T19:56:30.999 INFO:tasks.workunit.client.0.smithi088.stderr:     33892 Done                    | tee ceph_test_rados_api_aio.log
2024-02-14T19:56:30.999 INFO:tasks.workunit.client.0.smithi088.stderr:     33893 Done                    | sed "s/^/                  api_aio: /" 
2024-02-14T19:56:31.003 INFO:tasks.ceph.osd.4.smithi117.stderr:2024-02-14T19:56:31.000+0000 7f1fcdab6640 -1 received  signal: Hangup from /usr/bin/python3 /usr/bin/daemon-helper kill ceph-osd -f --cluster ceph -i 4  (PID: 25210) UID: 0

2024-02-14T21:07:04.827 INFO:tasks.workunit.client.0.smithi088.stdout:               api_aio_pp: [ RUN      ] LibRadosAio.ExecuteClassPP
2024-02-14T21:07:04.828 INFO:tasks.workunit.client.0.smithi088.stderr:bash: line 1: 33899 Alarm clock             ceph_test_rados_api_aio_pp --gtest_output=xml:/home/ubuntu/cephtest/archive/gtest_xml_report-api_aio_pp.xml 2>&1
2024-02-14T21:07:04.828 INFO:tasks.workunit.client.0.smithi088.stderr:     33900 Done                    | tee ceph_test_rados_api_aio_pp.log
2024-02-14T21:07:04.828 INFO:tasks.workunit.client.0.smithi088.stderr:     33901 Done                    | sed "s/^/               api_aio_pp: /" 
2024-02-14T21:07:04.829 INFO:teuthology.orchestra.run.smithi088.stdout:ERROR: (22) Invalid argument

2024-02-14T19:50:32.283 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: [ RUN      ] LibRadosWatchNotify.WatchNotify2Timeout
2024-02-14T19:50:32.283 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: watch_notify2_test_cb from 4914 notify_id 4690104287233 cookie 94085572009248
2024-02-14T19:50:32.283 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: watch_notify2_test_errcb cookie 94085572009248 err -107
2024-02-14T19:50:32.283 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: ./src/test/librados/watch_notify.cc:504: Failure
2024-02-14T19:50:32.283 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: Expected equality of these values:
2024-02-14T19:50:32.284 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify:   1u
2024-02-14T19:50:32.284 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify:     Which is: 1
2024-02-14T19:50:32.284 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify:   notify_cookies.size()
2024-02-14T19:50:32.284 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify:     Which is: 0
2024-02-14T19:50:32.284 INFO:tasks.workunit.client.0.smithi088.stdout:         api_watch_notify: [  FAILED  ] LibRadosWatchNotify.WatchNotify2Timeout (615927 ms)

looks like something new.. there is a big gup between the thrasher start-stop of osds between around 19:30:00 to 21:10:00
then we can see:

2024-02-14T21:09:29.182 INFO:tasks.thrashosds.thrasher:Traceback (most recent call last):
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 190, in wrapper
    return func(self)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 1425, in _do_thrash
    self.ceph_manager.wait_for_recovery(
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 2873, in wait_for_recovery
    assert now - start < timeout, \
AssertionError: wait_for_recovery: failed before timeout expired

2024-02-14T21:09:29.182 ERROR:tasks.thrashosds.thrasher:exception:
Traceback (most recent call last):
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 1301, in do_thrash
    self._do_thrash()
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 190, in wrapper
    return func(self)
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 1425, in _do_thrash
    self.ceph_manager.wait_for_recovery(
  File "/home/teuthworker/src/github.com_ceph_ceph-c_8420a053c0164096266bfcf03c3e3e81ef20d093/qa/tasks/ceph_manager.py", line 2873, in wait_for_recovery
    assert now - start < timeout, \
AssertionError: wait_for_recovery: failed before timeout expired

wait_for_recovery started at:

2024-02-14T19:33:58.563 INFO:tasks.ceph.ceph_manager.ceph:waiting for recovery to complete

looks like those 2 pgs making the delay:
"detail": [ {
"message": "pg 24.13 is active+recovery_wait+degraded, acting [7,6,1]"
}, {
"message": "pg 28.a is active+recovery_wait+degraded, acting [5,6,1]"
}
]

checking that

Thanks for Aishwarya who also looked on the queued ops that didn't executed, i opened new bug for it: https://tracker.ceph.com/issues/64504