ZCS in RH Cluster Suite Fails over with out any reason

[riyazna]

Hi ,

We have a setup here , where ZCS is installed in two node cluster with Red hat cluster suite.

ZCS 7 is installed and it's running fine with 500 users in the cluster suite. But it failed over twice in an interval of 10 days and we are unable to figure out the reason.

The system logs at the time of Fail Over says

Oct 24 22:10:24 zimbrastore2 clurgmgrd: [2516]: <err> script:zimbrascript: status of /etc/init.d/zimbra failed (returned 1)

we have two nodes namely zimbrastore1 and zimbrastore2 , before the cluster fail over zimbrastore2 was the active node.

zimbra logs at the time of Failover is as below

Oct 24 22:08:49 zimbrastore2 postfix/cleanup[24770]: 51629244FB2: message-id=<20111024163831.51629244FB2@cluster.mysubdomain .com>

Oct 24 22:09:12 zimbrastore2 zmmailboxdmgr[28944]: status OK

Oct 24 22:09:23 zimbrastore2 postfix/qmgr[25166]: 4259E244F8D: from=<HT0070653@mydomain.com>, size=79674, nrcpt=2 (queue active)

Oct 24 22:09:23 zimbrastore2 postfix/cleanup[27903]: 826D2244FE7: message-id=<C86CA6B754CC444FAED01331196CA25659A10DA5F0@SIN NODMBX001.mydomain.com>

Oct 24 22:09:23 zimbrastore2 postfix/lmtp[28715]: 894F1244F99: to=<rv0078187@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=356, delays=310/46/0.07/0.08, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)

Oct 24 22:09:40 zimbrastore2 postfix/smtpd[28144]: disconnect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:09:51 zimbrastore2 postfix/smtpd[24765]: lost connection after CONNECT from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:09:56 zimbrastore2 postfix/pickup[5204]: 99875244FC8: uid=0 from=<root>

Oct 24 22:11:22 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x2e6cea80 20111024163444.284672Z#000000#000#000000

Oct 24 22:11:28 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x2e3913c0 20111024163444.284672Z#000000#000#000000

Oct 24 22:10:25 zimbrastore2 postfix/qmgr[25166]: 5F371244F92: removed

Oct 24 22:11:34 10.11.12.211 slapd[3310]: do_syncrep2: rid=100 cookie=rid=100,csn=20111024163444.284672Z#000000#0 00#000000

Oct 24 22:10:54 zimbrastore2 postfix/qmgr[25166]: BF54E244FC9:
from=<sn0081487@mysubdomain.com>, size=14078, nrcpt=1 (queue active)

Oct 24 22:11:39 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x2eabaf1c 20111024163444.284672Z#000000#000#000000

Oct 24 22:10:54 zimbrastore2 postfix/qmgr[25166]: 894F1244F99: removed

Oct 24 22:11:40 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x2ed8b750 20111024163444.284672Z#000000#000#000000

Oct 24 22:10:31 zimbrastore2 zmmailboxdmgr[29233]: status requested

Oct 24 22:11:40 10.11.12.211 slapd[3310]: syncrepl_message_to_op: rid=100 be_modify uid=as0075414,ou=people,dc=mysubdomain,dc=com (0)

Oct 24 22:11:46 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x31298390 20111024163444.284672Z#000000#000#000000

Oct 24 22:10:37 zimbrastore2 postfix/smtpd[29256]: disconnect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:11:52 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x2eb35c30 20111024163444.284672Z#000000#000#000000

Oct 24 22:10:47 zimbrastore2 postfix/smtpd[29558]: connect from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:10:54 zimbrastore2 postfix/smtpd[24765]: disconnect from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:10:54 zimbrastore2 postfix/cleanup[28162]: 99875244FC8: message-id=<20111024163956.99875244FC8@cluster.mysubdomain .com>

Oct 24 22:10:54 zimbrastore2 postfix/qmgr[25166]: 51629244FB2: from=<root@cluster.mysubdomain.com>, size=1159, nrcpt=1 (queue active)

Oct 24 22:12:57 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x44d532c0 20111024163541.884747Z#000000#000#000000

Oct 24 22:10:54 zimbrastore2 postfix/lmtp[27846]: 927DA244F94: to=<ns0060715@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=441, delays=350/91/0.07/0.11, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)

Oct 24 22:13:02 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x29722658 20111024163541.884747Z#000000#000#000000

Oct 24 22:10:54 zimbrastore2 zmmailboxdmgr[29233]: status OK

Oct 24 22:13:03 10.11.12.210 slapd[4422]: syncprov_sendresp: cookie=rid=100,csn=20111024163541.884747Z#000000#0 00#000000

Oct 24 22:10:54 zimbrastore2 postfix/lmtp[27848]: 4259E244F8D: to=<pd0082421@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=1278, delays=1187/91/0.07/0.08, dsn=4.2.2, status=deferred (host cluster.mysubdomain.com[10.11.12.205] said: 452 4.2.2 Over quota (in reply to end of DATA command))

Oct 24 22:13:03 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x2ddc8d80 20111024163541.884747Z#000000#000#000000

Oct 24 22:10:54 zimbrastore2 postfix/smtpd[28306]: 6C8FF244F92: client=smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:13:09 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x273a6840 20111024163541.884747Z#000000#000#000000

Oct 24 22:13:14 10.11.12.211 slapd[3310]: do_syncrep2: rid=100 cookie=rid=100,csn=20111024163541.884747Z#000000#0 00#000000

Oct 24 22:13:15 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x2eb31953 20111024163541.884747Z#000000#000#000000

Oct 24 22:11:17 zimbrastore2 postfix/smtpd[29558]: lost connection after CONNECT from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:13:21 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x2eaf3660 20111024163541.884747Z#000000#000#000000

Oct 24 22:13:27 10.11.12.211 slapd[3310]: syncrepl_message_to_op: rid=100 be_modify uid=sm0072913,ou=people,dc=mysubdomain,dc=com (0)

Oct 24 22:13:33 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x310f0330 20111024163541.884747Z#000000#000#000000

Oct 24 22:13:33 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x2ea38f60 20111024163541.884747Z#000000#000#000000

Oct 24 22:11:34 zimbrastore2 postfix/pickup[5204]: 54BB7244F99: uid=0 from=<root>

Oct 24 22:11:40 zimbrastore2 postfix/qmgr[25166]: C9F8E244F8C: from=<HT0070653@mydomain.com>, size=748091, nrcpt=2 (queue active)

Oct 24 22:11:40 zimbrastore2 postfix/lmtp[28715]: BF54E244FC9: to=<rb0081351@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=201, delays=155/46/0.07/0.09, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)

Oct 24 22:11:46 zimbrastore2 zimbramon[29471]: 29471:info: 2011-10-24 22:11:46, QUEUE: 12608 88

Oct 24 22:11:58 zimbrastore2 zmmailboxdmgr[29528]: status requested

Oct 24 22:14:13 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x42d4f2c0 20111024163642.366733Z#000000#000#000000

Oct 24 22:14:18 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x23081658 20111024163642.366733Z#000000#000#000000

Oct 24 22:12:21 zimbrastore2 postfix/cleanup[27104]: 6C8FF244F92: message-id=<78a179a7000061b6@SMTP.Chand.mydomain.com>

Oct 24 22:14:25 10.11.12.210 slapd[4422]: syncprov_sendresp: cookie=rid=100,csn=20111024163642.366733Z#000000#0 00#000000

Oct 24 22:12:39 zimbrastore2 postfix/smtpd[29558]: disconnect from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:14:25 10.11.12.211 slapd[3310]: do_syncrep2: rid=100 cookie=rid=100,csn=20111024163642.366733Z#000000#0 00#000000

Oct 24 22:14:31 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x3119bc52 20111024163642.366733Z#000000#000#000000

Oct 24 22:12:47 zimbrastore2 postfix/smtpd[24765]: connect from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:14:31 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x20337960 20111024163642.366733Z#000000#000#000000

Oct 24 22:14:31 10.11.12.211 slapd[3310]: syncrepl_message_to_op: rid=100 be_modify uid=kr0050609,ou=people,dc=mysubdomain,dc=com (0)

Oct 24 22:14:37 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x29722658 20111024163646.347211Z#000000#000#000000

Oct 24 22:14:42 10.11.12.210 slapd[4422]: syncprov_sendresp: cookie=rid=100,csn=20111024163646.347211Z#000000#0 00#000000

Oct 24 22:13:02 zimbrastore2 postfix/cleanup[24770]: 54BB7244F99: message-id=<20111024164134.54BB7244F99@cluster.mysubdomain .com>

Oct 24 22:14:54 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x445522c0 20111024163654.559547Z#000000#000#000000

Oct 24 22:15:00 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x2961f658 20111024163654.559547Z#000000#000#000000

Oct 24 22:15:05 10.11.12.210 slapd[4422]: syncprov_sendresp: cookie=rid=100,csn=20111024163654.559547Z#000000#0 00#000000

Oct 24 22:13:09 zimbrastore2 postfix/qmgr[25166]: 927DA244F94: removed

Oct 24 22:13:16 zimbrastore2 postfix/smtpd[30097]: connect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:15:16 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x44d532c0 20111024163708.082799Z#000000#000#000000

Oct 24 22:13:23 zimbrastore2 postfix/smtpd[30108]: connect from smtp.chand.mydomain.com[10.3.0.150]
Oct 24 22:15:22 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x29722658 20111024163708.082799Z#000000#000#000000
Oct 24 22:13:25 zimbrastore2 postfix/smtpd[30114]: connect from smtp.chand.mydomain.com[10.3.0.150]
Oct 24 22:13:27 zimbrastore2 zmmailboxdmgr[29528]: status OK
Oct 24 22:13:33 zimbrastore2 zmmailboxdmgr[30019]: status requested


Oct 24 22:13:44 zimbrastore2 postfix/smtpd[28306]: disconnect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:13:49 zimbrastore2 postfix/smtpd[24765]: lost connection after CONNECT from zimbrastore1.mysubdomain.com[10.11.12.206]

Oct 24 22:14:07 zimbrastore2 postfix/pickup[5204]: 6FDC8244F94: uid=0 from=<root>

Oct 24 22:14:25 zimbrastore2 postfix/qmgr[25166]: AC726244FCE: from=<PX0079536@mydomain.com>, size=2691701, nrcpt=1 (queue active)

Oct 24 22:14:25 zimbrastore2 postfix/lmtp[29835]: 51629244FB2: to=<lk0067273@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=850, delays=638/211/0.07/0.34, dsn=2.1.5, status=sent (250 2.1.5 Delivery OK)

Oct 24 22:14:25 zimbrastore2 postfix/smtpd[30097]: B657E244FAC: client=smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:14:28 zimbrastore2 postfix/smtpd[29558]: connect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:14:31 zimbrastore2 postfix/smtpd[30108]: A1C35244FAE: client=smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:14:31 zimbrastore2 postfix/smtpd[30114]: BDFDC244FE9: client=smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:14:46 zimbrastore2 postfix/smtpd[30251]: connect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:14:42 zimbrastore2 zmmailboxdmgr[30019]: status OK



Oct 24 22:15:05 zimbrastore2 postfix/smtpd[24765]: disconnect from zimbrastore1.
mysubdomain.com[10.11.12.206]

Oct 24 22:15:39 zimbrastore2 postfix/cleanup[27104]: 6FDC8244F94: message-id=<20111024164407.6FDC8244F94@cluster.mysubdomain .com>

Oct 24 22:15:52 zimbrastore2 postfix/qmgr[25166]: BF54E244FC9: removed

Oct 24 22:15:52 zimbrastore2 postfix/lmtp[27848]: C9F8E244F8C: to=<pd0082421@mysubdomain.com>, relay=cluster.mysubdomain.com[10.11.12.205]:7025, delay=2738, delays=2486/252/0.07/0.16, dsn=4.2.2, status=deferred (host cluster.mysubdomain.com[10.11.12.205] said: 452 4.2.2 Over quota (in reply to end of DATA command))

Oct 24 22:15:57 zimbrastore2 postfix/smtpd[30097]: lost connection after RCPT from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:16:03 zimbrastore2 postfix/smtpd[29558]: disconnect from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:16:09 zimbrastore2 postfix/smtpd[30108]: lost connection after RCPT from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:17:40 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x42d4f2c0 20111024163837.697377Z#000000#000#000000

Oct 24 22:16:15 zimbrastore2 postfix/smtpd[30114]: lost connection after RCPT from smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:17:41 10.11.12.210 slapd[4422]: slap_queue_csn: queing 0x23081658 20111024163837.697377Z#000000#000#000000

Oct 24 22:16:15 zimbrastore2 zmmailboxdmgr[30220]: status requested

Oct 24 22:17:46 10.11.12.210 slapd[4422]: syncprov_sendresp: cookie=rid=100,csn=20111024163837.697377Z#000000#0 00#000000

Oct 24 22:17:47 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x2dec86c0 20111024163837.697377Z#000000#000#000000

Oct 24 22:16:15 zimbrastore2 postfix/smtpd[30251]: B2C91244FC9: client=smtp.chand.mydomain.com[10.3.0.150]

Oct 24 22:17:53 10.11.12.210 slapd[4422]: slap_graduate_commit_csn: removing 0x2e21dd50 20111024163837.697377Z#000000#000#000000

Oct 24 22:16:16 zimbrastore2 zimbramon[30539]: 30539:info: Stopping services initiated by zmcontrol

Oct 24 22:17:58 10.11.12.211 slapd[3310]: do_syncrep2: rid=100 cookie=rid=100,csn=20111024163837.697377Z#000000#0 00#000000

Oct 24 22:17:59 10.11.12.211 slapd[3310]: slap_queue_csn: queing 0x3118db53 20111024163837.697377Z#000000#000#000000

Oct 24 22:18:05 10.11.12.211 slapd[3310]: slap_graduate_commit_csn: removing 0x310b5660 20111024163837.697377Z#000000#000#000000

Oct 24 22:18:10 10.11.12.211 slapd[3310]: syncrepl_message_to_op: rid=100 be_modify uid=ps0068775,ou=people,dc=mysubdomain,dc=com (0)

[Klug]

I did not read your cut/paste log.
But I just wanted to say that because of this kind of behaviour, we moved away from RHCS for all customers we previously set it up...

Most customers migrate to a VM and use the "VM software supplier tools" to handle HA (VMware vSphere, Citrix XenServer, etc).

One of them migrated to a "manual cluster" : two servers (one runnning the other shut down) and one DAS. In cas of failure of the running server, it's shut down, the DAS is manually connected to the other server and this one is started.