Bug 824828 - [glusterfs-3.3.0qa43]: lot of disconnect and conneting log messages in client log file
[glusterfs-3.3.0qa43]: lot of disconnect and conneting log messages in client...
Status: CLOSED CURRENTRELEASE
Product: GlusterFS
Classification: Community
Component: protocol (Show other bugs)
pre-release
Unspecified Unspecified
medium Severity medium
: ---
: ---
Assigned To: Raghavendra Bhat
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2012-05-24 07:41 EDT by Raghavendra Bhat
Modified: 2013-07-24 14:02 EDT (History)
3 users (show)

See Also:
Fixed In Version: glusterfs-3.4.0
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2013-07-24 14:02:12 EDT
Type: Bug
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Raghavendra Bhat 2012-05-24 07:41:43 EDT
Description of problem:
3x2 distributed replicate volume. 2 fuse clients. quota enabled. 1 client running rdd and the other client running fs-perf-test. lock-heal was on. brought down 2 bricks immedietly after starting the 2 tests.

One of the clients is getting lot of these logs.


[2012-05-24 17:04:55.049055] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:04:55.049131] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:04:56.049999] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:04:56.050840] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:04:56.050921] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:04:58.050657] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:04:58.050844] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:04:58.050869] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:00.052198] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:00.052700] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:00.052782] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:01.054426] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:01.054856] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:01.054936] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:03.055679] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:03.056226] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:03.056313] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:04.056387] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:04.056859] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:04.057002] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:06.058374] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:06.058871] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:06.058956] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:07.060783] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:07.061253] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:07.061323] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:09.063130] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:09.063540] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:09.063597] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:10.064573] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:10.065266] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:10.065343] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:12.065962] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:12.066457] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:12.066537] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:13.067945] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:13.068620] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:13.068704] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
[2012-05-24 17:05:15.068207] W [client.c:2069:client_rpc_notify] 7-mirror-client-5: Cancelling the grace timer
[2012-05-24 17:05:15.068390] I [client.c:127:client_register_grace_timer] 7-mirror-client-5: Registering a grace timer
[2012-05-24 17:05:15.068413] I [client.c:2090:client_rpc_notify] 7-mirror-client-5: disconnected
[2012-05-24 17:05:17.070982] W [client.c:2069:client_rpc_notify] 7-mirror-client-3: Cancelling the grace timer
[2012-05-24 17:05:17.071506] I [client.c:127:client_register_grace_timer] 7-mirror-client-3: Registering a grace timer
[2012-05-24 17:05:17.071588] I [client.c:2090:client_rpc_notify] 7-mirror-client-3: disconnected
(END) 

Version-Release number of selected component (if applicable):


How reproducible:


Steps to Reproduce:
1. create a distribted replicate volume start it and mount it
2. run fs-perf-test on the volume
3.
  
Actual results:
lot of log results

Expected results:

lot of above logs should be avoided

Additional info:

possible theory behind it:

fs-perf-test takes a number as argument, creates those many files, opens all the files, writes some data on each fd, syncs each fd and then closes it.

Here 1024 was the argument given to fs-perf-tes. Since 2 bricks were down, whenever the file fs-perf-test is handling hashes to the down bricks client protocol tries to get the port number of those bricks  from glusterd (for which a connect and a disconnect has to happen), thus filling the log file with logs related to connect/disconnect.
Comment 1 Jules Wang 2012-10-25 02:36:01 EDT
Maybe this patch fixes your problem:

http://review.gluster.com/2947


By the way, the option lk-heal is off by default.
Comment 2 Raghavendra Bhat 2012-12-04 05:22:51 EST
Jules Wang,

Thanks for pointing out, it does. I kept this bug open as I was testing with lk-heal on. Anyways, will close the bug as there are some other testing effort needed to enable 'lk-heal' by default and would anticipate more of issues coming up then.

Note You need to log in before you can comment on or make changes to this bug.