[LU-10754] sanityn test 47b fails with 'create must fail'

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.11.0, Lustre 2.12.2
• Fix Version/s: Lustre 2.13.0
• Type: Bug
• Priority: Major
• Reporter: James Nunez (Inactive)
• Assignee: Patrick Farrell (Inactive)
• Resolution: Fixed
• Labels: dne, zfs
• Severity: 3

Description

sanityn test_47b fails for DNE/ZFS testing. From the client test_log, we see

== sanityn test 47b: pdirops: remote mkdir vs create ================================================= 09:50:51 (1519725051)
CMD: onyx-32vm9 lctl set_param fail_loc=0x80000145
fail_loc=0x80000145
 sanityn test_47b: @@@@@@ FAIL: create must fail 
lfs mkdir: error on LL_IOC_LMV_SETSTRIPE '/mnt/lustre/f47b.sanityn' (3): stripe already set
lfs setdirstripe: cannot create stripe dir '/mnt/lustre/f47b.sanityn': File exists

This test started failing on 2018-01-19.

The console and dmesg logs don’t have any more information in them for this failure than what is in the suite_log.

Logs for test sessions with this failure are at
https://testing.hpdd.intel.com/test_sets/b9932fbe-fd24-11e7-bd00-52540065bddc
https://testing.hpdd.intel.com/test_sets/316d208c-1bb4-11e8-a7cd-52540065bddc
https://testing.hpdd.intel.com/test_sets/5ce20dce-1905-11e8-a6ad-52540065bddc

Issue Links

• is duplicated by: LU-13097 sanityn test_47b: create must fail
• is related to: LU-12470 sanityn test_47b: create isn't blocked
• is related to: LU-2233 sanityn/40-46 takes ~800-900s

Comments

[Alex Zhuravlev]

https://testing.whamcloud.com/test_sessions/b9d6b421-a589-4a3c-8daa-a9e2e08e5b31

[Patrick Farrell (Inactive)]

https://testing.whamcloud.com/test_sessions/bc2f83f6-83cc-4baa-8854-25a3f29ecb0c

[Patrick Farrell (Inactive)]

So what I learned after looking at these logs for a bit is that the DNE2 protocol is complex and I don't understand it, but what I did learn is that we are hanging such that the lfs mkdir is not running until after the multiop has started:

—

$LFS mkdir -i 1 $DIR1/$tfile &
PID1=$!
sleep 1
multiop $DIR2/$tfile oO_CREAT:O_EXCL:c && error "create must fail"

—

The lfs mkdir hangs waiting on a lock (not the intended PDO lock, I think - much earlier...?).  The sequence of events is a bit beyond me right now, but it involves cancelling locks on MDT1, which are presumably held because of previous tests.  Somewhere in there, something gets stuck, and the lock cancellation does not complete (on MDT0) until after the create operation has started, hence the mkdir failing with EEXIST.

[Patrick Farrell (Inactive)]

I can't prove it, but I have a guess on this.

The lock it's waiting for was created by/during a previous test, and I can't prove it, but I think there's some uncommitted stuff under it that's getting sync'ed.  In that case, 'sleep 1' simply isn't long enough for that to happen due to our lack of the ZIL and the long commit intervals on ZFS (once per second).

 

I'm going to push a patch to change the sleeps to 2 seconds.

[Patrick Farrell (Inactive)]

Discussed with bzzz, he's going to take a look and see what we can do, maybe we can do better than just increasing the sleep.  (Which isn't 100% reliable, but we also want to avoid syncs...)

[Andreas Dilger]

What about just cancelling all of the MDC locks at the start of the test, so that we aren't waiting on that in the middle of the test? That avoids making the sleep to be long enough for the 1% case, without wasting time to make it too long for 99% of runs. We still need a small sleep due to fork/exec, but that can be sleep 0.2 or similar.

[Patrick Farrell (Inactive)]

That makes a lot more sense than my suggestion.

Andreas, has this failed recently?  I ignored it because I saw it a few times, then hadn't seen it since.

[Andreas Dilger]

PS: I post here because it seems like there has been an uptick in the frequency of test failures:

• 2019-05-10: 4 failures already today
• 2019-05-09: 4 failures the week ending on
• 2019-05-02: 2 failures that week
• 2019-04-25: 2 failures that week

There were a number of patches landed on 2019-05-08, so it is likely one of them is involved (possibly just increasing the size of the race window by making some piece of code/test slower.

[Patrick Farrell (Inactive)]

Presumably:

https://review.whamcloud.com/4392

Which modifies these

[Andreas Dilger]

It looks like the recent uptick in failures is caused by the landing on 2019-05-10 of patch https://review.whamcloud.com/4392 "LU-2233 tests: improve tests sanityn/40-47", which reduced the "sleep" time to 0.2s, which increased the probability of other lock
operations still being blocked when this test was run.

[Gerrit Updater]

Patrick Farrell ([e-mail]) uploaded a new patch: https://review.whamcloud.com/34848
Subject: LU-10754 tests: Clear mdc locks before tests
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 1a4b819075e2936ed9dc5d4b3600a7be37270c8a

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/34848/
Subject: LU-10754 tests: Clear mdc locks before tests
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 26a7abe812834663a6d42ba0d04606650c71cb9f

[Gerrit Updater]

Alex Zhuravlev ([e-mail]) uploaded a new patch: https://review.whamcloud.com/34853
Subject: LU-10754 debug: try to sleep for 1s
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 24860d1c1948a2a7ccec0be8eb1ea8ee78e63cb6

[James A Simmons]

This is causing about 1/3 of each test suite runs to fail.

[Gerrit Updater]

Andreas Dilger ([e-mail]) merged in patch https://review.whamcloud.com/34853/
Subject: LU-10754 tests: sanityn/47b to sleep for 1s
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 85ac0da36748311528aa7b89f62679f087b7445c

[Gerrit Updater]

Patrick Farrell ([e-mail]) uploaded a new patch: https://review.whamcloud.com/35399
Subject: LU-10754 tests: Debug full testing failure
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: c6779689cbcd658b600933425db1d5365b3a3337

[Patrick Farrell (Inactive)]

OK, figured it out:
https://review.whamcloud.com/#/c/4392/
breaks interop.

Wondering if we can just land it to b2_12?

[Andreas Dilger]

Wondering if we can just land it to b2_12?

If this patch is landed to b2_12, will it then cause interop testing problems for 2.12 vs. 2.10? Not that I'm totally against this, since we run far more testing on master than b2_12, but ideally we should just add a version interop check, or just skip this test for interop testing on b2_12 so that there aren't gratuitous errors that need to be looked at.

[Jian Yu]

The failure still occurred on master branch:
https://testing.whamcloud.com/test_sets/c376ce50-b86c-11e9-b753-52540065bddc
https://testing.whamcloud.com/test_sets/3e5c96d8-b7c6-11e9-b88c-52540065bddc
https://testing.whamcloud.com/test_sets/29aab538-b66a-11e9-b88c-52540065bddc

[Patrick Farrell (Inactive)]

yujian,

There are a number of bugs for this, unfortunately.  Here's the one we're using now, which has an unlanded fix: LU-12470

[Jian Yu]

Thank you, Patrick.