[LU-10683] write checksum errors

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.12.0, Lustre 2.10.5
• Affects Version/s: Lustre 2.10.3
• Environment: centos7, skylake, opa, zfs 0.7.6, lustre 2.10.3 + https://review.whamcloud.com/#/c/29992/. kernel nopti on servers, pti on clients, 3.10.0-693.17.1.el7.x86_64
• Severity: 3
• Assignee: Hongchao Zhang
• Reporter: SC Admin

Description

Hiya,

these appeared last night.
john100,101 are clients. arkle3,6 are OSS's. transom1 is running the fabric manager.

in light of the similar looking LU-9305 I thought I would create this ticket.
we run default (4M) rpcs on clients and servers. our OSTs are each 4 raidz3's in 1 zpool, and have recordsize=2M. 2 OSTs per OSS. 16 OSTs total.

I suppose it could be a OPA network glitch, but it affected 2 clients and 2 servers so that seems unlikely.

we have just moved from zfs 0.7.5 to zfs 0.7.6. we ran ior and mdtest after this change and they were fine. these errors occurred a couple of days after that.

Feb 19 23:45:12 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 54e81a18
Feb 19 23:45:12 john100 kernel: LNetError: 899:0:(lib-ptl.c:190:lnet_try_match_md()) Matching packet from 12345-192.168.44.33@o2ib44, match 1591386600741136 length 1048576 too big: 1048176 left, 1048176 allowed
Feb 19 23:45:12 arkle3 kernel: LNet: Using FMR for registration
Feb 19 23:45:12 arkle3 kernel: LustreError: 298612:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff881764648600
Feb 19 23:45:12 arkle3 kernel: LustreError: 298612:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff881764648600
Feb 19 23:45:12 arkle3 kernel: LustreError: 337237:0:(ldlm_lib.c:3242:target_bulk_io()) @@@ network error on bulk WRITE  req@ffff881687561450 x1591386600741136/t0(0) o4->8c8018f7-2e02-6c2b-cbcf-29133ecabf02@192.168.44.200@o2ib44:173/0 lens 608/448 e 0 to 0 dl 1519044318 ref 1 fl Interpret:/0/0 rc 0/0
Feb 19 23:45:12 arkle3 kernel: Lustre: dagg-OST0005: Bulk IO write error with 8c8018f7-2e02-6c2b-cbcf-29133ecabf02 (at 192.168.44.200@o2ib44), client will retry: rc = -110
Feb 19 23:45:12 arkle3 kernel: LNet: Skipped 1 previous similar message
Feb 19 23:45:12 john101 kernel: LNetError: 904:0:(lib-ptl.c:190:lnet_try_match_md()) Matching packet from 12345-192.168.44.36@o2ib44, match 1591895282655776 length 1048576 too big: 1048176 left, 1048176 allowed
Feb 19 23:45:12 arkle6 kernel: LustreError: 298397:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff8810cb714600
Feb 19 23:45:12 arkle6 kernel: LustreError: 298397:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff8810cb714600
Feb 19 23:45:12 arkle6 kernel: LustreError: 42356:0:(ldlm_lib.c:3242:target_bulk_io()) @@@ network error on bulk WRITE  req@ffff88276c3d5850 x1591895282655776/t0(0) o4->400cfa1c-7c7d-1d14-09ed-f6043574fd7c@192.168.44.201@o2ib44:173/0 lens 608/448 e 0 to 0 dl 1519044318 ref 1 fl Interpret:/0/0 rc 0/0
Feb 19 23:45:12 arkle6 kernel: Lustre: dagg-OST000b: Bulk IO write error with 400cfa1c-7c7d-1d14-09ed-f6043574fd7c (at 192.168.44.201@o2ib44), client will retry: rc = -110
Feb 19 23:45:12 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 54e81a18 (type 4), client csum now efde5b36
Feb 19 23:45:12 john100 kernel: LustreError: 924:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11  req@ffff880e7a9b4e00 x1591386600740944/t197580821951(197580821951) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044319 ref 2 fl Interpret:RM/0/0 rc 0/0
Feb 19 23:45:13 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum df7fda9d
Feb 19 23:45:13 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum df7fda9d (type 4), client csum now efde5b36
Feb 19 23:45:13 john100 kernel: LustreError: 911:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11  req@ffff8807492fe300 x1591386600747696/t197580821955(197580821955) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044320 ref 2 fl Interpret:RM/0/0 rc 0/0
Feb 19 23:45:15 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 87da008a
Feb 19 23:45:15 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 87da008a (type 4), client csum now efde5b36
Feb 19 23:45:15 john100 kernel: LustreError: 910:0:(osc_request.c:1611:osc_brw_redo_request()) @@@ redo for recoverable error -11  req@ffff880eb3d51b00 x1591386600751360/t197580821956(197580821956) o4->dagg-OST0005-osc-ffff88015a1ad800@192.168.44.33@o2ib44:6/4 lens 608/416 e 0 to 0 dl 1519044322 ref 2 fl Interpret:RM/0/0 rc 0/0
Feb 19 23:45:18 arkle3 kernel: LustreError: 168-f: dagg-OST0005: BAD WRITE CHECKSUM: from 12345-192.168.44.200@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111]: client csum efde5b36, server csum 1cc7a793
Feb 19 23:45:18 john100 kernel: LustreError: 132-0: dagg-OST0005-osc-ffff88015a1ad800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.44.33@o2ib44 inode [0x20000c02e:0x9ef:0x0] object 0x0:2683981 extent [331258364-335450111], original client csum efde5b36 (type 4), server csum 1cc7a793 (type 4), client csum now efde5b36

full log attached.
there were hung and unkillable user processes on the 2 clients afterwards. a reboot of the 2 clients has cleared up the looping messages of the type shown below.

Feb 20 14:28:15 arkle6 kernel: LustreError: 298395:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff882e25ef2c00
Feb 20 14:28:19 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff88176544be00
Feb 20 14:28:19 arkle3 kernel: LustreError: 298611:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff8814072e0200
Feb 20 14:28:19 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff88176544be00
Feb 20 14:28:19 arkle3 kernel: LustreError: 298611:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff8814072e0200
Feb 20 14:28:47 arkle6 kernel: LustreError: 298394:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff882e25ef3800
Feb 20 14:28:47 arkle6 kernel: LustreError: 298394:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff882e25ef3800
Feb 20 14:28:51 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff881615f0f000
Feb 20 14:28:51 arkle3 kernel: LustreError: 298610:0:(events.c:449:server_bulk_callback()) event type 5, status -61, desc ffff880be3931c00
Feb 20 14:28:51 arkle3 kernel: LustreError: 298609:0:(events.c:449:server_bulk_callback()) event type 3, status -61, desc ffff881615f0f000

cheers,
robin

Issue Links

• is related to: LU-11663 corrupt data after page-unaligned write with zfs backend lustre 2.10
• is related to: LU-11093 clients hang when over quota

Comments

[Gerrit Updater]

Alex Zhuravlev ([e-mail]) uploaded a new patch: https://review.whamcloud.com/33741
Subject: Revert "LU-10683 osd_zfs: set offset in page correctly"
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 3c3bbb07d12e327307fdea46aa48f22d50faf947

[Gerrit Updater]

Alex Zhuravlev ([e-mail]) uploaded a new patch: https://review.whamcloud.com/33728
Subject: Revert "LU-10683 osd_zfs: set offset in page correctly"
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: a95e7e398ee411a14c3d67072fbea273832e0957

[Gerrit Updater]

John L. Hammond ([e-mail]) merged in patch https://review.whamcloud.com/32899/
Subject: LU-10683 osd_zfs: set offset in page correctly
Project: fs/lustre-release
Branch: b2_10
Current Patch Set:
Commit: 686a73ea9467c53d261cf12d0802bb1332d50f4a

[Gerrit Updater]

Minh Diep ([e-mail]) uploaded a new patch: https://review.whamcloud.com/32899
Subject: LU-10683 osd_zfs: set offset in page correctly
Project: fs/lustre-release
Branch: b2_10
Current Patch Set: 1
Commit: 1484662e0213007bfa5b7b68f02df77719a1a6d7

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/32788/
Subject: LU-10683 osd_zfs: set offset in page correctly
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 83cb17031913ba2f33a5b67219a03c5605f48f27

[Gerrit Updater]

Hongchao Zhang ([e-mail]) uploaded a new patch: https://review.whamcloud.com/32788
Subject: LU-10683 osd_zfs: set offset in page correctly
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 1fb85e7eba6823b5822f7298c7fa648770239635

[Andreas Dilger]

Correct. The client will resend on checksum failures up to 10 times by default (controlled by osc.*.resend_count).

That the checksum at the client is always the same implies that the data is also the same (e.g. all zero). That it is different on the server each time implies it is being changed after the client has computed the checksum (e.g. in client RAM, over the network, or in OSS RAM). If you are using mmap() on files or O_DIRECT with another thread modifying the pages it is possible to see such corruption, but Lustre can't do anything about it (short of copying the data, which is highly undesirable).

[SC Admin]

from reading the lustre manual it sounds like these checksum events are re-tried after they are detected, so the users might be seeing no effect from them.
is that correct?

cheers,
robin

[Hongchao Zhang]

As per the logs, the checksum is a little strange at client side

[3111837064-3112361351]: client csum c253e960, server csum 5e6e4da8
00000020:02020000:15.0:1523986236.833762:0:10678:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3186813384-3187337671]: client csum c253e960, server csum a42a5590
00000020:02020000:1.0:1523986236.845204:0:285172:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3069890888-3070415175]: client csum c253e960, server csum fc43f2ee
00000020:02020000:17.0:1523986236.845219:0:298862:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3128614280-3129138567]: client csum c253e960, server csum 976d257c
00000020:02020000:5.0:1523986236.845231:0:287464:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3095056712-3095580999]: client csum c253e960, server csum 1747b303
00000020:02020000:7.0:1523986236.845411:0:287463:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3061502280-3062026567]: client csum c253e960, server csum 1c6d4fd9
00000020:02020000:9.0:1523986236.845578:0:134229:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3036333320-3036857607]: client csum c253e960, server csum 4b320be5
00000020:02020000:15.0:1523986236.845877:0:287086:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3027420424-3027944711]: client csum c253e960, server csum d537dae0
00000020:02020000:1.0:1523986236.846009:0:34879:0:(tgt_handler.c:2112:tgt_warn_on_cksum()) 168-f: dagg-OST0004: BAD WRITE CHECKSUM: from 12345-192.168.44.170@o2ib44 inode [0x280022737:0x5b:0x0] object 0x540000400:8286655 extent [3102921032-3103445319]: client csum c253e960, server csum 50418907

the checksum of different extent for the same file (0x280022737:0x5b:0x0) is the same from the client side (all are "c253e960"),
but it is different at server side.

I'll look at it more deeply to find out what cause it.

[SC Admin]

so far it looks like this group was NOT over quota, but was again using parallel hdf5 writes.

the 4 files in question apparently look ok to them (ie. not obviously corrupted).

cheers,
robin