Bug 207144 - rgmanager stuck in join/update state (cause: I/O wait on stdout/err)
rgmanager stuck in join/update state (cause: I/O wait on stdout/err)
Status: CLOSED ERRATA
Product: Red Hat Cluster Suite
Classification: Red Hat
Component: rgmanager (Show other bugs)
4
x86_64 Linux
medium Severity medium
: ---
: ---
Assigned To: Lon Hohberger
Cluster QE
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2006-09-19 13:54 EDT by Lenny Maiorani
Modified: 2009-04-16 16:20 EDT (History)
1 user (show)

See Also:
Fixed In Version: RHBA-2007-0149
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-05-10 17:17:37 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Switches logging in rgmanager / clulog utility to use non-blocking output for clulog() calls (1.67 KB, patch)
2006-09-28 14:04 EDT, Lon Hohberger
no flags Details | Diff
stdout and stderr from rgmanager (7.75 KB, application/octet-stream)
2006-10-02 16:06 EDT, Lenny Maiorani
no flags Details
Use nonblocking output and also do not block in recv() in the main thread (2.47 KB, text/x-patch)
2006-10-04 17:11 EDT, Lon Hohberger
no flags Details

  None (edit)
Description Lenny Maiorani 2006-09-19 13:54:56 EDT
Description of problem:
After a fence operation occurs, rgmanager does not complete joining the cluster
and take over VIPs.


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


How reproducible:
Often


Steps to Reproduce:
1. cause a node to get fenced
2. when the node attempts to rejoin the cluster, rgmanager is started, but never
takes over VIPs. 
3. clustat times out communicating with rgmanager.

  
Expected results:
VIPs are taken over by recovered node

Additional info:

output from /proc/cluster/services on each of the 3 nodes:
node 1 
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       U-1,10,2
[1 3]

DLM Lock Space:  "clvmd"                             2   3 run       U-1,10,2
[1 3]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[1 3]

DLM Lock Space:  "V1"                                5   6 run       -
[1 3]

DLM Lock Space:  "Snaporig"                          7   8 run       -
[1 3]

DLM Lock Space:  "Volume2"                           9  10 run       -
[1 3]

DLM Lock Space:  "Magma"                            12  13 run       -
[1]

GFS Mount Group: "crosswalk"                         4   5 run       -
[1 3]

GFS Mount Group: "V1"                                6   7 run       -
[1 3]

GFS Mount Group: "Snaporig"                          8   9 run       -
[1 3]

GFS Mount Group: "Volume2"                          10  11 run       -
[1 3]

User:            "usrm::manager"                    11  12 recover 2 -

Node 2 (fenced node)
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 join      S-4,4,2
[1 3 2]

DLM Lock Space:  "clvmd"                             2   3 join      S-4,4,2
[1 3 2]


Node 3
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 update    U-2,0,2
[1 3]

DLM Lock Space:  "clvmd"                             2   3 update    U-2,0,2
[1 3]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[1 3]

DLM Lock Space:  "V1"                                5   6 run       -
[1 3]

DLM Lock Space:  "Snaporig"                          7   8 run       -
[1 3]

DLM Lock Space:  "Volume2"                           9  10 run       -
[1 3]

GFS Mount Group: "crosswalk"                         4   5 run       -
[1 3]

GFS Mount Group: "V1"                                6   7 run       -
[1 3]

GFS Mount Group: "Snaporig"                          8   9 run       -
[1 3]

GFS Mount Group: "Volume2"                          10  11 run       -
[1 3]

User:            "usrm::manager"                     0  12 join      S-1,80,3
[]





In another case /proc/cluster/services:

[root@lizard01 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[2 3 1]

DLM Lock Space:  "clvmd"                             2   3 run       -
[2 3 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[2 3 1]

DLM Lock Space:  "V1"                                5   6 run       -
[2 3 1]

DLM Lock Space:  "Snaporig"                          7   8 run       -
[2 3 1]

DLM Lock Space:  "Volume2"                           9  10 run       -
[2 3 1]

GFS Mount Group: "crosswalk"                         4   5 run       -
[2 3 1]

GFS Mount Group: "V1"                                6   7 run       -
[2 3 1]

GFS Mount Group: "Snaporig"                          8   9 run       -
[2 3 1]

GFS Mount Group: "Volume2"                          10  11 run       -
[2 3 1]

User:            "usrm::manager"                    11  12 join      S-8,40,3
[2 3 1]



Lizard02 

[root@lizard02 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[2 3 1]

DLM Lock Space:  "clvmd"                             2   3 run       -
[2 3 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[2 3 1]

DLM Lock Space:  "V1"                                5   6 run       -
[2 3 1]

DLM Lock Space:  "Snaporig"                          7   8 run       -
[2 3 1]

DLM Lock Space:  "Volume2"                           9  10 run       -
[2 3 1]

DLM Lock Space:  "Magma"                            12  13 run       -
[2 3]

GFS Mount Group: "crosswalk"                         4   5 run       -
[2 3 1]

GFS Mount Group: "V1"                                6   7 run       -
[2 3 1]

GFS Mount Group: "Snaporig"                          8   9 run       -
[2 3 1]

GFS Mount Group: "Volume2"                          10  11 run       -
[2 3 1]

User:            "usrm::manager"                    11  12 update    U-4,1,1
[2 3 1]

Lizard03
[root@lizard03 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[2 3 1]

DLM Lock Space:  "clvmd"                             2   3 run       -
[2 3 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[3 2 1]

DLM Lock Space:  "V1"                                5   6 run       -
[3 2 1]

DLM Lock Space:  "Snaporig"                          7   8 run       -
[3 2 1]

DLM Lock Space:  "Volume2"                           9  10 run       -
[3 2 1]

DLM Lock Space:  "Magma"                            12  13 run       -
[2 3]

GFS Mount Group: "crosswalk"                         4   5 run       -
[3 2 1]

GFS Mount Group: "V1"                                6   7 run       -
[3 2 1]

GFS Mount Group: "Snaporig"                          8   9 run       -
[3 2 1]

GFS Mount Group: "Volume2"                          10  11 run       -
[3 2 1]

User:            "usrm::manager"                    11  12 update    U-6,2,1
[2 3 1]





And another:

Dragon01
[root@dragon01 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[2 3 1]

DLM Lock Space:  "clvmd"                             2   3 run       -
[2 3 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[2 3 1]

DLM Lock Space:  "V1"                                7   6 run       -
[2 3 1]

GFS Mount Group: "crosswalk"                         4   5 run       -
[2 3 1]

GFS Mount Group: "V1"                                8   7 run       -
[2 3 1]

User:            "usrm::manager"                     5   8 join      S-8,40,3
[2 3 1]

Dragon02
[root@dragon02 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[2 3 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[3 2 1]

DLM Lock Space:  "Magma"                             6   7 run       -
[3 2]

DLM Lock Space:  "clvmd"                             2   9 run       -
[3 2 1]

DLM Lock Space:  "V1"                                7  10 run       -
[2 3 1]

GFS Mount Group: "crosswalk"                         4   5 run       -
[3 2 1]

GFS Mount Group: "V1"                                8  11 run       -
[2 3 1]

User:            "usrm::manager"                     5   6 update    U-4,1,1
[3 2 1]


Dragon03
[root@dragon03 ~]# cat /proc/cluster/services
Service          Name                              GID LID State     Code
Fence Domain:    "default"                           1   2 run       -
[3 2 1]

DLM Lock Space:  "crosswalk"                         3   4 run       -
[3 2 1]

DLM Lock Space:  "Magma"                             6   7 run       -
[3 2]

DLM Lock Space:  "clvmd"                             2   9 run       -
[3 2 1]

DLM Lock Space:  "V1"                                7  10 run       -
[3 2 1]

GFS Mount Group: "crosswalk"                         4   5 run       -
[3 2 1]

GFS Mount Group: "V1"                                8  11 run       -
[3 2 1]

User:            "usrm::manager"                     5   6 update    U-4,1,1
[3 2 1]
Comment 1 Lenny Maiorani 2006-09-20 18:01:00 EDT
More info possibly related:

frii01 was fenced by frii02. When frii01 came back up rgmanager on frii02 never
completed marking frii01 as joining. When frii02 rgmanager was restarted it
joined properly. Here are some logs from /var/log/messages...

Sep 14 21:20:29 frii01 clurgmgrd[15602]: <info> Logged in SG "usrm::manager" 
Sep 14 21:20:29 frii01 clurgmgrd[15602]: <info> Magma Event: Membership Change 
Sep 14 21:20:29 frii01 clurgmgrd[15602]: <info> State change: Local UP 
Sep 14 21:20:29 frii01 clurgmgrd[15602]: <info> State change: frii02 UP 
Sep 14 21:20:30 frii01 clurgmgrd[15602]: <info> Magma Event: Membership Change 
Sep 14 21:20:30 frii01 clurgmgrd[15602]: <info> State change: frii02 DOWN 


Sep 14 18:54:36 frii02 clurgmgrd[12763]: <info> Magma Event: Membership Change 
Sep 14 18:54:36 frii02 clurgmgrd[12763]: <info> State change: frii01 DOWN 

Sep 14 21:20:17 frii02 clurgmgrd[12763]: <err> #37: Error receiving message
header 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Shutting down 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.107.225 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.106.225 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.105.225 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.104.225 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.106.225/24 from eth0.106 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.103.225 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.107.225/24 from eth0.107 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.102.225 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.105.225/24 from eth0.105 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service
172.16.101.225 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.104.225/24 from eth0.104 
Sep 14 21:20:17 frii02 clurgmgrd[12763]: <notice> Stopping service frii-mgmt 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.102.225/24 from eth0.102 
Sep 14 21:20:17 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.103.225/24 from eth5 
Sep 14 21:20:18 frii02 clurgmgrd[12763]: <notice> Stopping service snapshot 
Sep 14 21:20:18 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.101.225/24 from eth0.101 
Sep 14 21:20:18 frii02 clurgmgrd: [12763]: <info> Removing IPv4 address
172.16.103.226/24 from eth0.103 
Sep 14 21:20:18 frii02 clurgmgrd[12763]: <notice> Stopping service
email_notifier 
Sep 14 21:20:18 frii02 clurgmgrd: [12763]: <info> Executing
/mnt/crosswalk/snapshot/run_snap stop 
Sep 14 21:20:18 frii02 clurgmgrd[12763]: <notice> Stopping service nvbackup 
Sep 14 21:20:18 frii02 clurgmgrd: [12763]: <info> Executing
/opt/crosswalk/email_notifier/run_email_notifier stop 
Sep 14 21:20:18 frii02 clurgmgrd[12763]: <notice> Service snapshot is stopped 
Sep 14 21:20:18 frii02 clurgmgrd: [12763]: <info> Executing
/mnt/igridbackup/nvbackup/nvmain stop 
Sep 14 21:20:18 frii02 clurgmgrd[12763]: <notice> Service email_notifier is
stopped 
Sep 14 21:20:19 frii02 clurgmgrd[12763]: <notice> Service nvbackup is stopped 
Sep 14 21:20:27 frii02 clurgmgrd[12763]: <notice> Service 172.16.106.225 is
stopped 
Sep 14 21:20:27 frii02 clurgmgrd[12763]: <notice> Service 172.16.107.225 is
stopped 
Sep 14 21:20:27 frii02 clurgmgrd[12763]: <notice> Service 172.16.105.225 is
stopped 
Sep 14 21:20:28 frii02 clurgmgrd[12763]: <notice> Service 172.16.104.225 is
stopped 
Sep 14 21:20:28 frii02 clurgmgrd[12763]: <notice> Service 172.16.102.225 is
stopped 
Sep 14 21:20:28 frii02 clurgmgrd[12763]: <notice> Service 172.16.103.225 is
stopped 
Sep 14 21:20:28 frii02 clurgmgrd[12763]: <notice> Service 172.16.101.225 is
stopped 
Sep 14 21:20:28 frii02 clurgmgrd[12763]: <notice> Service frii-mgmt is stopped 
Sep 14 21:20:31 frii02 clurgmgrd[12763]: <notice> Shutdown complete, exiting 



Side note:
The kernel is 2.6.9-34 with a patch recently introduced from bz #199673.
Comment 2 Lon Hohberger 2006-09-21 11:41:48 EDT
Thanks for all of the information.  I'm wondering if this is just a simple join
synchronization problem in the SM magma plugin.
Comment 4 Lenny Maiorani 2006-09-22 17:50:52 EDT
Well, it is something we are seeing VERY regularly after a fence.

Another information point... we changed deadnode_timeout to 64 and hello_timer to 5.
Comment 5 Lenny Maiorani 2006-09-27 16:40:35 EDT
Figured out that one of the services being run by rgmanager was printing to
STDERR and STDOUT. This was causing the rgmanager some problems. As soon as we
took the printf's out of that service this problem stopped.

I guess the bug isn't really that rgmanager doesn't start up, but rather is is
not properly handling an interrupt.
Comment 6 Lon Hohberger 2006-09-28 14:04:26 EDT
Created attachment 137328 [details]
Switches logging in rgmanager / clulog utility to use non-blocking output for clulog() calls
Comment 7 Lenny Maiorani 2006-10-02 16:06:30 EDT
Created attachment 137594 [details]
stdout and stderr from rgmanager

New info: We are able to reproduce this by doing 2 consecutive fences to the
same node. Attached are some logs of STDOUT and STDERR from rgmanager on each
node.

Story: node1 was fenced and node2 is the failover domain for all node1
services. rgmanager on node1 is shown to be started by clustat, is still in the
"join" state according to /proc/cluster/services.
Comment 8 Lon Hohberger 2006-10-04 17:11:49 EDT
Created attachment 137773 [details]
Use nonblocking output and also do not block in recv() in the main thread
Comment 9 Lenny Maiorani 2006-10-04 17:15:02 EDT
Fenced node1 and when attempting to rejoin, we are stuck. Here are backtraces
and /proc/cluster/services info from each node:

node 1:
#0  0x0000003162bbf0a6 in __select_nocancel () from /lib64/tls/libc.so.6
#1  0x0000002a9558be30 in sm_wait_join_complete (p=0x542e00) at sm.c:242
#2  0x0000002a9558c1f7 in sm_login (self=0x542d20, fd=4, 
    groupname=0x4173d0 "usrm::manager") at sm.c:362
#3  0x00000033e5503930 in cp_login (cpp=0x542d20, fd=4, 
    groupname=0x4173d0 "usrm::manager") at plugin.c:708
#4  0x00000033e5502945 in clu_login (fd=4, groupname=0x4173d0 "usrm::manager")
    at global.c:295
#5  0x0000000000406489 in main (argc=2, argv=0x7fbffffd58) at main.c:814
#6  0x0000003162b1c4bb in __libc_start_main () from /lib64/tls/libc.so.6
#7  0x0000000000403a3a in _start ()
#8  0x0000007fbffffd48 in ?? ()
#9  0x000000000000001c in ?? ()
#10 0x0000000000000002 in ?? ()
#11 0x0000007fbffffeeb in ?? ()
#12 0x0000007fbffffeff in ?? ()
#13 0x0000000000000000 in ?? ()

No /proc/cluster/services info for usrm



Node 2:
#0  0x0000003c1560b52a in recv () from /lib64/tls/libpthread.so.0
#1  0x00000039c9a02539 in msg_peek (sockfd=12, buf=0x7fbffffaf0, count=20)
    at message.c:853
#2  0x00000000004055a6 in dispatch_msg (fd=12, nodeid=2) at main.c:346
#3  0x0000000000405de2 in event_loop (clusterfd=4) at main.c:548
#4  0x0000000000406533 in main (argc=2, argv=0x7fbffffd58) at main.c:839
#5  0x0000003c14d1c4bb in __libc_start_main () from /lib64/tls/libc.so.6
#6  0x0000000000403a3a in _start ()
#7  0x0000007fbffffd48 in ?? ()
#8  0x000000000000001c in ?? ()
#9  0x0000000000000002 in ?? ()
#10 0x0000007fbffffeeb in ?? ()
#11 0x0000007fbffffeff in ?? ()
#12 0x0000000000000000 in ?? ()

User:            "usrm::manager"                    16  19 update    U-4,1,1
[3 2 1]



Node 3:
#0  0x0000003f5af0b52a in recv () from /lib64/tls/libpthread.so.0
#1  0x0000003e92802539 in msg_peek (sockfd=9, buf=0x7fbffffaf0, count=20)
    at message.c:853
#2  0x00000000004055a6 in dispatch_msg (fd=9, nodeid=3) at main.c:346
#3  0x0000000000405de2 in event_loop (clusterfd=4) at main.c:548
#4  0x0000000000406533 in main (argc=2, argv=0x7fbffffd58) at main.c:839
#5  0x0000003f5a61c4bb in __libc_start_main () from /lib64/tls/libc.so.6
#6  0x0000000000403a3a in _start ()
#7  0x0000007fbffffd48 in ?? ()
#8  0x000000000000001c in ?? ()
#9  0x0000000000000002 in ?? ()
#10 0x0000007fbffffeeb in ?? ()
#11 0x0000007fbffffeff in ?? ()
#12 0x0000000000000000 in ?? ()

User:            "usrm::manager"                    16  18 update    U-4,1,1
[3 2 1]
Comment 10 Lenny Maiorani 2006-10-05 13:48:56 EDT
This patch has solved the problem. Tested it a few times and the re-join happens
each time.
Comment 13 Red Hat Bugzilla 2007-05-10 17:17:37 EDT
An advisory has been issued which should help the problem
described in this bug report. This report is therefore being
closed with a resolution of ERRATA. For more information
on the solution and/or where to find the updated files,
please follow the link below. You may reopen this bug report
if the solution does not work for you.

http://rhn.redhat.com/errata/RHBA-2007-0149.html

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