Ceph » Linux kernel client

The Rados just returned a very large extents 2208169984 and kernel libceph couldn't allocate enough memory for it and reset the connection and keep retrying the osd requests.

Hi Xiubo,

Is there any confirmation of that number in the OSD logs? I think it's more likely that the kernel client parses the OSD reply message incorrectly.

Ilya Dryomov wrote:

The Rados just returned a very large extents 2208169984 and kernel libceph couldn't allocate enough memory for it and reset the connection and keep retrying the osd requests.

Hi Xiubo,

Is there any confirmation of that number in the OSD logs? I think it's more likely that the kernel client parses the OSD reply message incorrectly.

No, in BlueStore.cc there has one log about that but the teuthology test doesn't enable it. All the other logs in osd.6 are correct and normal.

Raised two PRs to add more debug logs in osd and bluestore:

https://github.com/ceph/ceph/pull/54571
https://github.com/ceph/ceph/pull/54628

If the OSD says it's returning 64K of read data, it seems like it can't have returned 2208169984 separate extents? I don't know if the problem is with the kernel decoder, or the OSD encoder, but surely one of those has done something wrong...

Greg Farnum wrote:

If the OSD says it's returning 64K of read data, it seems like it can't have returned 2208169984 separate extents? I don't know if the problem is with the kernel decoder, or the OSD encoder, but surely one of those has done something wrong...

Yeah, the protocol seems correct for me. Maybe the issue locates in kernel libceph. I will spend more time on the kernel side during reproducing it.

Locally I reproduce a similar case and get the debug log by enabling the whole libceph.ko module debug logs, which is that the sr_datalen != 0 after parsing out the extents:

11740489 <7>[180935.437443] libceph:  ceph_sock_data_ready 000000003cbb0298 state = 12, queueing work
11740490 <7>[180935.437457] libceph:  get_osd 0000000061a3b6b6 3 -> 4
11740491 <7>[180935.437462] libceph:  queue_con_delay 000000003cbb0298 0
11740492 <7>[180935.437541] libceph:  try_read start 000000003cbb0298 state 12
11740493 <7>[180935.437547] libceph:  try_read tag 1 in_base_pos 0
11740494 <7>[180935.437555] libceph:  try_read got tag 7
11740495 <7>[180935.437558] libceph:  prepare_read_message 000000003cbb0298
11740496 <7>[180935.437562] libceph:  read_partial_message con 000000003cbb0298 msg 0000000000000000
11740497 <7>[180935.437569] libceph:  got hdr type 43 front 164 data 16408
11740498 <7>[180935.437575] libceph:  ceph_msg_revoke_incoming msg 0000000086d0af49 null con
11740499 <7>[180935.437579] libceph:  ceph_msg_get 0000000086d0af49 (was 1)
11740500 <7>[180935.437584] libceph:  get_reply tid 55853 0000000086d0af49
11740501 <7>[180935.437588] libceph:  get_osd 0000000061a3b6b6 4 -> 5
11740502 <7>[180935.437594] libceph:  prep_next_sparse_read: [2] starting new sparse read req. srlen=0x4000
11740503 <7>[180935.437600] libceph:  prep_next_sparse_read: [2] new sparse read op at idx 0 0x16c000~0x4000
11740504 <7>[180935.437607] libceph:  [2] got 1 extents                                                                   ===> Got 1 extent                                                                                                                       
11740505 <7>[180935.437613] libceph:  [2] sr_datalen 16384
11740506 <7>[180935.437616] libceph:  [2] ext 0 off 0x16c000 len 0x4000
11740507 <7>[180935.437629] libceph:  prep_next_sparse_read: [2] completed extent array len 1 cursor->resid 0             ===> And successfully parsed out the data
11740508 <7>[180935.437636] libceph:  try_read done on 000000003cbb0298 ret 0
11740509 <7>[180935.437641] libceph:  try_write start 000000003cbb0298 state 12
11740510 <7>[180935.437645] libceph:  try_write out_kvec_bytes 0
11740511 <7>[180935.437648] libceph:  try_write nothing else to write.
11740512 <7>[180935.437652] libceph:  try_write done on 000000003cbb0298 ret 0
11740513 <7>[180935.437656] libceph:  put_osd 0000000061a3b6b6 5 -> 4
11740514 <7>[180935.437701] libceph:  ceph_sock_data_ready 000000003cbb0298 state = 12, queueing work
11740515 <7>[180935.437707] libceph:  get_osd 0000000061a3b6b6 4 -> 5
11740516 <7>[180935.437710] libceph:  queue_con_delay 000000003cbb0298 0
11740517 <7>[180935.437786] libceph:  try_read start 000000003cbb0298 state 12
11740518 <7>[180935.437792] libceph:  try_read tag 7 in_base_pos 67
11740519 <7>[180935.437795] libceph:  read_partial_message con 000000003cbb0298 msg 0000000086d0af49
11740520 <7>[180935.437800] libceph:  prep_next_sparse_read: [2] starting new sparse read req. srlen=0x4000
11740521 <7>[180935.437807] libceph:  prep_next_sparse_read: [2] new sparse read op at idx 0 0x16c000~0x4000
11740522 <7>[180935.437814] libceph:  [2] got 0 extents                                                           ===> But later the socket was ready again and got 0 extent
11740523 <7>[180935.437912] libceph:  try_read done on 000000003cbb0298 ret 0
11740524 <7>[180935.437920] libceph:  try_write start 000000003cbb0298 state 12
11740525 <7>[180935.437926] libceph:  try_write out_kvec_bytes 0
11740526 <7>[180935.437929] libceph:  try_write nothing else to write.
11740527 <7>[180935.437940] libceph:  try_write done on 000000003cbb0298 ret 0
11740528 <7>[180935.437946] libceph:  put_osd 0000000061a3b6b6 5 -> 4
11740529 <7>[180935.515282] libceph:  ceph_sock_write_space 00000000296677ea nothing to write
11740530 <7>[180935.515427] libceph:  ceph_sock_write_space 00000000296677ea nothing to write
11740531 <7>[180935.523367] libceph:  handle_timeout osdc 00000000ce79daa0
11740532 <7>[180935.523391] libceph:  handle_timeout osdc 000000006ce90278
...
11741054 <7>[180940.606482] libceph:  [2] sr_datalen 251723776                                                       ===> It detected the sr_datalen is not zero                                                                                                                                                                   
11741055 <4>[180940.606488] libceph: sr_datalen 251723776 sr_index 0 count 0
11741056 <7>[180940.606494] libceph:  prep_next_sparse_read: [2] completed extent array len 0 cursor->resid 16384

The following is another similar case, which only enabled the net/ceph/osd_client.c debug logs:

3502640 <7>[101716.021654] libceph:  put_osd 0000000053846a81 29 -> 28
3502641 <7>[101716.021661] libceph:  get_osd 0000000053846a81 28 -> 29
3502642 <7>[101716.021671] libceph:  prep_next_sparse_read: [0] starting new sparse read req. srlen=0x4000 
3502643 <7>[101716.021677] libceph:  prep_next_sparse_read: [0] new sparse read op at idx 0 0x0~0x4000
3502644 <7>[101716.021683] libceph:  [0] got 1 extents
3502645 <7>[101716.021767] libceph:  [0] sr_datalen 16384
3502646 <7>[101716.021775] libceph:  [0] ext 0 off 0x0 len 0x4000
3502647 <7>[101716.021797] libceph:  prep_next_sparse_read: [0] completed extent array len 1 cursor->resid 0
3502648 <7>[101716.021811] libceph:  put_osd 0000000053846a81 29 -> 28
3502649 <7>[101716.022023] libceph:  get_osd 0000000053846a81 28 -> 29
3502650 <7>[101716.022211] libceph:  get_osd 0000000053846a81 29 -> 30
3502651 <7>[101716.022219] libceph:  put_osd 0000000053846a81 30 -> 29
3502652 <7>[101716.022392] libceph:  get_osd 0000000053846a81 29 -> 30
3502653 <7>[101716.022401] libceph:  put_osd 0000000053846a81 30 -> 29
3502654 <7>[101716.022582] libceph:  prep_next_sparse_read: [0] starting new sparse read req. srlen=0x4000
3502655 <7>[101716.022593] libceph:  prep_next_sparse_read: [0] new sparse read op at idx 0 0x0~0x4000
3502656 <7>[101716.022607] libceph:  [0] got 0 extents
3502657 <7>[101716.022671] libceph:  [0] sr_datalen 117506048
3502658 <4>[101716.022681] libceph: sr_datalen 117506048 sr_index 0 count 0                                                                                                                                                            
3502659 <7>[101716.022688] libceph:  prep_next_sparse_read: [0] completed extent array len 0 cursor->resid 16384
3502660 <3>[101716.022716] libceph: read_partial_message 000000000bdea690 data crc 73138397 != exp. 2589702240
3502661 <4>[101716.022729] libceph: osd0 (1)192.168.0.103:6801 bad crc/signature
3502662 <7>[101716.023109] libceph:  osd_fault osd 0000000053846a81 osd0
3502663 <7>[101716.023122] libceph:  reopen_osd osd 0000000053846a81 osd0
3502664 <7>[101716.023136] libceph:  get_osd 0000000053846a81 29 -> 30 
3502665 <7>[101716.023162] libceph:  encode_request_partial req 000000009a4f0cd7 msg 000000000792e2f4 oid 100000014ef.00000000 oid_len 20
3502666 <7>[101716.023178] libceph:  send_request req 000000009a4f0cd7 tid 127209 to pgid 3.9c3fa529 spgid 3.29s-1 osd0 e55 flags 0x40001c attempt 2
3502667 <7>[101716.023203] libceph:  put_osd 0000000053846a81 30 -> 29
3502668 <7>[101716.023208] libceph:  get_osd 0000000053846a81 29 -> 30 
3502669 <7>[101716.023218] libceph:  get_osd 0000000053846a81 30 -> 31
3502670 <7>[101716.023225] libceph:  put_osd 0000000053846a81 31 -> 30 
3502671 <7>[101716.023235] libceph:  encode_request_partial req 00000000214ecc66 msg 0000000062704b4f oid 100000014e9.00000000 oid_len 20
3502672 <7>[101716.023245] libceph:  send_request req 00000000214ecc66 tid 127210 to pgid 3.dfc16f54 spgid 3.54s-1 osd0 e55 flags 0x40001c attempt 2
3502673 <7>[101716.023259] libceph:  put_osd 0000000053846a81 30 -> 29
3502674 <7>[101716.023265] libceph:  get_osd 0000000053846a81 29 -> 30 
3502675 <7>[101716.023274] libceph:  encode_request_partial req 0000000006a7569e msg 000000000dcfe38a oid 100000014ef.00000000 oid_len 20
3502676 <7>[101716.023285] libceph:  send_request req 0000000006a7569e tid 127211 to pgid 3.9c3fa529 spgid 3.29s-1 osd0 e55 flags 0x40001c attempt 2
3502677 <7>[101716.023298] libceph:  put_osd 0000000053846a81 30 -> 29
3502678 <7>[101716.023306] libceph:  get_osd 0000000053846a81 29 -> 30
3502679 <7>[101716.023316] libceph:  encode_request_partial req 000000006f34cd26 msg 000000004f69eb40 oid 100000014ef.00000000 oid_len 20
3502680 <7>[101716.023327] libceph:  send_request req 000000006f34cd26 tid 127212 to pgid 3.9c3fa529 spgid 3.29s-1 osd0 e55 flags 0x40001c attempt 2
...

This time the osd request tid 127209 just caused data crc failure and retried the requests 3 times and then succeeded and completed the request:

3503041 <7>[101716.034397] libceph:  put_osd 0000000053846a81 29 -> 28
3503042 <7>[101716.034405] libceph:  get_osd 0000000053846a81 28 -> 29
3503043 <7>[101716.034417] libceph:  prep_next_sparse_read: [0] starting new sparse read req. srlen=0x4000
3503044 <7>[101716.034427] libceph:  put_osd 000000007e261c91 24 -> 23
3503045 <7>[101716.034427] libceph:  prep_next_sparse_read: [0] new sparse read op at idx 0 0x0~0x4000
3503046 <7>[101716.034439] libceph:  [0] got 1 extents
3503047 <7>[101716.034470] libceph:  encode_request_finish msg 000000001058a975 tid 127245 221+0+0 v8
3503048 <7>[101716.034513] libceph:  [0] sr_datalen 16384
3503049 <7>[101716.034521] libceph:  [0] ext 0 off 0x0 len 0x4000
3503050 <7>[101716.034543] libceph:  prep_next_sparse_read: [0] completed extent array len 1 cursor->resid 0
3503051 <7>[101716.034558] libceph:  put_osd 0000000053846a81 29 -> 28
3503052 <7>[101716.034648] libceph:  get_osd 0000000053846a81 28 -> 29
...
3504317 <7>[101716.095474] libceph:  handle_reply req 000000009a4f0cd7 tid 127209 flags 0x40001d pgid 3.29 epoch 55 attempt 3 v 0'0 uv 3337
3504318 <7>[101716.095491] libceph:   req 000000009a4f0cd7 tid 127209 op 0 rval 0 len 16408
3504319 <7>[101716.095497] libceph:  get_osd 000000007e261c91 39 -> 40
3504320 <7>[101716.095498] libceph:  handle_reply req 000000009a4f0cd7 tid 127209 result 0 data_len 16408
3504321 <7>[101716.095502] libceph:  finish_request req 000000009a4f0cd7 tid 127209
3504322 <7>[101716.095506] libceph:  unlink_request osd 0000000053846a81 osd0 req 000000009a4f0cd7 tid 127209
3504323 <7>[101716.095510] libceph:  put_osd 0000000053846a81 36 -> 35
3504324 <7>[101716.095521] libceph:  prep_next_sparse_read: [1] starting new sparse read req. srlen=0x10000
3504325 <7>[101716.095531] libceph:  prep_next_sparse_read: [1] new sparse read op at idx 0 0x18000~0x10000
3504326 <7>[101716.095544] libceph:  [1] got 1 extents
3504327 <7>[101716.095556] libceph:  [1] sr_datalen 65536
3504328 <7>[101716.095514] libceph:  __complete_request req 000000009a4f0cd7 tid 127209 cb finish_netfs_read [ceph] result 16408

Checked the osd side logs, all looked good.

Just the read_partial() couldn't successfully read the 21 bytes footer data from the socket:

1143 /*
1144  * read (part of) a message. 
1145  */             
1146 static int read_partial_message(struct ceph_connection *con)
1147 {               
...
1266         /* footer */
1267         size = sizeof_footer(con);
1268         end += size;          
1269         ret = read_partial(con, end, size, &m->footer);
1270         if (ret <= 0)         
1271                 return ret;
...

And returned 0. That means for the current osd reply, it seems the msg just lost some data ? or the msg was split into two socket msgs. And need to wait ?

The detail logs:

 4934308 <7>[ 5971.769375] libceph:  ceph_sock_data_ready 00000000043ac662 state = 12, queueing work
 4934309 <7>[ 5971.769390] libceph:  get_osd 00000000c4a173e4 6 -> 7
 4934310 <7>[ 5971.769400] libceph:  queue_con_delay 00000000043ac662 0
 4934311 <7>[ 5971.769456] libceph:  try_read start 00000000043ac662 state 12
 4934312 <7>[ 5971.769471] libceph:  try_read tag 1 in_base_pos 0
 4934313 <7>[ 5971.769576] libceph:  try_read got tag 7
 4934314 <7>[ 5971.769584] libceph:  prepare_read_message 00000000043ac662
 4934315 <7>[ 5971.769594] libceph:  read_partial_message con 00000000043ac662 msg 0000000000000000
 4934316 <7>[ 5971.769602] libceph:  read_partial left:53 have:0 size:53 con->v1.in_base_pos:0
 4934317 <7>[ 5971.769614] libceph:  read_partial return 1
 4934318 <7>[ 5971.769621] libceph:  got hdr type 43 front 164 data 16408
 4934319 <7>[ 5971.769633] libceph:  ceph_msg_revoke_incoming con 00000000043ac662 msg 0000000091573b78 not current, in_msg 0000000000000000
 4934320 <7>[ 5971.769644] libceph:  ceph_msg_get 0000000091573b78 (was 1)
 4934321 <7>[ 5971.769657] libceph:  get_reply tid 50437 0000000091573b78                                      ===> Received osd req reply for 'tid 50437'
 4934322 <7>[ 5971.769667] libceph:  put_osd 00000000c4a173e4 7 -> 6
 4934323 <7>[ 5971.769674] libceph:  get_osd 00000000c4a173e4 6 -> 7
 4934324 <7>[ 5971.769686] libceph:  prep_next_sparse_read: [2] starting new sparse read req. srlen=0x4000
 4934325 <7>[ 5971.769698] libceph:  prep_next_sparse_read: [2] new sparse read op at idx 0 0x83000~0x4000
 4934326 <7>[ 5971.769711] libceph:  [2] got 1 extents                                                         ===> Got 1 extent
 4934327 <44>[ 5971.769747] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934328 <7>[ 5971.769790] libceph:  [2] ext 0 off 0x83000 len 0x4000
 4934329 <7>[ 5971.769815] libceph:  prep_next_sparse_read: [2] completed extent array len 1 cursor->resid 0
 4934330 <7>[ 5971.769827] libceph:  read_partial left:21 have:0 size:21 con->v1.in_base_pos:53
 4934331 <7>[ 5971.769839] libceph:  read_partial left:7 have:14 size:21 con->v1.in_base_pos:67
 4934332 <7>[ 5971.769848] libceph:  read_partial return 0                                                     ===> But when reading the 21 bytes 'footer' failed
 4934333 <7>[ 5971.769857] libceph:  try_read done on 00000000043ac662 ret 0
 4934334 <7>[ 5971.769868] libceph:  try_write start 00000000043ac662 state 12
 4934335 <7>[ 5971.769876] libceph:  try_write out_kvec_bytes 0
 4934336 <44>[ 5971.769876] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934337 <7>[ 5971.769887] libceph:  try_write nothing else to write.
 4934338 <7>[ 5971.769894] libceph:  try_write done on 00000000043ac662 ret 0
 4934339 <7>[ 5971.769901] libceph:  put_osd 00000000c4a173e4 7 -> 6
 4934340 <7>[ 5971.770003] libceph:  ceph_sock_data_ready 00000000043ac662 state = 12, queueing work
 4934341 <7>[ 5971.770018] libceph:  get_osd 00000000c4a173e4 6 -> 7
 4934342 <7>[ 5971.770025] libceph:  queue_con_delay 00000000043ac662 0
 4934343 <7>[ 5971.770335] libceph:  try_read start 00000000043ac662 state 12
 4934344 <7>[ 5971.770346] libceph:  try_read tag 7 in_base_pos 67
 4934345 <7>[ 5971.770356] libceph:  read_partial_message con 00000000043ac662 msg 0000000091573b78
 4934346 <7>[ 5971.770363] libceph:  read_partial return 1
 4934347 <7>[ 5971.770371] libceph:  prep_next_sparse_read: [2] starting new sparse read req. srlen=0x4000     ===> And couldn't complete the req and just retried it
 4934348 <7>[ 5971.770380] libceph:  prep_next_sparse_read: [2] new sparse read op at idx 0 0x83000~0x4000
 4934349 <44>[ 5971.770381] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934350 <7>[ 5971.770393] libceph:  [2] got 0 extents                                                         ===> This time got 0 extent 
 4934351 <7>[ 5971.770407] libceph:  try_read done on 00000000043ac662 ret 0
 4934352 <7>[ 5971.770415] libceph:  try_write start 00000000043ac662 state 12
 4934353 <7>[ 5971.770427] libceph:  try_write out_kvec_bytes 0
 4934354 <7>[ 5971.770434] libceph:  try_write nothing else to write.
 4934355 <7>[ 5971.770440] libceph:  try_write done on 00000000043ac662 ret 0
 4934356 <7>[ 5971.770448] libceph:  put_osd 00000000c4a173e4 7 -> 6
 4934357 <44>[ 5971.770506] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934358 <7>[ 5971.770925] libceph:  ceph_sock_data_ready 00000000043ac662 state = 12, queueing work
 4934359 <7>[ 5971.770938] libceph:  get_osd 00000000c4a173e4 6 -> 7
 4934360 <7>[ 5971.770948] libceph:  queue_con_delay 00000000043ac662 0
 4934361 <7>[ 5971.771003] libceph:  try_read start 00000000043ac662 state 12
 4934362 <7>[ 5971.771016] libceph:  try_read tag 7 in_base_pos 67
 4934363 <44>[ 5971.771018] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934364 <7>[ 5971.771023] libceph:  read_partial_message con 00000000043ac662 msg 0000000091573b78
 4934365 <7>[ 5971.771028] libceph:  read_partial return 1
 4934366 <4>[ 5971.771040] libceph: sr_datalen 117506048 sr_index 0 count 0                                    ===> Incorrectly parsed the 'sr_datalen'
 4934367 <7>[ 5971.771048] libceph:  prep_next_sparse_read: [2] completed extent array len 0 cursor->resid 16384
 4934368 <7>[ 5971.771059] libceph:  read_partial left:7 have:14 size:21 con->v1.in_base_pos:67                ===> Just received the rest 7 bytes for the 'footer'
 4934369 <7>[ 5971.771071] libceph:  read_partial return 1
 4934370 <7>[ 5971.771078] libceph:  read_partial_message got msg 0000000091573b78 164 (3282417571) + 0 (0) + 16408 (3951688286)
 4934371 <3>[ 5971.771089] libceph: read_partial_message 0000000091573b78 data crc 1149494181 != exp. 3951688286
 4934372 <7>[ 5971.771098] libceph:  try_read done on 00000000043ac662 ret -5
 4934373 <7>[ 5971.771110] libceph:  fault 00000000043ac662 state 12 to peer (1)192.168.0.103:6809
 4934374 <4>[ 5971.771120] libceph: osd2 (1)192.168.0.103:6809 bad crc/signature
 4934375 <7>[ 5971.771128] libceph:  ceph_con_reset_protocol con 00000000043ac662
 4934376 <7>[ 5971.771141] libceph:  ceph_con_close_socket con 00000000043ac662 sock 00000000269625b3
 4934377 <44>[ 5971.771152] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934378 <7>[ 5971.771351] libceph:  ceph_sock_state_change 00000000043ac662 state = 12 sk_state = 4
 4934379 <7>[ 5971.771766] libceph:  con_sock_state_closed con 00000000043ac662 sock 3 -> 1
 4934380 <7>[ 5971.771779] libceph:  ceph_msg_put 0000000091573b78 (was 2)
 4934381 <7>[ 5971.771787] libceph:  fault on LOSSYTX channel, marking CLOSED
 4934382 <7>[ 5971.771794] libceph:  con_fault_finish 00000000043ac662
 4934383 <7>[ 5971.771803] libceph:  osd_fault osd 00000000c4a173e4 osd2
 4934384 <7>[ 5971.771811] libceph:  reopen_osd osd 00000000c4a173e4 osd2
 4934385 <7>[ 5971.771822] libceph:  con_close 00000000043ac662 peer (1)192.168.0.103:6809
 4934386 <7>[ 5971.771832] libceph:  ceph_con_reset_protocol con 00000000043ac662
 4934387 <44>[ 5971.771834] systemd-journald[730]: /dev/kmsg buffer overrun, some messages lost.
 4934388 <7>[ 5971.771840] libceph:  ceph_con_close_socket con 00000000043ac662 sock 0000000000000000
 4934389 <7>[ 5971.771846] libceph:  con_sock_state_closed con 00000000043ac662 sock 1 -> 1
 4934390 <7>[ 5971.771851] libceph:  ceph_con_reset_session con 00000000043ac662
 4934391 <7>[ 5971.771856] libceph:  ceph_msg_put 00000000754d3dac (was 2)
 4934392 <7>[ 5971.771862] libceph:  ceph_msg_put 0000000071381bef (was 2)
 4934393 <7>[ 5971.771873] libceph:  con_open 00000000043ac662 (1)192.168.0.103:6809
 4934394 <7>[ 5971.771881] libceph:  get_osd 00000000c4a173e4 7 -> 8
 4934395 <7>[ 5971.771889] libceph:  queue_con_delay 00000000043ac662 0
 4934396 <7>[ 5971.771912] libceph:  ceph_msg_revoke con 00000000043ac662 msg 00000000754d3dac not linked
 4934397 <7>[ 5971.771923] libceph:  encode_request_partial req 000000008e0e70f0 msg 00000000754d3dac oid 10000000a2e.00000005 oid_len 20
 4934398 <7>[ 5971.771936] libceph:  send_request req 000000008e0e70f0 tid 50437 to pgid 3.94a7c616 spgid 3.16s-1 osd2 e50 flags 0x40001c attempt 3   ===> Retried the req
 4934399 <7>[ 5971.771950] libceph:  ceph_msg_get 00000000754d3dac (was 1)

The V2: https://patchwork.kernel.org/project/ceph-devel/list/?series=808305&archive=both