Project

General

Profile

Actions
Copy link

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.

Status:
Resolved
Priority:
High
Assignee:
Jason Dillaman
Target version:
-
% Done:

0%

Source:
Tags:
Backport:
Regression:
No
Severity:
Reviewed:
Affected Versions:
ceph-qa-suite:
Pull request ID:
31794
Crash signature (v1):
Crash signature (v2):

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

Actions
Copy link
 #1

Updated by Jason Dillaman over 4 years ago

  • Status changed from 12 to In Progress
  • Assignee set to Jason Dillaman
Actions
Copy link
 #2

Updated by Jason Dillaman over 4 years ago

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.

Actions
Copy link
 #3

Updated by Jason Dillaman over 4 years ago

  • Project changed from RADOS to rbd
Actions
Copy link
 #4

Updated by Jason Dillaman over 4 years ago

  • 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
Actions
Copy link
 #5

Updated by Jason Dillaman over 4 years ago

  • Project changed from RADOS to rbd
Actions
Copy link
 #6

Updated by Jason Dillaman over 4 years ago

  • Status changed from Fix Under Review to Resolved
Actions
Copy link

Also available in: Atom PDF