[LU-7152] sanity-hsm test_24a:FAIL: restore changed ctime from 1442224769 to 1442224774

• Status: Resolved
• Project: Lustre
• Affects Version/s: Lustre 2.8.0, Lustre 2.9.0
• Fix Version/s: Lustre 2.9.0
• Type: Bug
• Priority: Major
• Reporter: Maloo
• Assignee: John Hammond
• Resolution: Fixed
• Severity: 3

Description

This issue was created by maloo for wangdi <[e-mail]>

This issue relates to the following test suite run: https://testing.hpdd.intel.com/test_sets/01ca7010-5adb-11e5-8250-5254006e85c2.

The sub-test test_24a failed with the following error:

restore changed ctime from 1442224769 to 1442224774

Updated after 4s: wanted 'SUCCEED' got 'SUCCEED'
 sanity-hsm test_24a: @@@@@@ FAIL: restore changed ctime from 1442224769 to 1442224774 
  Trace dump:
  = /usr/lib64/lustre/tests/test-framework.sh:4748:error_noexit()
  = /usr/lib64/lustre/tests/test-framework.sh:4779:error()
  = /usr/lib64/lustre/tests/sanity-hsm.sh:1885:test_24a()
  = /usr/lib64/lustre/tests/test-framework.sh:5026:run_one()
  = /usr/lib64/lustre/tests/test-framework.sh:5063:run_one_logged()
  = /usr/lib64/lustre/tests/test-framework.sh:4928:run_test()
  = /usr/lib64/lustre/tests/sanity-hsm.sh:1906:main()
Dumping lctl log to /logdir/test_logs/2015-09-14/lustre-reviews-el6_7-x86_64--review-zfs-part-1--1_8_1__34565__-69995637337060-051354/sanity-hsm.test_24a.*.1442224778.log
CMD: shadow-40vm3,shadow-40vm4,shadow-40vm5,shadow-40vm6.shadow.whamcloud.com /usr/sbin/lctl dk > /logdir/test_logs/2015-09-14/lustre-reviews-el6_7-x86_64--review-zfs-part-1--1_8_1__34565__-69995637337060-051354/sanity-hsm.test_24a.debug_log.\$(hostname -s).1442224778.log;
         dmesg > /logdir/test_logs/2015-09-14/lustre-reviews-el6_7-x86_64--review-zfs-part-1--1_8_1__34565__-69995637337060-051354/sanity-hsm.test_24a.dmesg.\$(hostname -s).1442224778.log
CMD: shadow-40vm5 pkill -INT -x lhsmtool_posix
CMD: shadow-40vm5 pgrep -x lhsmtool_posix

Comments

[Bob Glossman (Inactive)]

another on master:
https://testing.hpdd.intel.com/test_sets/95455c3e-69bc-11e5-9a21-5254006e85c2

seems to have started happening around 9/13. maybe something bad landed to master then.

[Bruno Faccini (Inactive)]

+1 at https://testing.hpdd.intel.com/test_sets/65b541f0-6d13-11e5-bf10-5254006e85c2
It is the 10th failure since Sept 13th. All with the same "restore changed ctime from X to Y" and always with Y=X + 4/5s.
Having a look to sanity-hsm/test_24a, looks like the post-restore test of a ctime diff :

[ $ctime0 -eq $ctime1 ] ||
             error "release changed ctime from $ctime0 to $ctime1"

does not agree with previous comment :

# Restore should not change atime or mtime and should not
# decrease ctime.

So, is ctime expected to "only" grow after restore, and thus test must be changed accordingly, or not ?

[Bruno Faccini (Inactive)]

Finally, looks like the comment is outdated and that the ctime diff test has been changed by patch for LU-6213, which claims to allow for no ctime modification upon restore ...

[James Nunez (Inactive)]

Another hit with logs at https://testing.hpdd.intel.com/test_sets/65b541f0-6d13-11e5-bf10-5254006e85c2
2015-10-26 15:28:02 - https://testing.hpdd.intel.com/test_sets/908346de-7bff-11e5-88cf-5254006e85c2
2015-11-20 09:28:40 - https://testing.hpdd.intel.com/test_sets/1bc69868-8f74-11e5-802f-5254006e85c2
2015-11-20 19:37:45 - https://testing.hpdd.intel.com/test_sets/98e07d06-8fc8-11e5-8d18-5254006e85c2
2015-12-07 11:25:01 - https://testing.hpdd.intel.com/test_sets/1bb71ca2-9ce0-11e5-9ee2-5254006e85c2

[Bruno Faccini (Inactive)]

+1 in master at https://testing.hpdd.intel.com/test_sessions/bf93dd10-9146-11e5-ad50-5254006e85c2

[Saurabh Tandan (Inactive)]

master, build# 3264, 2.7.64 tag
Regression:EL7.1 Server/EL6.7 Client
https://testing.hpdd.intel.com/test_sets/6b720f64-9f0a-11e5-8d81-5254006e85c2

[Saurabh Tandan (Inactive)]

Another instance forEL7.1 Server/EL7.1 Client - ZFS
Master, build# 3264
test_24a and test_56

Update not seen after 200s: wanted 'SUCCEED' got ''

https://testing.hpdd.intel.com/test_sets/3688a1f0-a135-11e5-83b8-5254006e85c2

[James Nunez (Inactive)]

More failures on master:
https://testing.hpdd.intel.com/test_sets/776f3788-aec8-11e5-bf32-5254006e85c2
2016-01-04 16:10:42 - https://testing.hpdd.intel.com/test_sets/763d327c-b308-11e5-8114-5254006e85c2
2016-02-21 21:02:28 - https://testing.hpdd.intel.com/test_sets/cd311532-d8fe-11e5-83e2-5254006e85c2

[Saurabh Tandan (Inactive)]

Another failure for master : Tag 2.7.66 FULL - EL7.1 Server/SLES11 SP3 Client, build# 3314
https://testing.hpdd.intel.com/test_sets/94600ac4-ca7b-11e5-9609-5254006e85c2

[Saurabh Tandan (Inactive)]

Another instance found for Full tag 2.7.66 -EL7.1 Server/SLES11 SP3 Client, build# 3314
https://testing.hpdd.intel.com/test_sets/94600ac4-ca7b-11e5-9609-5254006e85c2

[Richard Henwood (Inactive)]

Another instance on Master: 2.8.50-20-ga3e6b14

https://testing.hpdd.intel.com/test_sessions/6ce21e0c-e541-11e5-b659-5254006e85c2

[Bob Glossman (Inactive)]

another on master:
https://testing.hpdd.intel.com/test_sets/49113ebc-fc58-11e5-9791-5254006e85c2

[Gerrit Updater]

John L. Hammond ([e-mail]) uploaded a new patch: http://review.whamcloud.com/19441
Subject: LU-7152 hsm: sync volatile file before setting times
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 49f06d5303807081345e8db8fbb9cd5ec960bf5c

[Bob Glossman (Inactive)]

another on b2_8:
https://testing.hpdd.intel.com/test_sets/56841322-fdb5-11e5-8750-5254006e85c2

[Richard Henwood (Inactive)]

another example on Master, while running review-zfs-part-1:

https://testing.hpdd.intel.com/sub_tests/089cd9b2-0a14-11e6-b5f1-5254006e85c2

[Gerrit Updater]

Oleg Drokin ([e-mail]) merged in patch http://review.whamcloud.com/19441/
Subject: LU-7152 hsm: sync volatile file before setting times
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: 048fca4f9f227f57cc353d247b9873b54d12fb88

[Peter Jones]

Landed for 2.9