[Gluster-devel] Spurious failures in tests/basic/afr/arbiter.t

[Ravishankar N]

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 at gluster.org
>>> http://www.gluster.org/mailman/listinfo/gluster-devel

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.gluster.org/pipermail/gluster-devel/attachments/20150720/bfaa740e/attachment.html>