[LU-8062] recovery-small test_115b: @@@@@@ FAIL: dd success

• Type: Bug
• Resolution: Fixed
• Priority: Major
• Fix Version/s: Lustre 2.10.1, Lustre 2.11.0
• Affects Version/s: Lustre 2.8.0, Lustre 2.9.0, Lustre 2.10.0

Epic/Theme

test

• Severity: 3
• Assignee: WC Triage
• Reporter: Bhagyesh Dudhediya (Inactive)

Description

== recovery-small test 115b: write: late REQ MDunlink and no bulk == 21:12:09 (1461384729)
Filesystem 1K-blocks Used Available Use% Mounted on
onyx-38vm7@tcp:/lustre
74157152 309236 69890576 1% /mnt/lustre
fail_loc=0x8000051b
fail_val=4
Filesystem 1K-blocks Used Available Use% Mounted on
onyx-38vm7@tcp:/lustre
74157152 309236 69890576 1% /mnt/lustre
CMD: onyx-38vm8 lctl set_param fail_val=0 fail_loc=0x80000215
fail_val=0
fail_loc=0x80000215
1+0 records in
1+0 records out
4096 bytes (4.1 kB) copied, 2.13538 s, 1.9 kB/s
recovery-small test_115b: @@@@@@ FAIL: dd success
Trace dump:
= /usr/lib64/lustre/tests/test-framework.sh:4764:error()
= /usr/lib64/lustre/tests/recovery-small.sh:2161:test_115_write()
= /usr/lib64/lustre/tests/recovery-small.sh:2181:test_115b()
= /usr/lib64/lustre/tests/test-framework.sh:5028:run_one()
= /usr/lib64/lustre/tests/test-framework.sh:5067:run_one_logged()
= /usr/lib64/lustre/tests/test-framework.sh:4914:run_test()
= /usr/lib64/lustre/tests/recovery-small.sh:2183:main()
Dumping lctl log to /logdir/test_logs/2016-04-22/lustre-reviews-el6_7-x86_64-review-dne-part-1-1_6_1_38438_-70130481106820-100010/recovery-small.test_115b.*.1461384732.log

Issue Links

• is duplicated by: LU-8061 recovery-small: short description of the failure
• is related to: LU-8067 sanityn test_31a: read dd: reading `/mnt/lustre2/d31a.sanityn/f31a.sanityn': Input/output error 0 blocks, must be
• is related to: LU-7434 lost bulk leads to a hang

Comments

[Niu Yawei (Inactive)]

https://testing.hpdd.intel.com/test_sets/5766e584-41c7-11e6-bbf5-5254006e85c2

The failure reoccurred in master review.

[Vitaly Fertman]

Andreas Dilger added a comment - 8 hours ago - edited
Closing this bug, since the problematic patch was reverted, and LU-7434 is still open to track the re-landing of the fixed patch.

actually, the fix was submitted above. please re-land the original patch with the fix above.

[parinay v kondekar (Inactive)]

s/LU-7343/LU-7434/
(correcting the typo)

[Andreas Dilger]

Closing this bug, since the problematic patch was reverted, and LU-7434 is still open to track the re-landing of the fixed patch.

[Richard Henwood (Inactive)]

Another occurrence of this failure, on Master, on review-dne-part-1

https://testing.hpdd.intel.com/sub_tests/637e1824-0a36-11e6-855a-5254006e85c2

[Gerrit Updater]

Bhagyesh Dudhediya ([e-mail]) uploaded a new patch: http://review.whamcloud.com/19758
Subject: LU-8062 test: fix fail_val in recovery-small/115b
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: f5eb98a57ed6cfd36321cb2e7e6e2ac2eb309528

[Andreas Dilger]

Vitaly, could you please take a look at this? Is there a simple fix, or should the patch be reverted to give you more time to look into it?

[Andreas Dilger]

It appears the root cause of these failures is the following patch, which added test_115b and landed on 2016-04-21:

commit 55f8520817a31dabf19fe0a8ac2492b85d039c38
Author:     Vitaly Fertman <[e-mail]>
CommitDate: Thu Apr 21 02:27:54 2016 +0000

    LU-7434 ptlrpc: lost bulk leads to a hang
    
    The reverse order of request_out_callback() and reply_in_callback()
    puts the RPC into UNREGISTERING state, which is waiting for RPC &
    bulk md unlink, whereas only RPC md unlink has been called so far.
    If bulk is lost, even expired_set does not check for UNREGISTERING
    state.
    
    The same for write if server returns an error.
    
    This phase is ambiguous, split to UNREG_RPC and UNREG_BULK.
    
    Signed-off-by: Vitaly Fertman <[e-mail]>
    Reviewed-on: http://review.whamcloud.com/17221

[Andreas Dilger]

This appears to be the top failing test on master in the past week, so increasing the priority.

I checked a couple of the failing patches, and there doesn't seem to be any common source of the failure (i.e. it isn't caused by a bad patch that is repeatedly being retested) and some of the failures are on master. The few that I looked at more closely are based on commit 0f62ba942939c26edf07176d2eb082d38e95caec:

CommitDate: Thu Apr 21 02:28:41 2016 +0000

    LU-8024 kernel: kernel update [SLES12 SP1 3.12.57-60.35]
    
    Update target and kernel_config files for new version
    
    Test-Parameters: clientdistro=sles12 testgroup=review-ldiskfs \
      mdsdistro=sles12 ossdistro=sles12 mdsfilesystemtype=ldiskfs \
      mdtfilesystemtype=ldiskfs ostfilesystemtype=ldiskfs
    
    Signed-off-by: Bob Glossman <[e-mail]>
    Change-Id: Ic9f33c4877f93249b37726d8ad60c98ee624f719
    Reviewed-on: http://review.whamcloud.com/19593

Which isn't to imply that this is the root cause of the problem (many of the test failures are on RHEL6.7, not SLES at all), but rather that this is the point where the other patches are failing this test, so the problematic commit is somewhere before this point.

[Andreas Dilger]

It looks like this failure has only been happening since 2016-04-21:
https://testing.hpdd.intel.com/sub_tests/b09ba16c-07d9-11e6-9b34-5254006e85c2

so it is likely related to some patch that landed shortly before that time.

[Bhagyesh Dudhediya (Inactive)]

In recovery-small/test_115b :
An IO RPC is infected with some fail_loc value so that it would wait for some completion (req/reply lnet buffers unlink or even bulk unlink) for a while.
Also a delay is injected before it is send.
The delay gives some time to inject another fail_loc for the server side this time, the server will return an error in this particular case, whereas the 1st fail_loc is injected accurately, there is no more IO RPCs at this time, the problem with the test is that 2nd fail_loc is too generic, whatever RPC would be handled, it returns an error on it. it means if some other RPC appears just before our IO RPC, it gets an error but our IO does not.
On the OST side logs following lines are seen indicating that fail_loc which should ne caught in IO path is actually caught by the statfs thread:

00002000:00000020:1.0:1461384731.470636:0:7993:0:(ofd_obd.c:842:ofd_statfs()) 2317411 blocks: 2307535 free, 2183803 avail; 618944 objects: 618375 free; state 0
00002000:02000000:1.0:1461384731.470641:0:7993:0:(libcfs_fail.h:96:cfs_fail_check_set()) *** cfs_fail_loc=215, val=0***

i.e. statfs is in progress by thread 7993 and it catches 215 fail_loc.