Troubleshooting Oracle RAC node OS shutdown (‘crsctl stop crs -f’) cause db instance stop on another node
2023年第一个Oracle 19C故障有点稀奇,如果oracle告诉你尽可能少频率crsctl stop crs -f可以减少它意外停下了其它节点的db instance resource,是不是有点像“很久前”专家说的尽可能少感染? 我们知道当强制关闭CRS stack或CRS 部分资源未启动正常无法关闭CRS(crsctl stop crs)时加上选项“-f”, 但它应该也是只关闭本地节点,如果没有先关CRS,而直接关闭OS也是会自动触发“-f”方式关闭CRS,近期模拟一次OS故障,在一套RAC刚好要停一个node 更换内存需求时,我们只关闭了node1上的db instace,当然此时业务不受影响,node2上的实例正常依旧可以对外提供服务, 1小时后OS组准备就绪,在节点1关闭操作系统,同步收到了业务无法访问,查看node2 db实例已自动shutdown, 其它资源正常,手动立即起动db实例2恢复业务,刺激,为什么停实例1 CRS会触发停实例2 的db instance?
# inst2 db alert log
2023-01-12T23:40:10.987312+08:00 Thread 2 advanced to log sequence 168441 (LGWR switch), current SCN: 17859223670498 Current log# 12 seq# 168441 mem# 0: +DATADG/oradb/ONLINELOG/group_12.1019.1073731163 2023-01-12T23:40:11.645014+08:00 TT02 (PID:28936): SRL selected for T-2.S-168441 for LAD:2 2023-01-12T23:40:20.742418+08:00 ARC2 (PID:28824): Archived Log entry 486218 added for T-2.S-168440 ID 0xe50b355f LAD:1 2023-01-12T23:47:32.092036+08:00 Thread 2 advanced to log sequence 168442 (LGWR switch), current SCN: 17859228371436 Current log# 7 seq# 168442 mem# 0: +DATADG/oradb/ONLINELOG/group_7.1024.1073731121 2023-01-12T23:47:32.448516+08:00 TT02 (PID:28936): SRL selected for T-2.S-168442 for LAD:2 2023-01-12T23:47:41.895431+08:00 ARC3 (PID:28864): Archived Log entry 486220 added for T-2.S-168441 ID 0xe50b355f LAD:1 2023-01-12T23:51:08.224823+08:00 Shutting down ORACLE instance (abort) (OS id: 123812) <<<<<<<<<<<<<<<<<<<<<<<<<<<<< 2023-01-12T23:51:08.225249+08:00 Shutdown is initiated by oraagent.bin@anbob2 (TNS V1-V3). License high water mark = 4976 USER (ospid: 123812): terminating the instance 2023-01-12T23:51:08.226280+08:00 opiodr aborting process unknown ospid (46356) as a result of ORA-1092 2023-01-12T23:51:08.226285+08:00 opiodr aborting process unknown ospid (38421) as a result of ORA-1092 2023-01-12T23:51:08.226791+08:00 2023-01-12T23:51:12.772187+08:00 Termination issued to instance processes. Waiting for the processes to exit, wait time 5 sec 2023-01-12T23:51:13.883173+08:00 ORA-1092 : opitsk aborting process 2023-01-12T23:51:15.831282+08:00 Instance terminated by USER, pid = 123812 2023-01-12T23:51:17.953922+08:00 Instance shutdown complete (OS id: 123812)
# node1 gi alert LOG
2023-01-12 23:51:08.116 [OHASD(120049)]CRS-2791: Starting shutdown of Oracle High Availability Services-managed resources on 'anbob1'
2023-01-12 23:51:19.246 [ORAROOTAGENT(55993)]CRS-5822: Agent '/oracle/app/19c/grid/bin/orarootagent_root' disconnected from server. Details at (:CRSAGF00117:) {0:2:46020} in /oracle/app/grid/diag/crs/anbob1/crs/trace/crsd_orarootagent_root.trc.
2023-01-12 23:51:19.249 [ORAAGENT(70863)]CRS-5822: Agent '/oracle/app/19c/grid/bin/oraagent_grid' disconnected from server. Details at (:CRSAGF00117:) {0:4:10987} in /oracle/app/grid/diag/crs/anbob1/crs/trace/crsd_oraagent_grid.trc.
2023-01-12 23:51:21.911 [MDNSD(124573)]CRS-5602: mDNS service stopping by request.
2023-01-12 23:51:22.529 [MDNSD(124573)]CRS-8504: Oracle Clusterware MDNSD process with operating system process ID 124573 is exiting
2023-01-12 23:52:07.494 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk55; details at (:CSSNM00059:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk53; details at (:CSSNM00059:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk53; details at (:CSSNM00060:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.494 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk55; details at (:CSSNM00060:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk52; details at (:CSSNM00059:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk54; details at (:CSSNM00059:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk52; details at (:CSSNM00060:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.495 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk54; details at (:CSSNM00060:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.496 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk56; details at (:CSSNM00060:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:07.496 [OCSSD(909)]CRS-1649: An I/O error occurred for voting file: /dev/asm-disk56; details at (:CSSNM00059:) in /oracle/app/grid/diag/crs/anbob1/crs/trace/ocssd.trc.
2023-01-12 23:52:20.684 [OCTSSD(14604)]CRS-2405: The Cluster Time Synchronization Service on host anbob1 is shutdown by user
2023-01-12 23:52:20.685 [OCTSSD(14604)]CRS-8504: Oracle Clusterware OCTSSD process with operating system process ID 14604 is exiting
2023-01-12 23:52:21.693 [OCSSD(909)]CRS-1603: CSSD on node anbob1 has been shut down.
2023-01-12 23:52:24.697 [GPNPD(125353)]CRS-2329: GPNPD on node anbob1 shut down.
2023-01-12 23:52:25.702 [OHASD(120049)]CRS-2793: Shutdown of Oracle High Availability Services-managed resources on 'anbob1' has completed
2023-01-12 23:52:25.856 [ORAROOTAGENT(123141)]CRS-5822: Agent '/oracle/app/19c/grid/bin/orarootagent_root' disconnected from server. Details at (:CRSAGF00117:) {0:1:13} in /oracle/app/grid/diag/crs/anbob1/crs/trace/ohasd_orarootagent_root.trc.
2023-01-12 23:52:25.856 [ORAAGENT(124185)]CRS-5822: Agent '/oracle/app/19c/grid/bin/oraagent_grid' disconnected from server. Details at (:CRSAGF00117:) {0:5:173} in /oracle/app/grid/diag/crs/anbob1/crs/trace/ohasd_oraagent_grid.trc.
2023-01-12 23:52:25.865 [CRSCTL(77606)]CRS-8503: Oracle Clusterware process CRSCTL with operating system process ID 77606 experienced fatal signal or exception code 6.
# node2 oraagent_oracle
m_pConnxn:0x7fffac000910
2023-01-12 23:51:04.634 : USRTHRD:3838891776: [ INFO] {2:11173:58088} Thread:DedicatedThread DbAgent::DedicatedThread::run 380 m_stopnow:0 m_restart:0 setLsnrs:0 m_pConnxn:0x7fffac000910
2023-01-12 23:51:08.155 : AGFW:3852338944: [ INFO] {1:1586:64227} Agent received the message: RESOURCE_STOP[ora.oradb.db 2 1] ID 4099:33321960 <<<<<<<<<<<<<
2023-01-12 23:51:08.155 : AGFW:3852338944: [ INFO] {1:1586:64227} Preparing STOP command for: ora.oradb.db 2 1
2023-01-12 23:51:08.155 : AGFW:3852338944: [ INFO] {1:1586:64227} ora.oradb.db 2 1 state changed from: ONLINE to: STOPPING
2023-01-12 23:51:08.156 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] (:CLSN00108:) clsn_agent::stop {
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::getStopModeAttrib stop mode immediate option 1
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 000 {
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs attrib: CRS_ORIGINAL_REASON compare value: system attribute value: system
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs returns 1
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 040 isClean:0 or original reason is system - stopOption:ABORT
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 120 shutdown mode:4
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] DbAgent::preStopCbk {
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] DbAgentEventModule::stop stopping event bridge
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] DbAgentEventModule::stop stopping rlb event bridge
2023-01-12 23:51:08.157 :CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] DbAgent::preStopCbk dThread stop
2023-01-12 23:51:08.157 : USRTHRD:3836790528: [ INFO] {1:1586:64227} Thread:DedicatedThread DbAgent::DedicatedThread::stop entry
2023-01-12 23:51:08.157 : USRTHRD:3836790528: [ INFO] {1:1586:64227} Thread:DedicatedThread DbAgent::DedicatedThread::abortConnxn entry lock connectionLock:c404bc98
2023-01-12 23:51:08.157 : USRTHRD:3836790528: [ INFO] {1:1586:64227} InstConnection::breakCall this:0x7fffac000910 get DetachLock:0x55555a135aa8 m_pSrvH:0x7fffac1461d0, m_pSvcH:0x7fffac1451c0
# node1 Crsd log
# sed -n '/2023-01-12/,/2023-01-13 00:16:/p' crsd.trc.log |grep -i stop|grep -v StopRGO|grep 2673
2023-01-12 23:51:08.145 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.LISTENER.lsnr' on 'anbob1'
2023-01-12 23:51:08.146 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.LISTENER_1529.lsnr' on 'anbob1'
2023-01-12 23:51:08.146 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.chad' on 'anbob1'
2023-01-12 23:51:08.149 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.ARCHDG.dg' on 'anbob1'
2023-01-12 23:51:08.150 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.DATADG.dg' on 'anbob1'
2023-01-12 23:51:08.152 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.OCRDG.dg' on 'anbob1'
2023-01-12 23:51:08.153 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.MGMTDG.dg' on 'anbob1'
2023-01-12 23:51:08.155 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.oradb.db' on 'anbob2' <<<<<<<<<<<<<<<
2023-01-12 23:51:08.231 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.asm' on 'anbob1'
2023-01-12 23:51:08.379 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.anbob1.vip' on 'anbob1'
2023-01-12 23:51:09.039 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.ASMNET1LSNR_ASM.lsnr' on 'anbob1'
2023-01-12 23:51:13.169 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.asmnet1.asmnetwork' on 'anbob1'
2023-01-12 23:51:19.167 : CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2673: Attempting to stop 'ora.net1.network' on 'anbob1'
# 聚合日志
2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} dependency = STOP_DEPENDENCIES, target = hard(global:intermediate:ora.asm,global:shutdown:ora.ARCHDG.dg,global:shutdown:ora.DATADG.dg,global:shutdown:ora.MGMTDG.dg,global:shutdown:ora.OCRDG.dg, global:shutdown:ora.BAKDG.dg) 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log===== 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.logAFTER being processed: 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log===== 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log----- 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.logMODIFIED DEPENDENCY MAP for START_DEPENDENCIES: 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log----- 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} dependency = hard, target = uniform:global:ora.ARCHDG.dg,uniform:global:ora.DATADG.dg,uniform:global:ora.MGMTDG.dg,uniform:global:ora.OCRDG.dg, global:uniform:ora.BAKDG.dg 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} dependency = pullup, target = global:ora.ARCHDG.dg,global:ora.DATADG.dg,global:ora.MGMTDG.dg,global:ora.OCRDG.dg, global:ora.BAKDG.dg 2023-01-12 23:39:21.777../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} dependency = weak, target = type:ora.listener.type,global:type:ora.scan_listener.type,uniform:ora.ons,global:ora.gns, global:uniform:ora.LOGDG.dg 2023-01-12 23:39:21.779../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} Update attr: MANAGEMENT_POLICY 2023-01-12 23:39:21.779../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} Update attr: NAME 2023-01-12 23:39:21.779../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} Update attr: START_DEPENDENCIES 2023-01-12 23:39:21.779../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17842} Update attr: STOP_DEPENDENCIES ... 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Utils::getResAttrib: attribname USR_ORA_OPI value false len 5 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Utils::getResAttrib attribname:USR_ORA_OPI value:false exit 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs attrib: REASON compare value: user attribute value: dependency <<<<<<<<<<<<<<<<<<<<< 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs returns 0 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs attrib: CRS_ORIGINAL_REASON compare value: tha attribute value: system 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] Agent::valueOfAttribIs returns 0 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 810 isFenceSet:0 container stop 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 811 container stop isShutdown:1 2023-01-12 23:51:17.954../crsd/trace/crsd_oraagent_oracle_85.log:CLSDYNAM:3836790528: [ora.oradb.db]{1:1586:64227} [stop] InstAgent::stop 820 fence is not set 2023-01-12 23:51:17.962../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17890} Expression Filter : (((((STATE == ONLINE) OR (STATE == INTERMEDIATE)) OR (STATE == UNKNOWN)) AND ((NAME == ora.oradb.db) AND (LAST_SERVER == anbob2))) AND (STATE_DETAILS co Under THA)) 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17890} Stop cmd 0x7fff1c481b30 creating ops... 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17890} PE Command [ Stop Resource : 0x7fff1c481b30 ] has completed 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {2:11173:17890} UI Command [Stop Resource : 0x7fff1c481b30] is replying to sender. 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {1:1586:64227} Received reply to action [Stop] message ID: 33321959 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {1:1586:64227} RI [ora.oradb.db 2 1] new internal state: [STABLE] old value: [STOPPING] 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {1:1586:64227} RI [ora.oradb.db 2 1] new external state [OFFLINE] old value: [ONLINE] on anbob2 label = [Instance Shutdown] 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {1:1586:64227} Set State Details to [Instance Shutdown] from [ Open,HOME=/oracle/app/oracle/product/19c/db_1] for [ora.oradb.db 2 1] 2023-01-12 23:51:17.967../crsd/trace/crsd.trc.log: CRSPE:2342504192: [ INFO] {1:1586:64227} CRS-2677: Stop of 'ora.oradb.db' on 'anbob2' succeeded
从上面Node 1 crsd log中确实看到,在stop node1 crs的资源时主动stop 节点2的db resource “Attempting to stop ‘ora.oradb.db’ on ‘anbob2′”. 可知的一种情况比如db resource的STOP_DEPENDENCIES global中依赖一个ASM diskgroup, 并且node2上该ASM diskgroup 已经offline, 12C 后的FLEX ASM特性比如此时即使有数据文件该磁盘组上,db instance也可以通过asm listener访问远程节点上的ASM instance上正常的ASM DISKGROUP, 而此时如果NODE1 上的做为最后的可用的ASM diskgroup,那在stop crs时确实可以触发依赖对象其它实例的db instance.
但是, 我们也确认node2数据库所依赖的文件ASM DISKGROUP在node2上是ONline. 不过Oracle CRS资源中的STOP_DEPENDENCIES是只增加不会减少,比如我们把一个数据库文件放到一个新创建的ASM DISKGROUP中,此时会在db STOP_DEPENDENCIES中增加该ASM DG资源,但是把文件移除后STOP_DEPENDENCIES并不会自动清理。 这个环境我们分析后确实除了数据库文件外还有国内某备份软件在备份时会只在1个节点上mount 一组ASM diskgroup , 会STOP_DEPENDENCIES增加2组ASM DG,备份完成后会把2组日志dismount force. 而问题时间正好有备份任务从node1 切换到了node2上正在执行,ASM DISKGROUP bakdg只在Node2 是mounted. 该问题反馈给ORACLE后,确认是有未公开 Bug 32075956 – DI:”CRSCTL STOP CRS ” ON LOCAL NODE SHOULDN’T CAUSE THE SHUTDOWN OF THE INSTANCES ON THE REMOTE NODE 引起,触发条件是crsctl stop crs -f时当有资源仅在一个节点挂载时会误关闭db instance resource, 在19.18 RU中包含该补丁,解决是当本案例中在node1 stop crs -f时即使ASM DISKGROUP 只在node2 上online, 会拒绝错误的关闭node2上的db instance.
这套国产备份软件上一个故障是《Troubleshooting DB hang, v$asm_diskgroup query hang due to ASM I/O hang案例》
对不起,这篇文章暂时关闭评论。