[Gluster-devel] Spurious failures because of nfs and snapshots
Vijaikumar M
vmallika at redhat.com
Wed May 21 06:53:02 UTC 2014
From the log:
http://build.gluster.org:443/logs/glusterfs-logs-20140520%3a17%3a10%3a51.tgzit
looks like glusterd was hung:
*Glusterd log:**
* 5305 [2014-05-20 20:08:55.040665] E
[glusterd-snapshot.c:3805:glusterd_add_brick_to_snap_volume]
0-management: Unable to fetch snap device (vol1.brick_snapdevice0).
Leaving empty
5306 [2014-05-20 20:08:55.649146] I
[rpc-clnt.c:973:rpc_clnt_connection_init] 0-management: setting
frame-timeout to 600
5307 [2014-05-20 20:08:55.663181] I
[rpc-clnt.c:973:rpc_clnt_connection_init] 0-management: setting
frame-timeout to 600
5308 [2014-05-20 20:16:55.541197] W
[glusterfsd.c:1182:cleanup_and_exit] (--> 0-: received signum (15),
shutting down
Glusterd was hung when executing the testcase ./tests/bugs/bug-1090042.t.
*Cli log:**
*72649 [2014-05-20 20:12:51.960765] T
[rpc-clnt.c:418:rpc_clnt_reconnect] 0-glusterfs: attempting reconnect
72650 [2014-05-20 20:12:51.960850] T [socket.c:2689:socket_connect]
(-->/build/install/lib/libglusterfs.so.0(gf_timer_proc+0x1a2)
[0x7ff8b6609994]
(-->/build/install/lib/libgfrpc.so.0(rpc_clnt_reconnect+0x137)
[0x7ff8b5d3305b] (-
->/build/install/lib/libgfrpc.so.0(rpc_transport_connect+0x74)
[0x7ff8b5d30071]))) 0-glusterfs: connect () called on transport already
connected
72651 [2014-05-20 20:12:52.960943] T
[rpc-clnt.c:418:rpc_clnt_reconnect] 0-glusterfs: attempting reconnect
72652 [2014-05-20 20:12:52.960999] T [socket.c:2697:socket_connect]
0-glusterfs: connecting 0x1e0fcc0, state=0 gen=0 sock=-1
72653 [2014-05-20 20:12:52.961038] W [dict.c:1059:data_to_str]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(+0xb5f3)
[0x7ff8ad9e95f3]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(socket_clien
t_get_remote_sockaddr+0x10a) [0x7ff8ad9ed568]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(client_fill_address_family+0xf1)
[0x7ff8ad9ec7d0]))) 0-dict: data is NULL
72654 [2014-05-20 20:12:52.961070] W [dict.c:1059:data_to_str]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(+0xb5f3)
[0x7ff8ad9e95f3]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(socket_clien
t_get_remote_sockaddr+0x10a) [0x7ff8ad9ed568]
(-->/build/install/lib/glusterfs/3.5qa2/rpc-transport/socket.so(client_fill_address_family+0x100)
[0x7ff8ad9ec7df]))) 0-dict: data is NULL
72655 [2014-05-20 20:12:52.961079] E
[name.c:140:client_fill_address_family] 0-glusterfs:
transport.address-family not specified. Could not guess default value
from (remote-host:(null) or transport.unix.connect-path:(null))
optio ns
72656 [2014-05-20 20:12:54.961273] T
[rpc-clnt.c:418:rpc_clnt_reconnect] 0-glusterfs: attempting reconnect
72657 [2014-05-20 20:12:54.961404] T [socket.c:2689:socket_connect]
(-->/build/install/lib/libglusterfs.so.0(gf_timer_proc+0x1a2)
[0x7ff8b6609994]
(-->/build/install/lib/libgfrpc.so.0(rpc_clnt_reconnect+0x137)
[0x7ff8b5d3305b] (-
->/build/install/lib/libgfrpc.so.0(rpc_transport_connect+0x74)
[0x7ff8b5d30071]))) 0-glusterfs: connect () called on transport already
connected
72658 [2014-05-20 20:12:55.120645] D [cli-cmd.c:384:cli_cmd_submit]
0-cli: Returning 110
72659 [2014-05-20 20:12:55.120723] D
[cli-rpc-ops.c:8716:gf_cli_snapshot] 0-cli: Returning 110
Now we need to find why glusterd was hung.
Thanks,
Vijay
On Wednesday 21 May 2014 06:46 AM, Pranith Kumar Karampuri wrote:
> Hey,
> Seems like even after this fix is merged, the regression tests are failing for the same script. You can check the logs at http://build.gluster.org:443/logs/glusterfs-logs-20140520%3a14%3a06%3a46.tgz
>
> Relevant logs:
> [2014-05-20 20:17:07.026045] : volume create patchy build.gluster.org:/d/backends/patchy1 build.gluster.org:/d/backends/patchy2 : SUCCESS
> [2014-05-20 20:17:08.030673] : volume start patchy : SUCCESS
> [2014-05-20 20:17:08.279148] : volume barrier patchy enable : SUCCESS
> [2014-05-20 20:17:08.476785] : volume barrier patchy enable : FAILED : Failed to reconfigure barrier.
> [2014-05-20 20:17:08.727429] : volume barrier patchy disable : SUCCESS
> [2014-05-20 20:17:08.926995] : volume barrier patchy disable : FAILED : Failed to reconfigure barrier.
>
> Pranith
>
> ----- Original Message -----
>> From: "Pranith Kumar Karampuri" <pkarampu at redhat.com>
>> To: "Gluster Devel" <gluster-devel at gluster.org>
>> Cc: "Joseph Fernandes" <josferna at redhat.com>, "Vijaikumar M" <vmallika at redhat.com>
>> Sent: Tuesday, May 20, 2014 3:41:11 PM
>> Subject: Re: Spurious failures because of nfs and snapshots
>>
>> hi,
>> Please resubmit the patches on top of http://review.gluster.com/#/c/7753
>> to prevent frequent regression failures.
>>
>> Pranith
>> ----- Original Message -----
>>> From: "Vijaikumar M" <vmallika at redhat.com>
>>> To: "Pranith Kumar Karampuri" <pkarampu at redhat.com>
>>> Cc: "Joseph Fernandes" <josferna at redhat.com>, "Gluster Devel"
>>> <gluster-devel at gluster.org>
>>> Sent: Monday, May 19, 2014 2:40:47 PM
>>> Subject: Re: Spurious failures because of nfs and snapshots
>>>
>>> Brick disconnected with ping-time out:
>>>
>>> Here is the log message
>>> [2014-05-19 04:29:38.133266] I [MSGID: 100030] [glusterfsd.c:1998:main]
>>> 0-/build/install/sbin/glusterfsd: Started running /build/install/sbi
>>> n/glusterfsd version 3.5qa2 (args: /build/install/sbin/glusterfsd -s
>>> build.gluster.org --volfile-id /snaps/patchy_snap1/3f2ae3fbb4a74587b1a9
>>> 1013f07d327f.build.gluster.org.var-run-gluster-snaps-3f2ae3fbb4a74587b1a91013f07d327f-brick3
>>> -p /var/lib/glusterd/snaps/patchy_snap1/3f2ae3f
>>> bb4a74587b1a91013f07d327f/run/build.gluster.org-var-run-gluster-snaps-3f2ae3fbb4a74587b1a91013f07d327f-brick3.pid
>>> -S /var/run/51fe50a6faf0aa e006c815da946caf3a.socket --brick-name
>>> /var/run/gluster/snaps/3f2ae3fbb4a74587b1a91013f07d327f/brick3 -l
>>> /build/install/var/log/glusterfs/br
>>> icks/var-run-gluster-snaps-3f2ae3fbb4a74587b1a91013f07d327f-brick3.log
>>> --xlator-option *-posix.glusterd-uuid=494ef3cd-15fc-4c8c-8751-2d441ba
>>> 7b4b0 --brick-port 49164 --xlator-option
>>> 3f2ae3fbb4a74587b1a91013f07d327f-server.listen-port=49164)
>>> 2 [2014-05-19 04:29:38.141118] I
>>> [rpc-clnt.c:988:rpc_clnt_connection_init] 0-glusterfs: defaulting
>>> ping-timeout to 30secs
>>> 3 [2014-05-19 04:30:09.139521] C
>>> [rpc-clnt-ping.c:105:rpc_clnt_ping_timer_expired] 0-glusterfs: server
>>> 10.3.129.13:24007 has not responded in the last 30 seconds, disconnecting.
>>>
>>>
>>>
>>> Patch 'http://review.gluster.org/#/c/7753/' will fix the problem, where
>>> ping-timer will be disabled by default for all the rpc connection except
>>> for glusterd-glusterd (set to 30sec) and client-glusterd (set to 42sec).
>>>
>>>
>>> Thanks,
>>> Vijay
>>>
>>>
>>> On Monday 19 May 2014 11:56 AM, Pranith Kumar Karampuri wrote:
>>>> The latest build failure also has the same issue:
>>>> Download it from here:
>>>> http://build.gluster.org:443/logs/glusterfs-logs-20140518%3a22%3a27%3a31.tgz
>>>>
>>>> Pranith
>>>>
>>>> ----- Original Message -----
>>>>> From: "Vijaikumar M" <vmallika at redhat.com>
>>>>> To: "Joseph Fernandes" <josferna at redhat.com>
>>>>> Cc: "Pranith Kumar Karampuri" <pkarampu at redhat.com>, "Gluster Devel"
>>>>> <gluster-devel at gluster.org>
>>>>> Sent: Monday, 19 May, 2014 11:41:28 AM
>>>>> Subject: Re: Spurious failures because of nfs and snapshots
>>>>>
>>>>> Hi Joseph,
>>>>>
>>>>> In the log mentioned below, it say ping-time is set to default value
>>>>> 30sec.I think issue is different.
>>>>> Can you please point me to the logs where you where able to re-create
>>>>> the problem.
>>>>>
>>>>> Thanks,
>>>>> Vijay
>>>>>
>>>>>
>>>>>
>>>>> On Monday 19 May 2014 09:39 AM, Pranith Kumar Karampuri wrote:
>>>>>> hi Vijai, Joseph,
>>>>>> In 2 of the last 3 build failures,
>>>>>> http://build.gluster.org/job/regression/4479/console,
>>>>>> http://build.gluster.org/job/regression/4478/console this
>>>>>> test(tests/bugs/bug-1090042.t) failed. Do you guys think it is
>>>>>> better
>>>>>> to revert this test until the fix is available? Please send a
>>>>>> patch
>>>>>> to revert the test case if you guys feel so. You can re-submit it
>>>>>> along with the fix to the bug mentioned by Joseph.
>>>>>>
>>>>>> Pranith.
>>>>>>
>>>>>> ----- Original Message -----
>>>>>>> From: "Joseph Fernandes" <josferna at redhat.com>
>>>>>>> To: "Pranith Kumar Karampuri" <pkarampu at redhat.com>
>>>>>>> Cc: "Gluster Devel" <gluster-devel at gluster.org>
>>>>>>> Sent: Friday, 16 May, 2014 5:13:57 PM
>>>>>>> Subject: Re: Spurious failures because of nfs and snapshots
>>>>>>>
>>>>>>>
>>>>>>> Hi All,
>>>>>>>
>>>>>>> tests/bugs/bug-1090042.t :
>>>>>>>
>>>>>>> I was able to reproduce the issue i.e when this test is done in a loop
>>>>>>>
>>>>>>> for i in {1..135} ; do ./bugs/bug-1090042.t
>>>>>>>
>>>>>>> When checked the logs
>>>>>>> [2014-05-16 10:49:49.003978] I
>>>>>>> [rpc-clnt.c:973:rpc_clnt_connection_init]
>>>>>>> 0-management: setting frame-timeout to 600
>>>>>>> [2014-05-16 10:49:49.004035] I
>>>>>>> [rpc-clnt.c:988:rpc_clnt_connection_init]
>>>>>>> 0-management: defaulting ping-timeout to 30secs
>>>>>>> [2014-05-16 10:49:49.004303] I
>>>>>>> [rpc-clnt.c:973:rpc_clnt_connection_init]
>>>>>>> 0-management: setting frame-timeout to 600
>>>>>>> [2014-05-16 10:49:49.004340] I
>>>>>>> [rpc-clnt.c:988:rpc_clnt_connection_init]
>>>>>>> 0-management: defaulting ping-timeout to 30secs
>>>>>>>
>>>>>>> The issue is with ping-timeout and is tracked under the bug
>>>>>>>
>>>>>>> https://bugzilla.redhat.com/show_bug.cgi?id=1096729
>>>>>>>
>>>>>>>
>>>>>>> The workaround is mentioned in
>>>>>>> https://bugzilla.redhat.com/show_bug.cgi?id=1096729#c8
>>>>>>>
>>>>>>>
>>>>>>> Regards,
>>>>>>> Joe
>>>>>>>
>>>>>>> ----- Original Message -----
>>>>>>> From: "Pranith Kumar Karampuri" <pkarampu at redhat.com>
>>>>>>> To: "Gluster Devel" <gluster-devel at gluster.org>
>>>>>>> Cc: "Joseph Fernandes" <josferna at redhat.com>
>>>>>>> Sent: Friday, May 16, 2014 6:19:54 AM
>>>>>>> Subject: Spurious failures because of nfs and snapshots
>>>>>>>
>>>>>>> hi,
>>>>>>> In the latest build I fired for review.gluster.com/7766
>>>>>>> (http://build.gluster.org/job/regression/4443/console) failed
>>>>>>> because
>>>>>>> of
>>>>>>> spurious failure. The script doesn't wait for nfs export to be
>>>>>>> available. I fixed that, but interestingly I found quite a few
>>>>>>> scripts
>>>>>>> with same problem. Some of the scripts are relying on 'sleep 5'
>>>>>>> which
>>>>>>> also could lead to spurious failures if the export is not
>>>>>>> available
>>>>>>> in 5
>>>>>>> seconds. We found that waiting for 20 seconds is better, but
>>>>>>> 'sleep
>>>>>>> 20'
>>>>>>> would unnecessarily delay the build execution. So if you guys
>>>>>>> are
>>>>>>> going
>>>>>>> to write any scripts which has to do nfs mounts, please do it
>>>>>>> the
>>>>>>> following way:
>>>>>>>
>>>>>>> EXPECT_WITHIN 20 "1" is_nfs_export_available;
>>>>>>> TEST mount -t nfs -o vers=3 $H0:/$V0 $N0;
>>>>>>>
>>>>>>> Please review http://review.gluster.com/7773 :-)
>>>>>>>
>>>>>>> I saw one more spurious failure in a snapshot related script
>>>>>>> tests/bugs/bug-1090042.t on the next build fired by Niels.
>>>>>>> Joesph (CCed) is debugging it. He agreed to reply what he finds and
>>>>>>> share
>>>>>>> it
>>>>>>> with us so that we won't introduce similar bugs in future.
>>>>>>>
>>>>>>> I encourage you guys to share what you fix to prevent spurious
>>>>>>> failures
>>>>>>> in
>>>>>>> future.
>>>>>>>
>>>>>>> Thanks
>>>>>>> Pranith
>>>>>>>
>>>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://supercolony.gluster.org/pipermail/gluster-devel/attachments/20140521/864c9de2/attachment-0001.html>
More information about the Gluster-devel
mailing list