Ceph » RADOS

fast read finishes...

2018-07-11 16:14:12.509 7f42ce141700 20 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1780 (0'0,124'1780] local-lis/les=100/101 n=1 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] handle_sub_read_reply have shard=1
2018-07-11 16:14:12.509 7f42ce141700 20 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1780 (0'0,124'1780] local-lis/les=100/101 n=1 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] handle_sub_read_reply have shard=2
2018-07-11 16:14:12.509 7f42ce141700 20 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1780 (0'0,124'1780] local-lis/les=100/101 n=1 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] handle_sub_read_reply Complete: ReadOp(tid=25071, to_read={2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head=read_request_t(to_read=[0,8192,0], need={1(1)=[0,1],5(2)=[0,1],7(0)=[0,1]}, want_attrs=0)}, complete={2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head=read_result_t(r=0, errors={}, noattrs, returned=(0, 8192, [1(1),4096, 5(2),4096]))}, priority=127, obj_to_source={2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head=1(1),5(2),7(0)}, source_to_obj={1(1)=2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head,5(2)=2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head,7(0)=2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head}, in_progress=7(0))

a delete comes through...

2018-07-11 16:14:12.514 7f42ca139700 10 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1780 (0'0,124'1780] local-lis/les=100/101 n=1 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] do_osd_op  delete
2018-07-11 16:14:12.514 7f42ca139700 20 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1780 (0'0,124'1780] local-lis/les=100/101 n=1 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] _delete_oid 2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head whiteout=0 no_whiteout=0 try_no_whiteout=0

...
the local read op (that we didn't wait for) gets processed, and blocks in filestore

2018-07-11 16:14:12.515 7f42ce141700 25 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1781 (0'0,124'1781] local-lis/les=100/101 n=0 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 luod=124'1780 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] handle_sub_read case1: reading the complete chunk/shard.
2018-07-11 16:14:12.515 7f42ce141700 15 filestore(/var/lib/ceph/osd/ceph-7) read(3309): 2.10s0_head/0#2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head# 0~4096

the delete happens

2018-07-11 16:14:12.516 7f42e1bef700 10 filestore(/var/lib/ceph/osd/ceph-7) _collection_move_rename(5573): 2.10s0_head/0#2:08d04b95:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head#6f5 from 2.10s0_head/0#2:08d04b95:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head# = 0

the read unblocks (in filestore) and fails

2018-07-11 16:14:12.516 7f42ce141700 10 filestore(/var/lib/ceph/osd/ceph-7) error opening file /var/lib/ceph/osd/ceph-7/current/2.10s0_head/smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo_df442cd7d5503ee128f4_0_long with flags=2: (2) No such file or directory
2018-07-11 16:14:12.516 7f42ce141700 10 filestore(/var/lib/ceph/osd/ceph-7) read(3317): (2.10s0_head/0#2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head#) open error: (2) No such file or directory
2018-07-11 16:14:12.516 7f42ce141700  5 osd.7 pg_epoch: 124 pg[2.10s0( v 124'1781 (0'0,124'1781] local-lis/les=100/101 n=0 ec=33/20 lis/c 100/100 les/c/f 101/101/0 100/100/20) [7,1,5]p7(0) r=0 lpr=100 luod=124'1780 crt=124'1780 lcod 124'1779 mlcod 124'1779 active+clean] handle_sub_read: Error -2 reading 2:8d04b950:::smithi04683791-9 oooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo:head

/a/sage-2018-07-11_15:39:05-rados:thrash-erasure-code-master-distro-basic-smithi/2768764

From the user's perspective all is well since the subread reply is ignored (read logically finished), but the error log message is misleading.