One node's cluster suddenly terminated.
Below is the message in cluster's alert.log：
2012-09-11 11:41:30.328
[ctssd(22428)]CRS-2409:The clock on host node8 is not synchronous with the mean cluster time. No action has been taken as the Cluster Time Synchroniza
tion Service is running in observer mode.
2012-09-11 12:30:03.122
[cssd(21061)]CRS-1606:The number of voting files available, 0, is less than the minimum number of voting files required, 1, resulting in CSSD termination to
ensure data integrity; details at (:CSSNM00018:) in /prod/grid/11.2.0/grid/log/node8/cssd/ocssd.log
2012-09-11 12:30:03.123
[cssd(21061)]CRS-1656:The CSS daemon is terminating due to a fatal error; Details at (:CSSSC00012:) in /prod/grid/11.2.0/grid/log/node8/cssd/ocssd.log
2012-09-11 12:30:03.233 [cssd(21061)]CRS-1652:Starting clean up of CRSD resources.
Let‘s check ocssd.log：
2012-09-11 12:30:02.543: [ CSSD][1113450816]clssnmSendingThread: sending status msg to all nodes
2012-09-11 12:30:02.543: [ CSSD][1113450816]clssnmSendingThread: sent 5 status msgs to all nodes
2012-09-11 12:30:03.122: [ CSSD][1082489152](:CSSNM00018:)clssnmvDiskCheck: Aborting, 0 of 1 configured voting disks available, need 1
2012-09-11 12:30:03.123: [ CSSD][1082489152]###################################
2012-09-11 12:30:03.123: [ CSSD][1082489152]clssscExit: CSSD aborting from thread clssnmvDiskPingMonitorThread
2012-09-11 12:30:03.123: [ CSSD][1082489152]###################################
2012-09-11 12:30:03.123: [ CSSD][1082489152](:CSSSC00012:)clssscExit: A fatal error occurred and the CSS daemon is terminating abnormally
So it looks like an IO issue to VOTEDISK.
But after checking we didn't find any abnormal or error message from neither OS level nor storage side.
Then i reviewed the ocssd.log, and with surprise i found there is no long-disk timeout countdown in log.
We know if ocssd failed to reach Votedisk, then it will start to count 200s. Only if after 200s the votedisk still unavailable, then occsd will terminated itself.
The countdown information should be like:
clssscMonitorThreads clssnmvDiskPingThread not scheduled for 16020 msecs
But in our case, there is not such countdown, the occssd just terminated from clssnmvDiskPingMonitorThread all of a sudden.
It should be a bug instead of VOTEDISK IO issue. I will raise an SR with oracle support for further checking.
More......
GE, AGFA. experienced in 9i/10g/11g/12c, AdvanceReplication, Stream, GoldenGate, RAC, DataGuard, ODA, EXADATA, GridControl. In my career I have always been assigned to handle most complicated and critical oracle issues without solution online, and I hope to record some of them via this blog.
September 12, 2012
CSSD terminated from clssnmvDiskPingMonitorThread without disk timeout countdown
June 11, 2012
CSSD died with no error during GM grock activity
Recently i observed one node crashed and rebooted case: during the node's clusterware starting, its CSSD suddenly died during GM(Group Management) grock activity without any error. And server got a reboot because of that.
CSSD shows no errors:
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(0) msgseq(1), lastupdt<(nil)>, ignoreseq(0)
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmAddMember: granted member(0) flags(0x2) node(3) grock (0x2aaab0063ac0/CLSN.oratab)
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmCommonAddMember: global lock grock CLSN.oratab member(0/Remote) node(3) flags 0x2 0xb00c1df0
2012-06-08 09:18:10.495: [ CSSD][1106151744]clssgmHandleGrockRcfgUpdate: grock(CLSN.oratab), updateseq(1), status(0), sendresp(1)
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(1) msgseq(2), lastupdt<0x2aaab0054dc0>, ignoreseq(0)
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmRemoveMember: grock CLSN.oratab, member number 0 (0x2aaab00c1df0) node number 3 state 0x0 grock type 3
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmResetGrock: grock(CLSN.oratab) reset=1
2012-06-08 09:18:10.533: [ CSSD][1106151744]clssgmHandleGrockRcfgUpdate: grock(CLSN.oratab), updateseq(2), status(0), sendresp(1)
2012-06-08 09:18:10.535: [ CSSD][1106151744]clssgmTestSetLastGrockUpdate: grock(CLSN.oratab), updateseq(2) msgseq(3), lastupdt<0x2aaab0097f50>, ignoreseq(0)
2012-06-08 09:18:10.535: [ CSSD][1106151744]clssgmDeleteGrock: (0x2aaab0063ac0) grock(CLSN.oratab) deleted
<<----here CSSD died, it was doing some GM grock maintance and suddenly died and then server reboot, here we see no abnormal information---->>
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = CSSD, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCNM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCGM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GIPCCM, LogLevel = 2, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = CLSF, LogLevel = 0, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = SKGFD, LogLevel = 0, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = GPNP, LogLevel = 1, TraceLevel = 0
2012-06-08 09:28:30.052: [ CSSD][684039456]clsu_load_ENV_levels: Module = OLR, LogLevel = 0, TraceLevel = 0
[ CSSD][684039456]clsugetconf : Configuration type [4].
2012-06-08 09:28:30.052: [ CSSD][684039456]clssscmain: Starting CSS daemon, version 11.2.0.2.0, in (clustered) mode with uniqueness value 1339162110
Very soon CSSDMONITOR found the CSSD had died so it then sync (reboot) the node. Below is from CSSDMONITOR log:
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssRecvMsg: got a disconnect from the server while waiting for message type 27
2012-06-08 09:18:12.479: [ CSSCLNT][1113389376]clsssRecvMsg: got a disconnect from the server while waiting for message type 22
2012-06-08 09:18:12.479: [ USRTHRD][1113389376] clsnwork_queue: posting worker thread
2012-06-08 09:18:12.479: [ USRTHRD][1113389376] clsnpollmsg_main: exiting check loop
2012-06-08 09:18:12.479: [GIPCXCPT][1116543296]gipcInternalSend: connection not valid for send operation endp 0x86da430 [0000000000000162] { gipcEndpoint : l
ocalAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=)(GIPCID=031d7676-63f8ad6d-9852))', remoteAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_cihcissdb759_)(GIPCI
D=63f8ad6d-031d7676-9884))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0, pidPeer 9884, flags 0x3861e, usrFlags 0x20010 }, ret g
ipcretConnectionLost (12)
2012-06-08 09:18:12.479: [GIPCXCPT][1116543296]gipcSendSyncF [clsssServerRPC : clsss.c : 6271]: EXCEPTION[ ret gipcretConnectionLost (12) ] failed to send o
n endp 0x86da430 [0000000000000162] { gipcEndpoint : localAddr 'clsc://(ADDRESS=(PROTOCOL=ipc)(KEY=)(GIPCID=031d7676-63f8ad6d-9852))', remoteAddr 'clsc://(AD
DRESS=(PROTOCOL=ipc)(KEY=OCSSD_LL_cihcissdb759_)(GIPCID=63f8ad6d-031d7676-9884))', numPend 0, numReady 0, numDone 0, numDead 0, numTransfer 0, objFlags 0x0,
pidPeer 9884, flags 0x3861e, usrFlags 0x20010 }, addr 0000000000000000, buf 0x428d0d80, len 80, flags 0x8000000
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssServerRPC: send failed with err 12, msg type 7
2012-06-08 09:18:12.479: [ CSSCLNT][1116543296]clsssCommonClientExit: RPC failure, rc 3
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clsssRecvMsg: got a disconnect from the server while waiting for message type 1
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clssgsGroupGetStatus: communications failed (0/3/-1)
2012-06-08 09:18:12.479: [ CSSCLNT][1094465856]clssgsGroupGetStatus: returning 8
2012-06-08 09:18:12.479: [ USRTHRD][1114966336] clsnwork_process_work: calling sync
2012-06-08 09:18:12.479: [ USRTHRD][1094465856] clsnomon_status: Communications failure with CSS detected. Waiting for sync to complete...
Checked OS log and no errors gernerate during that period of time:
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1 ]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:27643
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:26972
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:26972
Jun 8 09:18:02 node759 snmpd[21008]: Connection from UDP: [127.0.0.1]:17368
Jun 8 09:18:02 node759 snmpd[21008]: Received SNMP packet(s) from UDP: [127.0.0.1]:17368
<<<----here suddenly rebooted with no information----->>>
Jun 8 09:23:03 node759 syslogd 1.4.1: restart.
Jun 8 09:23:03 node759 kernel: klogd 1.4.1, log source = /proc/kmsg started.
Jun 8 09:23:03 node759 kernel: g enabled (TM1)
Jun 8 09:23:03 node759 kernel: Intel(R) Xeon(R) CPU X7550 @ 2.00GHz stepping 06
Jun 8 09:23:03 node759 kernel: CPU 3: Syncing TSC to CPU 0.
Jun 8 09:23:03 node759 kernel: CPU 3: synchronized TSC with CPU 0 (last diff -6 cycles, maxerr 477 cycles)
Jun 8 09:23:03 node759 kernel: SMP alternatives: switching to SMP code
Jun 8 09:23:03 node759 kernel: Booting processor 4/32 APIC 0x10
Jun 8 09:23:03 node759 kernel: Initializing CPU#4
Searched on network, only find one bug report describle an similiar issue:
Bug 13954099: CSSD DIES SUDDENLY WITHOUT ANY ERRORS
Just like our case, In the bug report, cluster version is also 11.2.0.2, and the CSSD died during a GM grock activity without any errors.
Then CSSD monitor rebooted the node after found that CSSD died.
This problem is not repeatable, the next time we re-bring up the cluster on the node, it succeed. The issue not happen again.
No Patch avialable as yet.
More......
June 2, 2012
what will happen if we hang CSSD process in Rac
in 11gR2, we have many new background processes including two cssd related processes cssdmonitor and cssdagent. cssdagent process is charge of respawn cssd.bin.
And both of those processes are charge of monitor cssd state and system hang problem.
[root@node1 node1]# ps -ef|grep cssd
root 479 1 0 00:30 ? 00:00:01 /prod/grid/app/11.2.0/grid/bin/cssdmonitor
root 471 1 0 00:30 ? 00:00:01 /prod/grid/app/11.2.0/grid/bin/cssdagent
grid 568 1 0 00:30 ? 00:00:04 /prod/grid/app/11.2.0/grid/bin/ocssd.bin
Let's see what will happen if we hang the ocssd.bin process:
[root@node1 ~]# kill -SIGSTOP 568
[root@node1 ~]# kill -SIGSTOP 568
[root@node1 ~]# kill -SIGSTOP 568
After a few seconds the node got a reboot. Let's go to check the log. We can find below information in alert$hostname.log:
2012-05-27 09:39:01.558
[ohasd(4545)]CRS-8011:reboot advisory message from host: node1, component: mo224552, with time stamp: L-2012-02-05-22:51:26.126
[ohasd(4545)]CRS-8013:reboot advisory message text: clsnomon_status: need to reboot, unexpected failure 8 received from CSS
2012-05-27 09:39:01.634
[ohasd(4545)]CRS-8011:reboot advisory message from host: node1, component: ag014510, with time stamp: L-2012-05-26-05:35:13.032
[ohasd(4545)]CRS-8013:reboot advisory message text: Rebooting after limit 28500 exceeded; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 28541 milliseconds ago based on invariant clock value of 57493073
2012-05-26 05:34:53.160: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 50% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 14871 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
2012-05-26 05:35:02.748: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 75% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 21401 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
2012-05-26 05:35:08.907: [ USRTHRD][2915036048] clsnproc_needreboot: Impending reboot at 90% of limit 28500; disk timeout 28180, network timeout 28500, last heartbeat from CSSD at epoch seconds 1337981671.618, 25681 milliseconds ago based on invariant clock 57493073; now polling at 100 ms
Since cssd was hang, so cssd itself's log won't have any information:
2012-05-26 05:34:25.052: [ CSSD][2894060432]clssnmSendingThread: sending status msg to all nodes
2012-05-26 05:34:25.052: [ CSSD][2894060432]clssnmSendingThread: sent 4 status msgs to all nodes
2012-05-26 05:34:30.525: [ CSSD][2894060432]clssnmSendingThread: sending status msg to all nodes
2012-05-26 05:34:30.525: [ CSSD][2894060432]clssnmSendingThread: sent 4 status msgs to all nodes
----HERE REBOOTED----2012-05-27 09:39:24.030: [ CSSD][3046872768]clssscmain: Starting CSS daemon, version 11.2.0.1.0, in (clustered) mode with uniqueness value 1306460363
2012-05-27 09:39:24.032: [ CSSD][3046872768]clssscmain: Environment is productionMore......