snippets for client.4539.objecter from https://jenkins.ceph.com/job/ceph-api/95379/artifact/build/out/radosgw.8000.log
startup:
2025-05-07T17:23:51.076+0000 7fe487d0f880 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T17:23:51.096+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(29..29 src has 1..29)
2025-05-07T17:23:51.096+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [29,29] > 0
2025-05-07T17:23:51.096+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding full epoch 29
2025-05-07T17:23:51.096+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T17:23:51.096+0000 7fe487d0f880 10 client.4539.objecter _op_submit op 0x55f4868b1400
2025-05-07T17:23:51.096+0000 7fe487d0f880 20 client.4539.objecter _calc_target epoch 29 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T17:23:51.096+0000 7fe487d0f880 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T17:23:51.096+0000 7fe487d0f880 10 client.4539.objecter _calc_target raw pgid 3.85fca992 -> actual 3.0 acting [1,2,0] primary 1
2025-05-07T17:23:51.096+0000 7fe487d0f880 20 client.4539.objecter _get_session s=0x55f48685f080 osd=1 3
2025-05-07T17:23:51.096+0000 7fe487d0f880 10 client.4539.objecter _op_submit oid default.realm '@3' '@3' [read 0~0] tid 1 osd.1
2025-05-07T17:23:51.096+0000 7fe487d0f880 20 client.4539.objecter get_session s=0x55f48685f080 osd=1 3
2025-05-07T17:23:51.096+0000 7fe487d0f880 15 client.4539.objecter _session_op_assign 1 1
2025-05-07T17:23:51.096+0000 7fe487d0f880 15 client.4539.objecter _send_op 1 to 3.0 on osd.1
2025-05-07T17:23:51.096+0000 7fe487d0f880 20 client.4539.objecter put_session s=0x55f48685f080 osd=1 4
2025-05-07T17:23:51.096+0000 7fe487d0f880 5 client.4539.objecter 1 in flight
2025-05-07T17:23:51.096+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48b6f3c00
2025-05-07T17:23:51.096+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48b6f2800
2025-05-07T17:23:51.100+0000 7fe4824ce640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_op_reply(1 default.realm [read 0~0] v0'0 uv0 ondisk = -2 ((2) No such file or directory))
30 minutes later:
2025-05-07T17:53:51.102+0000 7fe4804ca640 1 client.4539.objecter ms_handle_reset 0x55f48b6f2800 session 0x55f48685f080 osd.1
2025-05-07T17:53:51.102+0000 7fe4804ca640 10 client.4539.objecter reopen_session osd.1 session, addr now [v2:172.21.5.39:6810/1605799410,v1:172.21.5.39:6811/1605799410]
2025-05-07T17:53:51.102+0000 7fe4804ca640 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T17:53:51.102+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(30..69 src has 1..390)
2025-05-07T17:53:51.102+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [30,69] > 29
2025-05-07T17:53:51.102+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 30
2025-05-07T17:53:51.102+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 31
...
2025-05-07T17:53:51.106+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 68
2025-05-07T17:53:51.106+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 69
2025-05-07T17:53:51.106+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T17:53:51.106+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48be44800
15 minutes later:
2025-05-07T18:08:51.104+0000 7fe4804ca640 1 client.4539.objecter ms_handle_reset 0x55f48be44800 session 0x55f48685f080 osd.1
2025-05-07T18:08:51.104+0000 7fe4804ca640 10 client.4539.objecter reopen_session osd.1 session, addr now [v2:172.21.5.39:6810/1605799410,v1:172.21.5.39:6811/1605799410]
2025-05-07T18:08:51.104+0000 7fe4804ca640 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T18:08:51.104+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(70..109 src has 1..571)
2025-05-07T18:08:51.104+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [70,109] > 69
2025-05-07T18:08:51.104+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 70
2025-05-07T18:08:51.104+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 71
...
2025-05-07T18:08:51.108+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 108
2025-05-07T18:08:51.108+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 109
2025-05-07T18:08:51.108+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T18:08:51.108+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48e598800
5 minutes later we send the [read 0~0] for 'default.realm':
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 10 client.4539.objecter _op_submit op 0x55f48e53c300
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 20 client.4539.objecter _calc_target epoch 109 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 10 client.4539.objecter _calc_target raw pgid 3.85fca992 -> actual 3.12 acting [0,3,1] primary 0
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 20 client.4539.objecter _get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 10 client.4539.objecter _op_submit oid default.realm '@3' '@3' [read 0~0] tid 10 osd.0
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 20 client.4539.objecter get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 15 client.4539.objecter _session_op_assign 0 10
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 15 client.4539.objecter _send_op 10 to 3.12 on osd.0
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 20 client.4539.objecter put_session s=0x55f48b875680 osd=0 4
2025-05-07T18:13:54.512+0000 7fe3a0b0b640 5 client.4539.objecter 1 in flight
2025-05-07T18:13:54.512+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48ee94800
2025-05-07T18:13:54.516+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(564..603 src has 1..604)
2025-05-07T18:13:54.516+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [564,603] > 109
2025-05-07T18:13:54.516+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map requesting missing epoch 110
2025-05-07T18:13:54.516+0000 7fe4804ca640 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T18:13:54.516+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T18:13:54.516+0000 7fe4804ca640 20 client.4539.objecter 10 3.85fca992 osd.0 default.realm [read 0~0]
2025-05-07T18:13:54.516+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(110..149 src has 1..604)
2025-05-07T18:13:54.516+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [110,149] > 109
2025-05-07T18:13:54.516+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 110
2025-05-07T18:13:54.516+0000 7fe4804ca640 10 client.4539.objecter checking op 10
2025-05-07T18:13:54.516+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 110 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:13:54.516+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:13:54.516+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 111
...
2025-05-07T18:13:54.524+0000 7fe4804ca640 10 client.4539.objecter checking op 10
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 148 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:13:54.524+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 149
2025-05-07T18:13:54.524+0000 7fe4804ca640 10 client.4539.objecter checking op 10
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 149 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T18:13:54.524+0000 7fe4804ca640 20 client.4539.objecter 10 3.85fca992 osd.0 default.realm [read 0~0]
multiple 5-second delays here, leading up to "tid 10 on osd.0 is laggy":
2025-05-07T18:13:56.332+0000 7fe480ccb640 10 client.4539.objecter tick
2025-05-07T18:14:01.337+0000 7fe480ccb640 10 client.4539.objecter tick
2025-05-07T18:14:06.337+0000 7fe480ccb640 10 client.4539.objecter tick
2025-05-07T18:14:06.337+0000 7fe480ccb640 2 client.4539.objecter tid 10 on osd.0 is laggy
2025-05-07T18:14:06.337+0000 7fe480ccb640 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T18:14:06.337+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(150..189 src has 1..604)
2025-05-07T18:14:06.337+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [150,189] > 149
2025-05-07T18:14:06.337+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 150
...
it's not until epoch 349 that we send the first RETRY:
2025-05-07T18:14:26.341+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 348
2025-05-07T18:14:26.341+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 349
2025-05-07T18:14:26.341+0000 7fe4804ca640 10 client.4539.objecter handle_osd_map checking op 10
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 349 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 349 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter _get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:14:26.341+0000 7fe4804ca640 20 client.4539.objecter get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:14:26.341+0000 7fe4804ca640 15 client.4539.objecter _session_op_assign 0 10
2025-05-07T18:14:26.341+0000 7fe4804ca640 15 client.4539.objecter _send_op 10 to 3.12 on osd.0
2025-05-07T18:14:26.341+0000 7fe4804ca640 1 -- 172.21.5.39:0/718804214 --> [v2:172.21.5.39:6802/495011071,v1:172.21.5.39:6803/495011071] -- osd_op(unknown.0.0:10 3.12 3:49953fa1:::default.realm:head [read 0~0] snapc 0=[] RETRY=1 ondisk+retry+read+known_if_redirected+full_try+supports_pool_eio e349) -- 0x55f48b6f2800 con 0x55f48ee94800
we send the second RETRY after epoch 429 and get a reply shortly after:
2025-05-07T18:14:41.350+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 428
2025-05-07T18:14:41.350+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map decoding incremental epoch 429
2025-05-07T18:14:41.350+0000 7fe4804ca640 10 client.4539.objecter handle_osd_map checking op 10
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 429 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:14:41.350+0000 7fe4804ca640 10 client.4539.objecter _calc_target raw pgid 3.85fca992 -> actual 3.12 acting [0,3,1] primary 0
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter _calc_target epoch 429 base default.realm @3 precalc_pgid 0 pgid 0.0 is_read
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter _calc_target target default.realm @3 -> pgid 3.85fca992
2025-05-07T18:14:41.350+0000 7fe4804ca640 1 --2- 172.21.5.39:0/718804214 >> [v2:172.21.5.39:6802/495011071,v1:172.21.5.39:6803/495011071] conn(0x55f48bce2c00 0x55f48b6cb600 unknown :-1 s=NONE pgs=0 cs=0 l=1 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0).connect
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter _get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter get_session s=0x55f48b875680 osd=0 3
2025-05-07T18:14:41.350+0000 7fe4804ca640 15 client.4539.objecter _session_op_assign 0 10
2025-05-07T18:14:41.350+0000 7fe4804ca640 15 client.4539.objecter _send_op 10 to 3.12 on osd.0
2025-05-07T18:14:41.350+0000 7fe4804ca640 1 -- 172.21.5.39:0/718804214 --> [v2:172.21.5.39:6802/495011071,v1:172.21.5.39:6803/495011071] -- osd_op(unknown.0.0:10 3.12 3:49953fa1:::default.realm:head [read 0~0] snapc 0=[] RETRY=2 ondisk+retry+read+known_if_redirected+full_try+supports_pool_eio e429) -- 0x55f48e568000 con 0x55f48bce2c00
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter put_session s=0x55f48b875680 osd=0 4
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter dump_active .. 0 homeless
2025-05-07T18:14:41.350+0000 7fe4804ca640 20 client.4539.objecter 10 3.85fca992 osd.0 default.realm [read 0~0]
2025-05-07T18:14:41.354+0000 7fe482ccf640 1 --2- 172.21.5.39:0/718804214 >> [v2:172.21.5.39:6802/495011071,v1:172.21.5.39:6803/495011071] conn(0x55f48bce2c00 0x55f48b6cb600 unknown :-1 s=BANNER_CONNECTING pgs=0 cs=0 l=1 rev1=0 crypto rx=0 tx=0 comp rx=0 tx=0)._handle_peer_banner_payload supported=3 required=0
2025-05-07T18:14:41.354+0000 7fe4804ca640 10 client.4539.objecter ms_handle_connect 0x55f48bce2c00
2025-05-07T18:14:41.354+0000 7fe482ccf640 1 --2- 172.21.5.39:0/718804214 >> [v2:172.21.5.39:6802/495011071,v1:172.21.5.39:6803/495011071] conn(0x55f48bce2c00 0x55f48b6cb600 crc :-1 s=READY pgs=674 cs=0 l=1 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).ready entity=osd.0 client_cookie=0 server_cookie=0 in_seq=0 out_seq=0
2025-05-07T18:14:41.354+0000 7fe4804ca640 1 -- 172.21.5.39:0/718804214 <== osd.0 v2:172.21.5.39:6802/495011071 1 ==== osd_map(566..605 src has 1..606) ==== 18635+0+0 (crc 0 0 0) 0x55f48b814c00 con 0x55f48bce2c00
2025-05-07T18:14:41.354+0000 7fe4804ca640 10 client.4539.objecter ms_dispatch2 0x55f4868fa000 osd_map(566..605 src has 1..606)
2025-05-07T18:14:41.354+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map got epochs [566,605] > 429
2025-05-07T18:14:41.354+0000 7fe4804ca640 3 client.4539.objecter handle_osd_map requesting missing epoch 430
2025-05-07T18:14:41.354+0000 7fe4804ca640 10 client.4539.objecter _maybe_request_map subscribing (onetime) to next osd map
2025-05-07T18:14:41.354+0000 7fe482ccf640 1 -- 172.21.5.39:0/718804214 <== osd.0 v2:172.21.5.39:6802/495011071 2 ==== osd_op_reply(10 default.realm [read 0~0] v0'0 uv0 ondisk = -2 ((2) No such file or directory)) ==== 157+0+0 (crc 0 0 0) 0x55f48bf00000 con 0x55f48bce2c00