[#LU-387] Test failure on test suite mmp

[LU-387] Test failure on test suite mmp Created: 02/Jun/11 Updated: 11/Oct/11 Resolved: 15/Jul/11
Status:	Resolved
Project:	Lustre
Component/s:	None
Affects Version/s:	Lustre 2.1.0, Lustre 1.8.6
Fix Version/s:	Lustre 2.1.0, Lustre 1.8.7

Type:

Bug

Priority:

Minor

Reporter:

Maloo

Assignee:

Niu Yawei (Inactive)

Resolution:

Fixed

Votes:

Labels:

None

Attachments:

0001-LU-387-mmp.sh-test_9-failed.patch

diagnosis_v1.patch

mds-dmesg-2.log

mds-dmesg.log

mmp-1308230138.tar.bz2

mmp.test_9.test_log.client-15-ib.log

mmp_test9_fix.patch

Severity:

Rank (Obsolete):

4954

Description

This issue was created by maloo for sarah <sarah@whamcloud.com>

This issue relates to the following test suite run: https://maloo.whamcloud.com/test_sets/452782d2-8d47-11e0-aab9-52540025f9af.

Comments

Comment by Sarah Liu [ 02/Jun/11 ]

this one can be reproduced.

Comment by Niu Yawei (Inactive) [ 07/Jun/11 ]

Looks the e2fsck has already completed before we try to kill it, I suspect it's a test script problem, looking into the test_9, we can see we always sleep (2 * mmp_interval) before killing the e2fsck process, I'm afraid that the fsck might have been finished during this period, and I don't quite understand why we have to wait for (2 * mmp_interval).

Johann, could you take a look on this? Thanks in advance.

Comment by Peter Jones [ 07/Jun/11 ]

Niu

I understand from Johann that you have discussed this on Skype and now have a way forward on this issue so I am assigning it to you

Peter

Comment by Niu Yawei (Inactive) [ 08/Jun/11 ]

The e2fsck should last at least (2 * mmp_check_inteval), so I don't see why the script can't find e2fsck process when it trying to ternimate it.

Hi, Sarah
Could you apply this diagnostic patch to the test script and reproduce the bug? Please also collect the log/dmesg of MDS, which might be helpful. Thanks.

Comment by Sarah Liu [ 09/Jun/11 ]

with this patch, test 9 can pass. due to ~~LU-404~~, mmp cannot be run by auster and the result cannot be uploaded to Maloo. I will upload the log as attachment.

Comment by Niu Yawei (Inactive) [ 09/Jun/11 ]

This diagnostic patch just print more information in the test script, it should not affect the test result. From the output of this round of test, looks the mmp_check_interval is much shorter than the previous round, that could be the reason of why the bug wasn't triggered this time.

Hi, Sarah, was there any test environment being changed during those two round of tests? Could you try to figure out that if the bug is still reproducable? (then try to reproduce it with the diagnostic patch). Thank you in advance.

Comment by Peter Jones [ 09/Jun/11 ]

Sarah

There is a patch ready for LU404 now so perhaps trying with that will enable you to run the test with auster as before

Peter

Comment by Sarah Liu [ 09/Jun/11 ]

Niu,

Yes, the test environment changed a little bit. In the first run, there are three osts and two lustre clients; the second run, I uses two osts and only one lustre client. Today I run this test again on build #149 since the build with fix of ~~LU-404~~ cannot be successfully installed due to ~~LU-345~~. This time uses three osts and two clients, with your patch, it can be reproduced. Here is the link:

https://maloo.whamcloud.com/test_sets/cc1962fa-92e8-11e0-a0d3-525400

Also, please find the mds log in the attached.

Comment by Niu Yawei (Inactive) [ 09/Jun/11 ]

Hi, Sarah, looks the maloo link is broken?

Comment by Sarah Liu [ 10/Jun/11 ]

https://maloo.whamcloud.com/test_sets/cc1962fa-92e8-11e0-a0d3-52540025f9af

Comment by Niu Yawei (Inactive) [ 14/Jun/11 ]

Hi, Sarah

I adjust the diagnostic patch slightly, could you reproduce it with this patch again, thanks a lot.

Comment by Niu Yawei (Inactive) [ 14/Jun/11 ]

It's really nice that Yujian found a log with timestamp:

20:33:18:== mmp test 9: mount after aborted e2fsck ============================================================ 13:33:16 (1307824396)
20:33:18:Starting mds1: -o user_xattr,acl /dev/sdb /mnt/mds1
20:33:19:debug=0x33f0404
20:33:19:subsystem_debug=0xffb7e3ff
20:33:19:debug_mb=32
20:33:19:Started lustre-MDT0000
20:33:19:Starting ost1: /dev/sdb5 /mnt/ost1
20:33:20:debug=0x33f0404
20:33:20:subsystem_debug=0xffb7e3ff
20:33:20:debug_mb=32
20:33:20:Started lustre-OST0000
20:33:20:Stopping /mnt/mds1 (opts
20:33:26:Stopping /mnt/ost1 (opts
20:33:34:Running e2fsck on the device /dev/sdb on mds1...
20:33:35:fat-amd-4-ib: e2fsck 1.41.90.wc2 (14-May-2011)
20:33:46:Pass 1: Checking inodes, blocks, and sizes
20:33:46:Pass 2: Checking directory structure
20:33:46:Pass 3: Checking directory connectivity
20:33:46:Pass 4: Checking reference counts
20:33:46:Pass 5: Checking group summary information
20:33:46:lustre-MDT0000: 53/5000040 files (9.4% non-contiguous), 736124/2500000 blocks
20:33:47:/usr/lib64/lustre/tests/mmp.sh: line 560: kill: (13487) - No such process
20:33:47:Mounting /dev/sdb on mds1...
20:33:47:Starting mds1: -o user_xattr,acl /dev/sdb /mnt/mds1
20:33:48:debug=0x33f0404
20:33:48:subsystem_debug=0xffb7e3ff
20:33:48:debug_mb=32
20:33:48:Started lustre-MDT0000
20:33:49: mmp test_9: @@@@@@ FAIL: mount /dev/sdb on mds1 should fail

From the timestamp, we can see the e2fsck waited for (2 * mmp_check_interval + 1) = 11 seconds before setting EXT2_MMP_SEQ_FSCK and start fsck, however, the fsck finished in 1 (or less than 1) second! So it's quite possible that the e2fsck has completed before the test script trying to kill it. (The test script has to wait for (2 * mmp_check_interval) = 10 seconds before killing the e2fsck otherwise, EXT2_MMP_SEQ_FSCK might not be set).

The solution I can think out so far is that we should fill the filesystem with more inodes and blocks before the test_9, then the fsck duration will be enlarged. Andreas & Johann, what's you opinion? Thanks.

Comment by Andreas Dilger [ 14/Jun/11 ]

If e2fsck is run with the "-F" option it will flush the disk cache, so it should increase the test time somewhat due to extra disk seeks. I think the reason that this e2fsck is now running so quickly is because of ~~LU-255~~ enabling the "flex_bg" feature and allowing e2fsck to avoid a lot of seeking during the test. Also, Johann has reduced the wait interval for MMP so that the startup is faster.

Depending on the state of the filesystem when e2fsck is first run, I think this test may still be valid if the wait interval is only $((

{mdt,ost}

_mmp_check_interval + 4)) or so. If the initial state of the MMP block is "clean"
(MMP Sequence: 4283256144) then e2fsck will immediately modify the MMP block and only wait 2x mmp_check_interval, while if it is unclean it will wait 2x mmp_check_interval to see if there is another process changing it before modifying the MMP block. This could be determined inside the get_mmp_check_interval() function.

In any case, I don't think this bug is a blocker for the release, since it is a well-understood failure with the test script only, and does not implicate a problem with the MMP code itself (as we still see a wait interval of 2x the wait interval).

Comment by Niu Yawei (Inactive) [ 15/Jun/11 ]

Thanks for your comment, Andreas.

The "-F" option can only increase the time before e2fsck trying to change mmp block, seems it can't help much for this case.

If the initial state of MMP block is "clean", the e2fsck will:

1. set MMP block with a random seq;
2. wait for (2 * mmp_check_interval +1) seconds;
3. set MMP block with "fsck" seq;
4. run pass 1-5 check;
5. set MMP block with "clean" seq;

I think the purpose of this test is to see if ext3/4 mount can aware of running e2fsck by checking mmp seq = EXT2_MMP_SEQ_FSCK, which means the e2fsck must be killed during phase 4, otherwise, the test might fail. The problem is that it's hard for the test script to know exactly when the e2fsck is in phase 4 and ensure it's terminated in phase 4 by some way. I think the only way is to enlarge the duration of phase 4 (that might needs fill the filesystem with inodes/blocks), am I understanding right?

Anyway, let's try to create some inodes before testing to see if it works.

Comment by Niu Yawei (Inactive) [ 15/Jun/11 ]

Hi, Sarah
Could you apply this patch to the test script to see if it works?

Comment by Andreas Dilger [ 15/Jun/11 ]

Niu, the "-F" flag will flush all of the cache for the device, so any IO done during pass 1-5 will have to be loaded from disk instead of from cache... That said, if there aren't many files in the filesystem it may still complete too quickly, so creating files is one way to slow it down.

For landing this patch to git, if it fixes the problem, I would suggest creating the files in a subdirectory, like:

DIR=$MOUNT/d0.mmp
mkdir -p $DIR
chattr +T $DIR
createmany -d $DIR/d 100000

so that it spreads the files across the block groups and slows down access. Using "e2fsck -F" will still help.

Comment by Niu Yawei (Inactive) [ 15/Jun/11 ]

Thank you, Andreas. Yes, I was wrong on the "-F" option.

Comment by Niu Yawei (Inactive) [ 15/Jun/11 ]

Hi, Sarah, I updated the patch according to Andreas' comments, pleasee try this one. Thanks.

Comment by Sarah Liu [ 16/Jun/11 ]

with this patch, failed again, please find logs in the attached.

Comment by Niu Yawei (Inactive) [ 16/Jun/11 ]

Thank you, Sarah.

From the log, we can see the test failed for mounting OST device, seems fsck on OST device is still too fast. (I created 100000 objects, and enabled "-F" option, looks it's still not enough).

Actually, though the test for MDS device passed, it's not we expected, because the mount is not failed for MMP block checking, instead, the mount failed because the e2fsck is still running... So we are not sure if the "create dir" slow down fsck on MDS device.

================================================================================
Mounting /dev/sdb on mds1...
/usr/lib64/lustre/tests/test-framework.sh: line 267: 24499 Aborted run_e2fsck $MMP_MDS_FAILOVER $MMP_MDSDEV "-fyF"
Starting mds1: -o user_xattr,acl /dev/sdb /mnt/mds1
192.168.4.131: mount.lustre: mount /dev/sdb at /mnt/mds1 failed: Device or resource busy
mount -t lustre /dev/sdb /mnt/mds1
Start of /dev/sdb on mds1 failed 16
tune2fs 1.41.90.wc3 (28-May-2011)

Running e2fsck on the device /dev/sdc1 on ost1...
192.168.4.131: e2fsck 1.41.90.wc3 (28-May-2011)
192.168.4.131: e2fsck: MMP: device currently active while trying to open /dev/sdb

The superblock could not be read or does not describe a correct ext2
filesystem. If the device is valid and it really contains an ext2
filesystem (and not swap or ufs or something else), then the superblock
is corrupt, and you might try running e2fsck with an alternate superblock:
e2fsck -b 16416 <device>
==================================================================================

From above log, we can see we sent abort signal to e2fsck process, but it didn't terminate immediately (maybe the process is running in kernel mode at that time), then mount MDS device failed for -EBUSY because the e2fsck process is opening the device. (we expect the mount fail with -EINVAL, since the ext3/4_fill_super() should return -EINVAL when it found the MMP block is in 'fsck' state) Actually, it's hard to guarantee the e2fsck terminate in an exact time period by kill command (you know, signal isn't realtime), in another word, it's hard to make sure the e2fsck being killed during the phase 4(pass 1 - 5).

I checked some passed tests on maloo, looks they are all passed because of e2fsck not being killed, which means though the test can pass sometimes, but the results aren't valid.

Now I'm wondering if we should spend more effort on this test? IMHO, the test method isn't valid, could we just simply disable it for now? Andreas, what do you think about? Thanks.

Comment by Andreas Dilger [ 16/Jun/11 ]

I dislike disabling tests, because they very rarely get enabled again, which opens a hole for bugs to enter.

Note that I don't actually consider the test to be incorrect if the MDT or OST mount fails due to e2fsck still running, since this is still correctly checking that the EXT2_MMP_SEQ_FSCK is preventing the mount from ever succeeding (the server should print "fsck is running on the filesystem" to the kernel dmesg and fail mounting).

One possible way to ensure e2fsck is stopped before exiting is to use gdb to interrupt it at the start of pass1() or similar, after ext2fs_mmp_start() is run:

echo -e "break e2fsck_pass1\nrun -fy $MMP_MDSDEV\nquit" > $TMP/mds_gdb_cmds
gdb -batch -x $TMP/mds_gdb_cmds

This will interrupt e2fsck with mmp_seq = EXT2_MMP_SEQ_FSCK, and no need to use "sleep" or other random occurrences.

One possible problem is that both "gdb" and "e2fsprogs-debuginfo" packages need to be installed on the nodes running e2fsck, which may be a problem in some test environments.

Comment by Niu Yawei (Inactive) [ 16/Jun/11 ]

Hi, Andreas

If the test_9 is running on single client node, the mount will just return -EBUSY before checking the MMP block when e2fsck is running, so it's not EXT2_MMP_SEQ_FSCK is preventing the mount. If the test_9 is running on a pair of failover nodes (e2fsck on one node, mount on another one), the test is valid, however, it'll be exactly same as test_8.

I'll try the gdb way, thank you!

Comment by Andreas Dilger [ 16/Jun/11 ]

I was just working on the MMP tests for e2fsprogs before sending it upstream, and I found another way to set EXT2_MMP_SEQ_FSCK on the filesystem without needing gdb or e2fsprogs-debuginfo installed on the client:

# this will cause debugfs to create the /tmp/debugfs.mark file once it has
# passed the MMP startup, then continue reading input until it is killed
MARKFILE=$(mktemp)
{ echo "dump_inode <2> $MARKFILE"; cat /dev/zero; } | $DEBUGFS -w $TMPFILE &
while [ ! -e $MARKFILE ]; do
       sleep 1
done
rm -f $MARKFILE
killall -9 debugfs

This is not timing dependent, since debugfs will continue reading from /dev/zero until it is killed.

Comment by Jian Yu [ 17/Jun/11 ]

Lustre Branch: v1_8_6_RC2
Lustre Build: http://newbuild.whamcloud.com/job/lustre-b1_8/80/
e2fsprogs Build: http://newbuild.whamcloud.com/job/e2fsprogs-master/40/
Distro/Arch: RHEL6/x86_64(patchless client, in-kernel OFED, kernel version: 2.6.32-131.2.1.el6)
RHEL5/x86_64(server, OFED 1.5.3.1, kernel version: 2.6.18-238.12.1.el5_lustre)

MGS/MDS Nodes: client-10-ib(active), client-12-ib(passive)
                                 \  /
                            1 combined MGS/MDT

OSS Nodes:     fat-amd-1-ib(active), fat-amd-2-ib(active)
                                 \  /
                                 OST1 (active in fat-amd-1-ib)
                                 OST2 (active in fat-amd-2-ib)
                                 OST3 (active in fat-amd-1-ib)
                                 OST4 (active in fat-amd-2-ib)
                                 OST5 (active in fat-amd-1-ib)
                                 OST6 (active in fat-amd-2-ib)

Client Node:  fat-amd-3-ib

mmp test 9 failed as follows:

Running e2fsck on the device /dev/disk/by-id/scsi-1IET_00020001 on ost1failover...
fat-amd-2-ib: e2fsck 1.41.90.wc2 (14-May-2011)
Pass 1: Checking inodes, blocks, and sizes
Pass 2: Checking directory structure
Pass 3: Checking directory connectivity
Pass 4: Checking reference counts
Pass 5: Checking group summary information
lustre-OST0000: 58/125184 files (6.9% non-contiguous), 28117/500000 blocks
/usr/lib64/lustre/tests/mmp.sh: line 573: kill: (12252) - No such process
Mounting /dev/disk/by-id/scsi-1IET_00020001 on ost1...
Starting ost1:   /dev/disk/by-id/scsi-1IET_00020001 /mnt/ost1
fat-amd-1-ib: lnet.debug=0x33f1504
fat-amd-1-ib: lnet.subsystem_debug=0xffb7e3ff
fat-amd-1-ib: lnet.debug_mb=48
Started lustre-OST0000
 mmp test_9: @@@@@@ FAIL: mount /dev/disk/by-id/scsi-1IET_00020001 on ost1 should fail

Maloo report: https://maloo.whamcloud.com/test_sets/ea7cb158-98f0-11e0-9a27-52540025f9af

Comment by Niu Yawei (Inactive) [ 19/Jun/11 ]

Hi, Sarah

Could you try this patch? It uses debugfs to make sure the MMP block is in 'e2fsck' before trying to mount the device in test_9, and it works fine in my local testing environment. (Please make sure the test scripts updated on both client and servers)

Comment by Andreas Dilger [ 19/Jun/11 ]

Niu, it is far better to add patches to Gerrit instead of attachments in Jira.

Patches in Gerrit automatically build RPMs that can be installed for testing quickly, they can be inspected more easily, and if testing and inspection goes well it can be landed more easily afterward.

Comment by Niu Yawei (Inactive) [ 20/Jun/11 ]

Ok, I pushed the patch for review: http://review.whamcloud.com/979 . Thanks.

Comment by Sarah Liu [ 20/Jun/11 ]

Hi Niu,

I didn't use lustre-review build 1041(from http://review.whamcloud.com/979) since lu-395's fix isn't in that branch, instead, I tested the latest lustre-master build #176 with your patches and it passed. By the way, the new added script mark_mmp.sh does not executable, you may need change that

https://maloo.whamcloud.com/test_sets/cd89342a-9b72-11e0-9a27-52540025f9af

Comment by Niu Yawei (Inactive) [ 21/Jun/11 ]

Ah, I think it because I forgot to add mmp_mark.sh into Makefile.am, will add it. Thank you.

Comment by Andreas Dilger [ 21/Jun/11 ]

Note that Git keeps the right file permissions, so you should "chmod 0x755 mmp_mark.sh" and rebase your patch.

Comment by Niu Yawei (Inactive) [ 21/Jun/11 ]

I checked out a new copy of mmp_mark.sh from git, the mode is 755, so I think the mode is correct when I committing it.

Comment by Peter Jones [ 21/Jun/11 ]

Landed for 2.1

Comment by Build Master (Inactive) [ 21/Jun/11 ]

Integrated in lustre-master » x86_64,client,sles11,inkernel #177
~~LU-387~~ mmp.sh test_9 failed