SYSTEM.credentials.domains.root.ASM.Self.XXXX.root not found
1. Phenomenon
Oracle 12.2.0.1.0 cluster cannot be started after shutdown.
CRS status check is stuck in storage starting, and other resources cannot be started
[root@db2 ~]# /oracle/product/12.2.0.1/grid/bin/crsctl status res -t -init
--------------------------------------------------------------------------------
Name Target State Server State details
--------------------------------------------------------------------------------
Cluster Resources
--------------------------------------------------------------------------------
ora.asm
1 ONLINE ONLINE xd1archdb2 STABLE
ora.cluster_interconnect.haip
1 ONLINE ONLINE xd1archdb2 STABLE
ora.crf
1 ONLINE OFFLINE STABLE
ora.crsd
1 ONLINE OFFLINE STABLE
ora.cssd
1 ONLINE ONLINE xd1archdb2 STABLE
ora.cssdmonitor
1 ONLINE ONLINE xd1archdb2 STABLE
ora.ctssd
1 ONLINE ONLINE xd1archdb2 OBSERVER,STABLE
ora.diskmon
1 OFFLINE OFFLINE STABLE
ora.driver.afd
1 ONLINE ONLINE xd1archdb2 STABLE
ora.drivers.acfs
1 ONLINE ONLINE xd1archdb2 STABLE
ora.evmd
1 ONLINE INTERMEDIATE xd1archdb2 STABLE
ora.gipcd
1 ONLINE ONLINE xd1archdb2 STABLE
ora.gpnpd
1 ONLINE ONLINE xd1archdb2 STABLE
ora.mdnsd
1 ONLINE ONLINE xd1archdb2 STABLE
ora.storage
1 ONLINE OFFLINE xd1archdb2 STARTING <===================
--------------------------------------------------------------------------------
The last point in the alert log of crs[ORAROOTAGENT(199820)]CRS-5019: All OCR locations are on ASM disk groups [OCR_VOTE], and none of these disk groups are mounted. Details are at "(:CLSN00140:)" in "/oracle/gridbase/diag/crs/xd1archdb2/crs/trace/ohasd_orarootagent_root.trc".
Checking this log, you can see
2021-11-24 11:15:34.101 : USRTHRD:1556182784: {0:5:3} 8154 Error 4 querying length of attr ASM_STATIC_DISCOVERY_ADDRESS
2021-11-24 11:15:34.136 : CLSCRED:1556182784: (:CLSCRED1079:)clsCredOcrKeyExists: Obj dom : SYSTEM.credentials.domains.root.ASM.Self.9d0ad57d52f57f81bf9bdc78d36d559f.root not found
2021-11-24 11:15:34.136 : USRTHRD:1556182784: {0:5:3} 7872 Error 4 opening dom root in 0x7fc828518480
2021-11-24 11:15:35.190 : default:1556182784: clsCredDomClose: Credctx deleted 0x7fc828228ed0
2021-11-24 11:15:36.207 : CLSNS:1556182784: clsns_SetTraceLevel:trace level set to 1.
2021-11-24 11:15:36.210 : default:1556182784: Inited LSF context: 0x7fc828321c50
2021-11-24 11:15:36.214 : CLSCRED:1556182784: clsCredCommonInit: Inited singleton credctx.
2021-11-24 11:15:36.214 : CLSCRED:1556182784: (:CLSCRED0101:)clsCredDomInitRootDom: Using user given storage context for repository access.
2021-11-24 11:15:36.237 : USRTHRD:1556182784: {0:5:3} 8154 Error 4 querying length of attr ASM_DISCOVERY_ADDRESS
2021-11-24 11:15:36.241 : USRTHRD:1556182784: {0:5:3} 8154 Error 4 querying length of attr ASM_STATIC_DISCOVERY_ADDRESS
2021-11-24 11:15:36.276 : CLSCRED:1556182784: (:CLSCRED1079:)clsCredOcrKeyExists: Obj dom : SYSTEM.credentials.domains.root.ASM.Self.9d0ad57d52f57f81bf9bdc78d36d559f.root not found
2021-11-24 11:15:36.276 : USRTHRD:1556182784: {0:5:3} 7872 Error 4 opening dom root in 0x7fc82834a180
2021-11-24 11:15:37.361 : default:1556182784: clsCredDomClose: Credctx deleted 0x7fc828228ed0
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} -- trace dump on error exit --
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} Error [kgfoAl06] in [kgfokge] at kgfo.c:3115
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} ORA-12547: TNS:lost contact
ORA-12547: TNS:lost contact
ORA-15077: could not locate ASM instance serving a required diskgroup
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} Category: 7
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} DepInfo: 12547
2021-11-24 11:15:37.361 : USRTHRD:1556182784: {0:5:3} -- trace dump end --
SYSTEM.credentials.domains.root.ASM.Self.9d0ad57d52f57f81bf9bdc78d36d559f.root not found,ORA-15077: could not locate ASM instance serving a required diskgroup,Unable to connect to asm instance, although crsctl checks that asm is started. But actually asm is not started
[root@db2 trace]# ps -ef | grep asm
root 206099 200334 0 11:17 pts/2 00:00:00 grep --color=auto asm
2. Cause analysis
ASM did not actually start successfully and could not locate the disk group.
3. Solution
Start the ASM instance manually. run as asm owner
sqlplus/as sysasm
startup
4. Root cause
In this version, ASM has the features of flex ASM. In this environment, the pattern used is flex.
[grid@db1 ~]$ asmcmd
ASMCMD> showclustermode
ASM cluster : Flex mode enabled
ASMCMD> exit
[grid@db1 ~]$ srvctl config asm
ASM home: <CRS home>
Password file: +OCR_VOTE/orapwASM
Backup of Password file:
ASM listener: LISTENER
ASM instance count: 3
Cluster ASM listener: ASMNET1LSNR_ASM
When the ASM server in flex ASM starts, all ASM networks should be connected.
Check ASM listening
[grid@db1 ~]$ lsnrctl status ASMNET1LSNR_ASM
LSNRCTL for Linux: Version 12.2.0.1.0 - Production on 24-NOV-2021 19:00:17
Copyright (c) 1991, 2016, Oracle. All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=ASMNET1LSNR_ASM)))
STATUS of the LISTENER
------------------------
Alias ASMNET1LSNR_ASM
Version TNSLSNR for Linux: Version 12.2.0.1.0 - Production
Start Date 24-NOV-2021 11:10:01
Uptime 0 days 7 hr. 50 min. 15 sec
Trace Level off
Security ON: Local OS Authentication
SNMP OFF
Listener Parameter File /oracle/product/12.2.0.1/grid/network/admin/listener.ora
Listener Log File /oracle/gridbase/diag/tnslsnr/xd1archdb1/asmnet1lsnr_asm/alert/log.xml
Listening Endpoints Summary...
(DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(KEY=ASMNET1LSNR_ASM)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.*.*.111)(PORT=1526)))
(DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.*.*.111)(PORT=1526)))
The listener supports no services
The command completed successfully
You can see that the service is not registered in ASM listening.
Check whether the listening log is visible
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.*.*.111)(PORT=1526)))
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=10.*.*.111)(PORT=1526)))
24-NOV-2021 11:10:03 * (ADDRESS=(PROTOCOL=ipc)(KEY=ASMNET1LSNR_ASM)) * service_register * LsnrAgt * 0
2021-11-24T11:10:06.129013+08:00
24-NOV-2021 11:10:06 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=db1)(USER=grid))(COMMAND=status)(ARGUMENTS=64)(SERVICE=ASMNET1LSNR_ASM)(VERSION=203424000)) * status * 0
2021-11-24T11:10:08.041279+08:00
Incoming connection from 10.*.*.111 rejected
24-NOV-2021 11:10:08 * 12546
TNS-12546: TNS:permission denied
TNS-12560: TNS:protocol adapter error
TNS-00516: Permission denied
Access to another node was also denied
2021-11-24T11:13:50.958237+08:00
Incoming connection from 10.*.*.112 rejected
24-NOV-2021 11:13:50 * 12546
TNS-12546: TNS:permission denied
TNS-12560: TNS:protocol adapter error
TNS-00516: Permission denied
111 and 112 access are denied. Combined with the CRS log on node 112, there is an ora-12547 error. Check the white list of sqlnet.ora and find that its address does not exist in the ACL.
You need to modify sqlnet.ora, add the corresponding address, and restart ASM listening to take effect.