Bug #42889
closed
[msgr] continuous CRC mismatch under Ubuntu 18.04 causing spinning connection resets
Added by Jason Dillaman over 4 years ago.
Updated over 4 years ago.
Description
http://qa-proxy.ceph.com/teuthology/jdillaman-2019-11-19_13:54:56-rbd-wip-42598-distro-basic-smithi/4523756/teuthology.log
I've looked back against historical RBD suite runs on the master branch and for at least the past few months the "dynamic_features_no_cache" test has been regularly failing only under the Ubuntu 18 distro. I caught it in the act in the run above and increased the objecter and ms logs [1] to see that it was spinning on connect/resend/disconnect against OSD 7. I then increased the ms logs for OSD 7 [2] to find it complaining of a CRC mismatch upon the receipt of the first message:
2019-11-19T21:28:42.638+0000 7f7e444c6700 20 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0).handle_read_frame_epilogue_main r=0
2019-11-19T21:28:42.638+0000 7f7e444c6700 20 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check success: expected_crc=1380803411 calculated_crc=1380803411
2019-11-19T21:28:42.638+0000 7f7e444c6700 20 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check success: expected_crc=354238021 calculated_crc=354238021
2019-11-19T21:28:42.638+0000 7f7e444c6700 20 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check success: expected_crc=4294967295 calculated_crc=4294967295
2019-11-19T21:28:42.638+0000 7f7e444c6700 5 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0).handle_read_frame_epilogue_main message integrity check failed: expected_crc=1969711020 calculated_crc=3757546011
2019-11-19T21:28:42.638+0000 7f7e444c6700 10 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0)._fault
2019-11-19T21:28:42.638+0000 7f7e444c6700 2 --2- [v2:172.21.15.25:6826/11408,v1:172.21.15.25:6827/11408] >> 172.21.15.87:0/402634445 conn(0x55bb6e815b00 0x55bb74086b00 crc :-1 s=THROTTLE_DONE pgs=10769522 cs=0 l=1 rx=0 tx=0)._fault on lossy channel, failing
[1] http://qa-proxy.ceph.com/teuthology/jdillaman-2019-11-19_13:54:56-rbd-wip-42598-distro-basic-smithi/4523756/remote/smithi087/log/ceph-client.0.10972.log.gz
[2] http://qa-proxy.ceph.com/teuthology/jdillaman-2019-11-19_13:54:56-rbd-wip-42598-distro-basic-smithi/4523756/remote/smithi025/log/ceph-osd.7.log.gz
- Status changed from 12 to In Progress
- Assignee set to Jason Dillaman
I traced the issue to the fact that we no longer copy IO buffers on writes (when the cache is disabled). The QEMU environment uses virtio-blk so the guest OS memory is directly mapped back through QEMU and provided to librbd. If the guest OS changes the memory after the IO has been submitted but before it has been acknowledged, the CRC will change but librados/Objecter will only compute the CRC one time. This causes the CRC mismatch spin between the client sending the old CRC and the OSD computing the new CRC and noticing the mismatch.
I added some extra logging to librbd/Objecter to dump the IO contents and CRCs:
2019-11-21T05:34:45.773+0000 7f36b3481640 0 librbd::io::ImageRequestWQ: 0x55cc88406e10 aio_write: aio_completion=0x55ccb1410600 2625536~4096 crc=1201768886 data=
00000000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
00000090 ff 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
000000a0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000900 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
000009b0 ff ff 0f 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
000009c0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000a00 00 e0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00000a10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000a80 00 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |.`..............|
00000a90 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000b00 00 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |. ..............|
00000b10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000ff0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00001000
2019-11-21T05:34:45.777+0000 7f36277fe700 0 client.4617.objecter CRC CORRUPTION: original_crc=1201768886, new_crc=3360471729, data=
00000000 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
00000090 ff 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
000000a0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000900 ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff ff |................|
*
000009c0 ff ff ff ff ff ff 3f 00 00 00 00 00 00 00 00 00 |......?.........|
000009d0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000a00 00 e0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00000a10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000a80 00 60 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |.`..............|
00000a90 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000b00 00 20 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |. ..............|
00000b10 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
*
00000ff0 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 |................|
00001000
This test that repeatedly fails is xfstest 049 which involves putting an XFS filesystem on a loop file on top of an XFS filesystem -- on Ubuntu 12. I am going to retest with a more modern Ubuntu to see if it's still changing the IO post submission. Perhaps librbd should instruct librados/Objector to recompute data CRCs upon session fault -- or I need to remove support for zero-copy writes.
- Project changed from RADOS to rbd
- Project changed from rbd to RADOS
- Status changed from In Progress to Fix Under Review
- Severity deleted (
3 - minor)
- Pull request ID set to 31794
- Project changed from RADOS to rbd
- Status changed from Fix Under Review to Resolved
Also available in: Atom
PDF