[LU-12766] sanity-quota test 3 fails with 'write success, but expect EDQUOT'

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.13.0, Lustre 2.14.0, Lustre 2.12.4
• Fix Version/s: Lustre 2.15.0
• Type: Bug
• Priority: Minor
• Reporter: James Nunez (Inactive)
• Assignee: Wang Shilong (Inactive)
• Resolution: Fixed

Description

sanity-quota test_3 fails with 'write success, but expect EDQUOT', but looking at the client test_log we see

Total allocated inode limit: 0, total allocated block limit: 0
pid 1000 is using default file quota setting
Files for project (1000):
lfs: failed for '/mnt/lustre': Too many levels of symbolic links
 sanity-quota test_3: @@@@@@ FAIL: write success, but expect EDQUOT 
  Trace dump:
  = /usr/lib64/lustre/tests/test-framework.sh:6115:error()
  = /usr/lib64/lustre/tests/sanity-quota.sh:152:quota_error()
  = /usr/lib64/lustre/tests/sanity-quota.sh:771:test_block_soft()
  = /usr/lib64/lustre/tests/sanity-quota.sh:827:test_3()

There is no additional errors or indication of a problem in any of the console logs.

We’ve only seen sanity-quota test 3 fail with this error and with the lfs error:
https://testing.whamcloud.com/test_sets/7a25bb86-d6ed-11e9-a2b6-52540065bddc

We've seen sanity-quota test 3 fail with the same "write success, but expect EDQUOT " error, but the test_log does not have the lfs error. The logs have a different failure:

Total allocated inode limit: 0, total allocated block limit: 0
Some errors happened when getting quota info. Some devices may be not working or deactivated. The data in "[]" is inaccurate.
Files for project (1000):
 sanity-quota test_3: @@@@@@ FAIL: write success, but expect EDQUOT 
  Trace dump:
  = /usr/lib64/lustre/tests/test-framework.sh:6114:error()
  = /usr/lib64/lustre/tests/sanity-quota.sh:152:quota_error()
  = /usr/lib64/lustre/tests/sanity-quota.sh:734:test_block_soft()
  = /usr/lib64/lustre/tests/sanity-quota.sh:784:test_3()

Logs for these errors are at
https://testing.whamcloud.com/test_sets/43331474-b5b5-11e9-a1bd-52540065bddc
https://testing.whamcloud.com/test_sets/5f2b2d6c-bffe-11e9-98c8-52540065bddc

Issue Links

• is related to: LU-12787 sanity-quota: test 3 failure "write s...
• is related to: LU-14279 sanity-quota test_3b: write success, ...

Comments

[Alexander Zarochentsev]

I filed LU-12787 for those failures:

> https://testing.whamcloud.com/test_sets/43331474-b5b5-11e9-a1bd-52540065bddc
> https://testing.whamcloud.com/test_sets/5f2b2d6c-bffe-11e9-98c8-52540065bddc

[Bruno Faccini (Inactive)]

+1 on master @https://testing.whamcloud.com/test_sessions/431dfbf0-778f-46c2-84d5-e61058e669d6

[Andreas Dilger]

I see in the test output for one of these failures:

https://testing.whamcloud.com/test_sets/0f515d40-3b53-11ea-80b4-52540065bddc

Sleep through grace
sanity-quota.sh: line 357: let: 4m55: value too great for base (error token is "4m55")
...sleep 4m55 seconds
sleep: invalid time interval '4m55'

[Andreas Dilger]

In a recent failure this is more interesting;

https://testing.whamcloud.com/test_sets/e5ffdc29-ca05-4fa2-8c9a-c9d2e2da3946

Block grace time: 1w; Inode grace time: 1w
:
Sleep through grace ...
...sleep 21305 seconds

which is 255s less than 6h. From the code:

        case $flavour in
                block)
                        time=$(lfs quota -$qtype $qarg $parg $DIR|
                                   awk 'NR == 3 { print $5 }'| sed 's/s$//')
                        ;;
                file)
                        time=$(lfs quota -$qtype $qarg $DIR|
                                   awk 'NR == 3 { print $9 }'| sed 's/s$//')
                        ;;
         esac

        [[ $time == *m* ]] && time=${time//m/} && time=$((time*60));
        [[ $time == *h* ]] && time=${time//h/} && time=$((time*60*60));
        [[ $time == *d* ]] && time=${time//d/} && time=$((time*24*60*60));
        [[ $time == *w* ]] && time=${time//w/} && time=$((time*7*24*60*60));

                let time+=$extrasleep
                echo "...sleep $time seconds"
                sleep $time

The wdhm handling was added in patch https://review.whamcloud.com/37327 "LU-13174 tests: sanity-quota to convert minutes into seconds", but I don't think there is a bug in the time conversion code. It is more likely that the bug exists in the extraction of the timestamp itself? It is strange that the output looks like "Block grace time: 1w; Inode grace time: 1w" but the parsing line is looking at fields "$5" and "$9" when the grace time looks like it is in "$4" and "$8"?

[Gerrit Updater]

Wang Shilong ([e-mail]) uploaded a new patch: https://review.whamcloud.com/41259
Subject: LU-12766 test: convert time to seconds properly
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 15797ddcf4b0a30398c11bac2588047619b5ad31

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch https://review.whamcloud.com/41259/
Subject: LU-12766 test: convert time to seconds properly
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 1a2b381616b372efb5e386ef5fff3aa2f76873a4

[Peter Jones]

Landed for 2.15