12.2: Rootupgrade.sh Fails With ORA-27300: OS system dependent operation:sslssunreghdlr failed with status: 0

(Doc ID 2327353.1)

Last updated on NOVEMBER 29, 2017

Applies to:

Oracle Database - Enterprise Edition - Version 12.2.0.1 and later
Information in this document applies to any platform.

Symptoms

 

 GI upgraded from 11.2.0.4 to 12.2.0.1, rootupgrade.sh succeeded on one node(node01) and failed on the other node with the below error.

ora.storage is not starting on the second node node02

On second node, rootupgrade.sh execution will show.
.

2017-10-10 20:03:26: OCR is on ASM
2017-10-10 20:03:26: Configured CRS Home: /u01/app/oragrid/12.2.0.1
2017-10-10 20:03:27: Command output:
> CRS-2672: Attempting to start 'ora.asm' on 'node02'
> CRS-2676: Start of 'ora.asm' on 'node02' succeeded
>End Command output
2017-10-10 20:03:27: Start of resource "ora.asm" Succeeded
2017-10-10 20:03:27: Configured CRS Home: /u01/app/oragrid/12.2.0.1
2017-10-10 20:13:37: Command output:
> CRS-2672: Attempting to start 'ora.storage' on 'node02'
> ORA-27300: OS system dependent operation:sslssunreghdlr failed with
status: 0
> ORA-27301: OS failure message: Error 0
> ORA-27302: failure occurred at: sskgpreset1CRS-2674: Start of
'ora.storage' on 'node02' failed
> CRS-2679: Attempting to clean 'ora.storage' on 'node02'
> CRS-2681: Clean of 'ora.storage' on 'node02' succeeded
> CRS-4000: Command Start failed, or completed with errors.
>End Command output
2017-10-10 20:13:37: Configured CRS Home: /u01/app/oragrid/12.2.0.1
2017-10-10 20:13:37: Executing cmd: /u01/app/oragrid/12.2.0.1/bin/crsctl
check resource ora.crsd -init
2017-10-10 20:13:37: Executing cmd: /u01/app/oragrid/12.2.0.1/bin/crsctl
status resource ora.crsd -init
2017-10-10 20:13:38: Command output:

From CRS alert log:

============

2017-10-09 23:08:48.164 [OCTSSD(8257560)]CRS-2407: The new Cluster Time
Synchronization Service reference node is host node01.
2017-10-09 23:08:48.175 [OCTSSD(8257560)]CRS-2401: The Cluster Time
Synchronization Service started on host node02.
2017-10-09 23:08:49.774 [OSYSMOND(24576104)]CRS-8500: Oracle Clusterware
OSYSMOND process is starting with operating system process ID 24576104
2017-10-09 23:09:07.464 [ORAROOTAGENT(15466694)]CRS-5019: All OCR locations
are on ASM disk groups [AFF_DATA_DG01], and none of these disk groups are
mounted. Details are at "(:CLSN00140:)" in
"/u01/oragrid/diag/crs/node02/crs/trace/ohasd_orarootagent_root.trc".
2017-10-09 23:19:02.293 [ORAROOTAGENT(15466694)]CRS-5818: Aborted command
'start' for resource 'ora.storage'. Details at (:CRSAGF00113:) {0:0:156} in
/u01/oragrid/diag/crs/node02/crs/trace/ohasd_orarootagent_root.trc.
2017-10-09 23:19:06.882 [ORAROOTAGENT(15466694)]CRS-5017: The resource action
"ora.storage start" encountered the following error:
2017-10-09 23:19:06.882+Storage agent start action aborted. For details refer
to "(:CLSN00107:)" in
"/u01/oragrid/diag/crs/node02/crs/trace/ohasd_orarootagent_root.trc".
2017-10-09 23:19:06.893 [OHASD(14090470)]CRS-2757: Command 'Start' timed out
waiting for response from the resource 'ora.storage'. Details at
(:CRSPE00221:) {0:0:156} in
/u01/oragrid/diag/crs/node02/crs/trace/ohasd.trc.
2017-10-09 23:20:14.635 [ORAROOTAGENT(15466694)]CRS-5021: Check of storage
failed: details at "(:CLSN00117:)" in
"/u01/oragrid/diag/crs/node02/crs/trace/ohasd_orarootagent_root.trc"
2017-10-09 23:20:20.017 [ORAROOTAGENT(15466694)]CRS-5019: All OCR locations
are on ASM disk groups [AFF_DATA_DG01], and none of these disk groups are
mounted. Details are at "(:CLSN00140:)" in
"/u01/oragrid/diag/crs/node02/crs/trace/ohasd_orarootagent_root.trc"

 .

From ohasd.trc:

=========

command (115429dd0): [ ora.crsd ]
2017-10-09 23:09:02.267 : CRSPE:7197: {0:0:156} Start cmd 115429dd0
creating ops...
2017-10-09 23:09:02.268 : CRSPE:7197: {0:0:156} Evaluating start
of:ora.crsd on [] reason [user] Opts: 2 In pool :0
2017-10-09 23:09:02.272 : CRSPE:7197: {0:0:156} Start cmd 115429dd0
filtering 1 ops...
2017-10-09 23:09:02.273 : CRSPE:7197: {0:0:156} ...Start cmd 115429dd0
created 1 ops
2017-10-09 23:09:02.273 : CRSPE:7197: {0:0:156} Operation 1157e12b0 has 16
WOs
2017-10-09 23:09:02.274 : CRSPE:7197: {0:0:156} RI [ora.crsd 1 1] new
target state: [ONLINE] old value: [OFFLINE]
2017-10-09 23:09:02.274 : CRSPE:7197: {0:0:156} RI [ora.storage 1 1] new
target state: [ONLINE] old value: [OFFLINE]
2017-10-09 23:09:02.276 : CRSOCR:6169: {0:0:156} Multi Write Batch
processing...
2017-10-09 23:09:02.277 : CRSPE:7197: {0:0:156} Deleting RI-pat

From ohasd_orarootagent_root.trc:

=====================

2017-10-09 23:09:13.910 : CLSCRED:2572: (:CLSCRED1079:)clsCredOcrKeyExists:
Obj dom :
SYSTEM.credentials.domains.root.ASM.Self.2b6f2e459308cfbeff5a2fac213c4a84.root
not found
2017-10-09 23:09:13.911 : USRTHRD:2572: {0:0:156} 7755 Error 4 opening dom
root in 1118a8bf0
.
2017-10-09 23:09:13.969 : CSSCLNT:2572: clsssinit: initialized context:
(112ccd530) flags 0x104
2017-10-09 23:09:13.978 : CSSCLNT:2572: clsssterm: terminating context
(112ccd530)
2017-10-09 23:09:13.979 : default:2572: clsCredDomClose: Credctx deleted
111840470
2017-10-09 23:09:13.979 : USRTHRD:2572: {0:0:156} -- trace dump on error exit
--
.
2017-10-09 23:09:13.980 : USRTHRD:2572: {0:0:156} Error [kgfoAl06] in
[kgfokge] at kgfo.c:3083
.
2017-10-09 23:09:13.980 : USRTHRD:2572: {0:0:156} ORA-27300: OS system
dependent operation:sslssunreghdlr failed with status: 0
ORA-27301: OS failure message: Error 0
ORA-27302: failure occurred at: sskgpreset1
.
2017-10-09 23:09:13.980 : USRTHRD:2572: {0:0:156} Category: 7
.
2017-10-09 23:09:13.980 : USRTHRD:2572: {0:0:156} DepInfo: 27300
.
2017-10-09 23:09:13.982 : USRTHRD:2572: {0:0:156} -- trace dump end --
.
2017-10-09 23:09:13.982 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start]
StorageAgent::parsekgforetcodes retcode = 7, kgfoCheckMount(AFF_DATA_DG01),
flag 2
2017-10-09 23:09:13.982 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start] (null)
category: 7, operation: kgfoAl06, loc: kgfokge, OS error: 27300, other:
ORA-27300: OS system dependent operation:sslssunreghdlr failed with status: 0
ORA-27301: OS failure message: Error 0
ORA-27302: failure occurred at: sskgpreset1
2017-10-09 23:09:13.983 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start]
StorageAgent::check kgfo returncode 1
2017-10-09 23:09:13.983 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start]
(:CLSN00140:)StorageAgent::parsekgforretcodes OCR dgName AFF_DATA_DG01 state
1
2017-10-09 23:09:13.984 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start]
waiting for check to not return PARTIALor UNPLANNED_OFFLINE 1
2017-10-09 23:09:14.985 :CLSDYNAM:2572: [ora.storage]{0:0:156} [start]
StorageAgent::check NODEROLE_HUB getOCRdetails
2017-10-09 23:09:14.989 : GPNP:2572: clsgpnp_dbmsGetItem_profile: [at
clsgpnp_dbms.c:399] Result: (0) CLSGPNP_OK. (:GPNP00401:)got
ASM-Profile.Mode='remote'
2017-10-09 23:09:14.990 : GPNP:2572: clsgpnp_dbmsGetItem_profile: [at
clsgpnp_dbms.c:399] Result: (0) CLSGPNP_OK. (:GPNP00401:)got
ASM-Profile.Mode='remote'
2017-10-09 23:09:15.015 : CSSCLNT:2572: clsssinit: initialized context:
(1118ab7d0) flags 0x115

Able to start asm manually on node 2 and ora.asm was marked online ,storage tried to access OCR  but failed to open password file on ASM diskgroup and caused upgrade failure .
.
currently node 1 is upgraded and the last node(node02) isn't.

From crsd_oraagent_oragrid.trc:

=====================

2017-10-11 17:53:54.765 : USRTHRD:4371: {1:56297:2} Thread::start { acquire
thndMX:1610abf0
2017-10-11 17:53:54.765 : USRTHRD:4371: {1:56297:2} Thread::start spawn
pThnd:110a5e470 thndType:1
2017-10-11 17:53:54.766 : USRTHRD:4371: {1:56297:2} Thread::start thread
spawned tid:8458
2017-10-11 17:53:54.766 : USRTHRD:4371: {1:56297:2} Thread::start spawned
release thndMX:1610abf0 }
2017-10-11 17:53:54.768 : USRTHRD:8458: {1:56297:2}
Thread:RegEndpointThread:ASMNET1LSNR_ASM LsnrAgent::RegEndpointThread::run
entry
2017-10-11 17:53:54.775 : USRTHRD:8458: {1:56297:2}
Thread:RegEndpointThread:ASMNET1LSNR_ASM LsnrAgent::RegEndpointThread::run
Registering Endpoint nsgfei_EndpointInit()
(ADDRESS=(PROTOCOL=TCP)(HOST=192.168.1.185)(PORT=1525))
2017-10-11 17:53:57.782 : USRTHRD:8458: {1:56297:2}
Thread:RegEndpointThread:ASMNET1LSNR_ASM LsnrAgent::RegEndpointThread::run
registered endpoint (ADDRESS=(PROTOCOL=TCP)(HOST=192.168.1.185)(PORT=1525))
2017-10-11 17:53:59.016 :CLSDYNAM:4371: [ora.ASMNET1LSNR_ASM.lsnr]{1:56297:2}
[check] clsnUtils::error Exception type=2 string=
CRS-5020: Not all endpoints are registered for listener ASMNET1LSNR_ASM===> endpoint update issue
.
2017-10-11 17:53:59.016 : AGFW:4371: {1:56297:2} Sending background msg
for resid ora.ASMNET1LSNR_ASM.lsnr node01 1
2017-10-11 17:53:59.016 : AGFW:4371: {1:56297:2} Agent sending message to
PE: AGENT_BACKGROUNDMSG_TOPE[] ID 28675:4361980

node01:ASM> srvctl config asm
ASM home: <CRS home>
Password file: /u01/app/oragrid/12.2.0.1/dbs/orapw+ASM
Backup of Password file:
ASM listener: ASMNET1LSNR_ASM
ASM instance count: 2
Cluster ASM listener: ASMNET1LSNR_ASM

 

ora.asm has start and stop depencies on ASMNET1LSNR as below

 [root@node01 ~]# srvctl config listener -l ASMNET1LSNR_ASM
Name: ASMNET1LSNR_ASM
Type: ASM Listener
Owner: oracle
Subnet: 10.64.220.0
Home: <CRS home>
End points: TCP:1525
Listener is enabled.
Listener is individually enabled on nodes:
Listener is individually disabled on nodes:
[root@node01 ~]#

Changes

 ASMNET1LSNR is a new listener resource  in 12.2 for ASM intercommunication with default port 1525

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms