Ceph » RADOS

The object oi.size should be 4194304, but it is actually 4063232.
The object data_digest is 0xffffffff, but read crc is 0x29d98db8.

-----------------------------------------------------------------
in this case:
client write 0~4M, osd received multiple ops [0~128k], [131072~128k], [262144~128k], ..., [4063232~128k]
when write complete, oi.size should be 4194304.
but other truncate will modify op's length and truncate oi.size.

Consider two abnormal cases:
1. write after truncate, need to do truncate first and then do write.
2. write before truncate, need to trim length first and then do write.]

-----------------------------------------------------------------
in case2:
if truncate is to 0,
write is [0~128k]
trim length from 128k to 0, write change to [0~0], do nothing, oi.size is 0, x1 = set_data_digest(crc32(-1)).
write is [128k~128k]
trim length from 128k to 0, write change to [128k~0], truncate oi.size to offset 128k, x2 = set_data_digest(crc32(x1)).
write is [256k~128k]
trim length from 128k to 0, write change to [256k~0], truncate oi.size to offset 256k, x3 = set_data_digest(crc32(x2)).
...
write is [4063232~128k]
trim length from 128k to 0, write change to [4063232~0], truncate oi.size to offset 4063232, xn = set_data_digest(crs32(xn-1))

Now, we can see oi.size is 4063232, and data_digest is 0xffffffff, because thelength of in_data of crc is 0 every time.

---------------------------------------------------------------------
in conclusion, There are two logical problems that need to be fixed:
1. when truncate in write, need clear data_digest and DIGEST flag
2. when write before truncate, need to trim length, when offset over than oi.size, don't truncate oi.size to offset.

https://github.com/ceph/ceph/pull/43902

my ceph version is nautilous 14.2.5

Our cluster seems to have encountered a similar issue to yours. We haven't yet identified the root cause. I'm wondering if it might be due to the same reason you mentioned. Could you please help me check if it's the same issue as yours?
The issue with our cluster occurred like this: one of the osd.32 committed suicide due to timeout caused by the excessive pressure of data deletion. Subsequently, an object in pg 2.ac7 encountered an 'object unfound' situation.
------------------------------
118078 2023-11-20 12:07:50.149172 osd.44 (osd.44) 88770 : cluster [ERR] 2.ac7 missing primary copy of 2:e357d41e:::200516ce993.0000002d:head, will try copies on 20
118079 2023-11-20 12:07:51.101958 osd.44 (osd.44) 88771 : cluster [ERR] 2.ac7 has 1 objects unfound and apparently lost
-------------------------------

After comparing the logs of the three OSDs at the time of the failure, I found that osd.32 had not yet recovered from its suicide at the time of the failure. The primary osd, osd.44, first carried out a full-object read CRC check and discovered that the locally calculated checksum value (0xebe9ec95) in the object header did not match the expected checksum value (0xffffffff). It then planned to retrieve this object data from osd.20 for recovery.
------------------
1697 2023-11-20 12:07:50.147 7f64322e1700 0 osd.44 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] async=[32] r=0 lpr=47041 pi=[46703,47041)/1 rops=1 crt=47163'155742025 lcod 47163'155742024 mlcod 47039'155739869 active+recovering+undersized+degraded+remapped mbc={2 55={(2+0)=1}}] build_push_op 2.ac7_head full-object read crc 0xebe9ec95 != expected 0xffffffff on 2:e357d41e:::200516ce993.0000002d:head
1698 2023-11-20 12:07:50.148 7f64322e1700 0 osd.44 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] async=[32] r=0 lpr=47041 pi=[46703,47041)/1 rops=1 crt=47163'155742025 lcod 47163'155742024 mlcod 47039'155739869 active+recovering+undersized+degraded+remapped mbc={2 55={(2+0)=1}}] prep_object_replica_pushes Error 5 on oid 2:e357d41e:::200516ce993.0000002d:head
1699 2023-11-20 12:07:50.148 7f64322e1700 0 osd.44 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] async=[32] r=0 lpr=47041 pi=[46703,47041)/1 rops=1 crt=47163'155742025 lcod 47163'155742024 mlcod 47039'155739869 active+recovering+undersized+degraded+remapped mbc={2 55={(1+0)=1}}] failed_push 2:e357d41e:::200516ce993.0000002d:head from shard 44, reps on 20 unfound? 0
1700 2023-11-20 12:07:50.148 7f64322e1700 -1 log_channel(cluster) log [ERR] : 2.ac7 missing primary copy of 2:e357d41e:::200516ce993.0000002d:head, will try copies on 20
1701 2023-11-20 12:07:50.157 7f64322e1700 0 osd.44 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] async=[32] r=0 lpr=47041 pi=[46703,47041)/1 rops=1 crt=47163'155742025 lcod 47163'155742024 mlcod 47039'155739869 active+recovering+undersized+degraded+remapped m=1 u= 1 mbc={255={}}] failed_push adding 2:e357d41e:::200516ce993.0000002d:head to shard 20's missing set too
1702 2023-11-20 12:07:50.157 7f64322e1700 0 osd.44 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] async=[32] r=0 lpr=47041 pi=[46703,47041)/1 rops=1 crt=47163'155742025 lcod 47163'155742024 mlcod 47039'155739869 active+recovering+undersized+degraded+remapped m=1 u= 1 mbc={255={}}] failed_push 2:e357d41e:::200516ce993.0000002d:head from shard 20, reps on unfound? 1
1703 2023-11-20 12:07:51.101 7f642e2d9700 -1 log_channel(cluster) log [ERR] : 2.ac7 has 1 objects unfound and apparently lost
---------------------------

"After receiving the request, osd.20 also performed a full-object read. Upon reading, it conducted a CRC check and found that the locally calculated checksum value (0xebe9ec95) did not match the expected checksum value (0xffffffff), resulting in an 'object unfound' situation.
------------------------
2389 2023-11-20 12:07:50.148 7fe95d162700 0 osd.20 pg_epoch: 47175 pg[2.ac7( v 47163'155742025 (47035'155738947,47163'155742025] local-lis/les=47041/47042 n=6326 ec=261/261 lis/c 47041/46703 les/c/f 47042/46704/ 0 47040/47041/36944) [44,20,32]/[44,20] r=1 lpr=47041 pi=[46703,47041)/1 luod=0'0 lua=47039'155740414 crt=47163'155742025 lcod 47163'155742024 active+remapped mbc={}] build_push_op 2.ac7_head full-object rea d crc 0xebe9ec95 != expected 0xffffffff on 2:e357d41e:::200516ce993.0000002d:head
2390 2023-11-20 12:15:58.584 7fe95d162700 0 log_channel(cluster) log [DBG] : 2.9a7 deep-scrub starts
2391 2023-11-20 12:17:12.192 7fe95d162700 0 log_channel(cluster) log [DBG] : 2.9a7 deep-scrub ok
2392 2023-11-20 12:17:44.167 7fe95d162700 0 osd.20 pg_epoch: 47312 pg[2.ac7( v 47310'155747427 (47310'155744347,47310'155747427] local-lis/les=47311/47312 n=6330 ec=261/261 lis/c 47311/46703 les/c/f 47312/46704/ 0 47311/47311/36944) [44,20] r=1 lpr=47311 pi=[46703,47311)/1 luod=0'0 crt=47310'155747427 lcod 47310'155747426 active mbc={}] build_push_op 2.ac7_head full-object read crc 0xebe9ec95 != expected 0xffffffff on 2:e357d41e:::200516ce993.0000002d:head
------------------------

I found that the CRC values calculated from the reads by both OSDs are identical. However, the expected checksum value, oi.data_digest, seems to have experienced an anomaly, resulting in the unusual value of 0xffffffff. This situation appears to be very similar to the issue you described. Do you have any idea why oi.data_digest would show this strange value of 0xffffffff?

bump up

TODO: final review.

The fix goes into QA.

In QA.

Bump up.

Bump up.

New changes in the PR (a unit test fix). Need to reQA.