Ceph » RADOS

There seems to be an expectation mismatch between the OSD and the Objecter (or at least the neorados bit of the Objecter). Based on a quick look, I'm inclined to say that this is an OSD bug.

1. A combined cmpext+write op arrives on the OSD:

2024-01-26T10:52:24.783-0500 7f6a861a1700  1 -- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] <== client.4499 172.21.9.34:0/3763700879 4 ==== osd_op(client.4499.0:76 59.0 59.95312129 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e304) v8 ==== 284+0+28 (crc 0 0 0) 0x5623c974e000 con 0x5623ca360480

2. cmpext fails the compare (as expected -- the client is sending data that doesn't match on purpose):

2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] _handle_message: osd_op(client.4499.0:76 59.0 59.95312129 (undecoded) ondisk+write+known_if_redirected+supports_pool_eio e304) v8
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_op: op osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e304) v8
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] op_has_sufficient_caps session=0x5623c8f2b400 pool=59 (test-librbd-senta04-2299691-58 ) pool_app_metadata={rados={}} need_read_cap=1 need_write_cap=1 classes=[] -> yes
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_op osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e304) v8 may_write may_read -> write-ordered flags ondisk+write+known_if_redirected+supports_pool_eio
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] get_object_context: found obc in cache: obc(59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head rwstate(none n=0 w=0))
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] get_object_context: obc(59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head rwstate(none n=0 w=0)) oi: 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head(304'22 client.4499.0:70 dirty s 526 uv 22 alloc_hint [4194304 4194304 0]) exists: 1 ssc(59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:snapdir snapset: 0=[]:{} ref: 1 registered: 1 exists: 1)
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] find_object_context 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head @head oi=59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head(304'22 client.4499.0:70 dirty s 526 uv 22 alloc_hint [4194304 4194304 0])
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] maybe_handle_manifest_detail: 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head is not manifest object 
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_op obc obc(59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head rwstate(excl n=1 w=0))
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] execute_ctx 0x5623c967c400
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] execute_ctx 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] ov 304'22 av 304'28 snapc 0=[] snapset 0=[]:{}
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_osd_op 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b]
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_osd_op  cmpext 512~14 in=14b
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_extent_cmp
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_osd_op 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [sync_read 512~14]
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_osd_op  sync_read 512~14
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_read
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]]  read got 14 / 14 bytes from obj 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head
2024-01-26T10:52:24.783-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] do_osd_ops error: (4100) Unknown error 4100
2024-01-26T10:52:24.783-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] execute_ctx alloc reply 0x5623c80b2d80 result -4100
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] PeeringState::calc_trim_to_aggressive limit = 304'25
2024-01-26T10:52:24.787-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]]  op order client.4499 tid 76 last was 70
2024-01-26T10:52:24.787-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] execute_ctx update_log_only -- result=-4100
2024-01-26T10:52:24.787-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] record_write_error r=-4100
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] submit_log_entries 304'28 (0'0) error    59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head by client.4499.0:76 0.000000 -4100 ObjectCleanRegions clean_offsets: [(0, 18446744073709551615)], clean_omap: true, new_object: false
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] new_repop: repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=0 r=-4100)
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'27 (0'0,304'27] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] PeeringState::merge_new_log_entries 304'28 (0'0) error    59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head by client.4499.0:76 0.000000 -4100 ObjectCleanRegions clean_offsets: [(0, 18446744073709551615)], clean_omap: true, new_object: false
2024-01-26T10:52:24.787-0500 7f6a645e6700 20 update missing, append 304'28 (0'0) error    59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head by client.4499.0:76 0.000000 -4100 ObjectCleanRegions clean_offsets: [(0, 18446744073709551615)], clean_omap: true, new_object: false
2024-01-26T10:52:24.787-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 lua=304'27 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] PeeringState::append_log_entries_update_missing trim_to bool = 1 trim_to = 0'0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 trim proposed trim_to = 0'0
2024-01-26T10:52:24.787-0500 7f6a645e6700  6 write_log_and_missing with: dirty_to: 0'0, dirty_from: 4294967295'18446744073709551615, writeout_from: 304'28, trimmed: , trimmed_dups: , clear_divergent_priors: 0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 _write_log_and_missing clearing up to 0'0 dirty_to_dups=0'0 dirty_from_dups=4294967295'18446744073709551615 write_from_dups=4294967295'18446744073709551615 trimmed_dups.size()=0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 _write_log_and_missing going to encode log.dups.size()=0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 _write_log_and_missing 1st round encoded log.dups.size()=0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 _write_log_and_missing 2st round encoded log.dups.size()=0
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 end of _write_log_and_missing
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 lua=304'27 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] op_applied version 304'28
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'25 crt=304'25 lcod 304'24 mlcod 304'24 active+clean ps=[2~1]] PeeringState::calc_trim_to_aggressive limit = 304'25
2024-01-26T10:52:24.787-0500 7f6a645e6700 10 osd.0 304 dequeue_op osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e304) v8 finish

3. Before the op is ready, OSD session gets reset (due to ms_inject_socket_failures injection on the client):

2024-01-26T10:52:24.787-0500 7f6a861a1700  1 --2- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] >> 172.21.9.34:0/3763700879 conn(0x5623ca360480 0x5623c97b8580 crc :-1 s=READY pgs=20 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_read_frame_preamble_main read frame preamble failed r=-1
2024-01-26T10:52:24.787-0500 7f6a861a1700  1 --2- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] >> 172.21.9.34:0/3763700879 conn(0x5623ca360480 0x5623c97b8580 crc :-1 s=READY pgs=20 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).stop
2024-01-26T10:52:24.787-0500 7f6a75b6c700  2 osd.0 304 ms_handle_reset con 0x5623ca360480 session 0x5623c8f2b400

4. The client resends the op and dup detection on the OSD kicks in:

2024-01-26T10:52:24.791-0500 7f6a861a1700  1 -- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] <== client.4499 172.21.9.34:0/3763700879 1 ==== osd_op(client.4499.0:76 59.0 59.95312129 (undecoded) ondisk+retry+write+known_if_redirected+supports_pool_eio e304) v8 ==== 284+0+28 (crc 0 0 0) 0x5623c974e780 con 0x5623ca3e6480

2024-01-26T10:52:24.791-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] _handle_message: osd_op(client.4499.0:76 59.0 59.95312129 (undecoded) ondisk+retry+write+known_if_redirected+supports_pool_eio e304) v8
2024-01-26T10:52:24.791-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] do_op: op osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] RETRY=1 ondisk+retry+write+known_if_redirected+supports_pool_eio e304) v8
2024-01-26T10:52:24.791-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] op_has_sufficient_caps session=0x5623c974e280 pool=59 (test-librbd-senta04-2299691-58 ) pool_app_metadata={rados={}} need_read_cap=1 need_write_cap=1 classes=[] -> yes
2024-01-26T10:52:24.791-0500 7f6a645e6700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] do_op osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] RETRY=1 ondisk+retry+write+known_if_redirected+supports_pool_eio e304) v8 may_write may_read -> write-ordered flags ondisk+retry+write+known_if_redirected+supports_pool_eio
2024-01-26T10:52:24.791-0500 7f6a645e6700  3 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] do_op dup client.4499.0:76 version 304'28

^^^ It's not logged, but I suspect that PG::check_in_progress_op() returns with user_version = 0 and an empty op_returns vector here.

2024-01-26T10:52:24.791-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] already_complete: 304'28
2024-01-26T10:52:24.791-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] already_complete: repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=0 r=-4100)
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 op_wq(0) _process 59.0 to_process <> waiting <> waiting_peering {}
2024-01-26T10:52:24.791-0500 7f6a645e6700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'28 (0'0,304'28] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'25 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] already_complete: repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=0 r=-4100) not committed, returning false

5. The op becomes ready:

2024-01-26T10:52:24.791-0500 7f6a685ee700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'27 crt=304'26 lcod 304'26 mlcod 304'26 active+clean ps=[2~1]] repop_all_committed: repop tid 1813 all committed
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'26 active+clean ps=[2~1]] PeeringState::calc_min_last_complete_ondisk last_complete_ondisk is updated to: 304'27 from: 304'26
2024-01-26T10:52:24.791-0500 7f6a685ee700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]] eval_repop repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=1 r=-4100)
2024-01-26T10:52:24.791-0500 7f6a685ee700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]]  commit: repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=1 r=-4100)

6. Reply with user_version = 0 is sent:

2024-01-26T10:52:24.791-0500 7f6a685ee700  1 -- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] --> 172.21.9.34:0/3763700879 -- osd_op_reply(76 rbd_data.1193ad1baaa.0000000000000000 [cmpext 512~14,write 512~14] v304'28 uv0 ondisk = -4100 ((4100) Unknown error 4100)) v8 -- 0x5623c92786c0 con 0x5623ca3e6480
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]] PeeringState::prepare_stats_for_publish reporting purged_snaps [2~1]
2024-01-26T10:52:24.791-0500 7f6a685ee700 15 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]] PeeringState::prepare_stats_for_publish publish_stats_to_osd 304:75
2024-01-26T10:52:24.791-0500 7f6a685ee700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]]  removing repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=1 r=-4100)
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]]    q front is repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=1 r=-4100)
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]] finished operator() r=-4100
2024-01-26T10:52:24.791-0500 7f6a685ee700 10 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]]  sending commit on osd_op(client.4499.0:76 59.0 59:94848ca9:::rbd_data.1193ad1baaa.0000000000000000:head [cmpext 512~14 in=14b,write 512~14 in=14b] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e304) v8 0x5623c80b2d80

7. Reply with user_version != 0 is sent:

2024-01-26T10:52:24.791-0500 7f6a685ee700  1 -- [v2:172.21.9.34:6802/39207300,v1:172.21.9.34:6803/39207300] --> 172.21.9.34:0/3763700879 -- osd_op_reply(76 rbd_data.1193ad1baaa.0000000000000000 [cmpext 512~14,write 512~14] v304'28 uv22 ondisk = -4100 ((4100) Unknown error 4100)) v8 -- 0x5623c80b2d80 con 0x5623ca360480
2024-01-26T10:52:24.791-0500 7f6a685ee700 20 osd.0 pg_epoch: 304 pg[59.0( v 304'30 (0'0,304'30] local-lis/les=301/302 n=9 ec=301/301 lis/c=301/301 les/c/f=302/302/0 sis=301) [0] r=0 lpr=301 luod=304'28 crt=304'26 lcod 304'27 mlcod 304'27 active+clean ps=[2~1]] remove_repop repgather(0x5623c982d800 304'28 rep_tid=1813 committed?=1 r=-4100)

8. On the client side, Objecter processes the reply with user_version = 0. This reply also happens to have rval = 0 for all ops, including cmpext even though it failed the compare:

2024-01-26T10:52:24.791-0500 7ff755ffb700  1 -- 172.21.9.34:0/3763700879 <== osd.0 v2:172.21.9.34:6802/39207300 1 ==== osd_op_reply(76 rbd_data.1193ad1baaa.0000000000000000 [cmpext 512~14,write 512~14] v304'28 uv0 ondisk = -4100 ((4100) Unknown error 4100)) v8 ==== 223+0+0 (crc 0 0 0) 0x7ff704078040 con 0x7ff72c025d50
2024-01-26T10:52:24.791-0500 7ff755ffb700 10 client.4499.objecter ms_dispatch 0x55bffcc34780 osd_op_reply(76 rbd_data.1193ad1baaa.0000000000000000 [cmpext 512~14,write 512~14] v304'28 uv0 ondisk = -4100 ((4100) Unknown error 4100)) v8
2024-01-26T10:52:24.791-0500 7ff755ffb700 10 client.4499.objecter in handle_osd_op_reply
2024-01-26T10:52:24.791-0500 7ff755ffb700  7 client.4499.objecter handle_osd_op_reply 76 ondisk uv 0 in 59.0 attempt 1
2024-01-26T10:52:24.791-0500 7ff755ffb700 10 client.4499.objecter  op 0 rval 0 len 0
2024-01-26T10:52:24.791-0500 7ff755ffb700 10 client.4499.objecter  op 1 rval 0 len 0
2024-01-26T10:52:24.791-0500 7ff755ffb700 15 client.4499.objecter handle_osd_op_reply completed tid 76
2024-01-26T10:52:24.791-0500 7ff755ffb700 15 client.4499.objecter _finish_op 76

Because of rval = 0 there, Adam's cmpext "handler" from https://github.com/ceph/ceph/pull/52495 doesn't set mismatch_offset and doesn't adjust the overall return code. -4100 is returned to the user (librbd in this case), which chokes on it: we expect -MAX_ERRNO (-4095) overall return code and mismatch_offset = 5.

For comparison, here is Objecter processing the same thing when retries aren't involved:

2024-01-26T10:47:07.259-0500 7ff743fff700 10 client.4142.objecter ms_dispatch 0x55bffca54cd0 osd_op_reply(67 rbd_data.102eba81544b.0000000000000000 [cmpext 512~14,write 512~14] v12'23 uv21 ondisk = -4100 ((4100) Unknown error 4100)) v8
2024-01-26T10:47:07.259-0500 7ff743fff700 10 client.4142.objecter in handle_osd_op_reply
2024-01-26T10:47:07.259-0500 7ff743fff700  7 client.4142.objecter handle_osd_op_reply 67 ondisk uv 21 in 2.0 attempt 0
2024-01-26T10:47:07.259-0500 7ff743fff700 10 client.4142.objecter  op 0 rval -4100 len 0
2024-01-26T10:47:07.259-0500 7ff743fff700 10 client.4142.objecter ERROR: tid 67: handler function threw CmpExt mismatch [osd:4095]
2024-01-26T10:47:07.259-0500 7ff743fff700 10 client.4142.objecter  op 1 rval 0 len 0
2024-01-26T10:47:07.259-0500 7ff743fff700 15 client.4142.objecter handle_osd_op_reply completed tid 67
2024-01-26T10:47:07.259-0500 7ff743fff700 15 client.4142.objecter _finish_op 67

Radoslaw, is PG::check_in_progress_op() returning with user_version = 0 and an empty op_returns vector, causing a dummy reply with user_version = 0 and rval = 0 for all ops being sent first, expected? Should such a dummy reply be sent at all?