Re: Spurious failures in tests/basic/afr/arbiter.t

[Ravishankar N <ravishankar@xxxxxxxxxx>]

On 07/20/2015 12:45 PM, Niels de Vos wrote:

On Mon, Jul 20, 2015 at 09:25:15AM +0530, Ravishankar N wrote:

I'll take a look.

Thanks. I'm actually not sure if this is a arbiter.t issue, maybe I
blamed it too early? Its the first test that gets executed, and no
others are tried after it failed.

Niels

Regards,
Ravi

On 07/20/2015 03:07 AM, Niels de Vos wrote:

I have seen several occurences of failures in arbiter.t now. This is one
of the errors:

    https://build.gluster.org/job/rackspace-regression-2GB-triggered/12626/consoleFull

    [21:20:20] ./tests/basic/afr/arbiter.t ..
    not ok 7 Got "N" instead of "Y"
    not ok 15
    not ok 16 Got "" instead of "1"
    not ok 23 Got "" instead of "1"
    not ok 25 Got "0" when not expecting it
    not ok 26
    not ok 34 Got "0" instead of "1"
    not ok 35 Got "0" instead of "1"
    not ok 41 Got "" instead of "1"
    not ok 47 Got "N" instead of "Y"
    Failed 10/47 subtests
    [21:20:20]
    Test Summary Report
    -------------------
    ./tests/basic/afr/arbiter.t (Wstat: 0 Tests: 47 Failed: 10)
      Failed tests:  7, 15-16, 23, 25-26, 34-35, 41, 47

So the test #7 that failed is "16 EXPECT_WITHIN $UMOUNT_TIMEOUT "Y" force_umount $M0"
Looking at mnt-glusterfs-0.log, I see that the unmount has already happened before the actual command was run, at least from the time stamp logged by G_LOG() function.

[2015-07-19 21:16:21.784293] I [fuse-bridge.c:4946:fuse_thread_proc] 0-fuse: unmounting /mnt/glusterfs/0
[2015-07-19 21:16:21.784542] W [glusterfsd.c:1214:cleanup_and_exit] (-->/lib64/libpthread.so.0(+0x79d1) [0x7fc3f41c49d1] -->glusterfs(glusterfs_sigwaiter+0xe4) [0x409734] -->glusterfs(cleanup_and_exit+0x87) [0x407ba7] ) 0-: received signum (15), shutting down
[2015-07-19 21:16:21.784571] I [fuse-bridge.c:5645:fini] 0-fuse: Unmounting '/mnt/glusterfs/0'.
[2015-07-19 21:16:21.785817332]:++++++++++ G_LOG:./tests/basic/afr/arbiter.t: TEST: 15 ! stat /mnt/glusterfs/0/.meta/graphs/active/patchy-replicate-0/options/arbiter-count ++++++++++
[2015-07-19 21:16:21.796574975]:++++++++++ G_LOG:./tests/basic/afr/arbiter.t: TEST: 16 Y force_umount /mnt/glusterfs/0 ++++++++++

I have no clue as to why that could have happened because appending to the gluster log files using G_LOG() is done *before* the test is executed. In all my trial runs, the G_LOG message gets logged first, followed by the logs relevant to the actual command being run.


FWIW, http://review.gluster.org/#/c/11114/ changed made the following change to arbiter.t  amongst other test cases :

-TEST umount $M0
+EXPECT_WITHIN $UMOUNT_TIMEOUT "Y" force_umount $M0

But I'm not sure doing a umount -f has any impact for fuse mounts.

Regards,
Ravi

    Files=1, Tests=47, 243 wallclock secs ( 0.04 usr  0.00 sys + 15.22 cusr  3.48 csys = 18.74 CPU)
    Result: FAIL


Who could have look at this?

Thanks,
Niels
_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel

_______________________________________________
Gluster-devel mailing list
Gluster-devel@xxxxxxxxxxx
http://www.gluster.org/mailman/listinfo/gluster-devel