CRS-5014 CLSN00009 CRS-5017 RAC環境監聽異常，無法正常啟動和關閉

raysuen發表於2021-02-07

問題描述：

        資料庫監聽異常，無法正常啟動和關閉

解決過程：

[root@dntodu013 ~]# /u01/app/12.2.0.1/grid/bin/srvctl stop listener -n dntodu013                    
PRCR-1014 : Failed to stop resource ora.LISTENER.lsnr
PRCR-1065 : Failed to stop resource ora.LISTENER.lsnr
LSNRCTL for Linux: Version 12.2.0.1.0 - Production on 07-FEB-2021 11:27:25
Copyright (c) 1991, 2016, Oracle.  All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))
CRS-5014: Agent "ORAAGENT" timed out starting process "/u01/app/12.2.0.1/grid/bin/lsnrctl" for action "clean": details at "(:CLSN00009:)" in "/u01/app/grid/diag/crs/dntodu013/crs/trace/crsd_oraagent_grid.trc"
LSNRCTL for Linux: Version 12.2.0.1.0 - Production on 07-FEB-2021 11:28:27
Copyright (c) 1991, 2016, Oracle.  All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))
CRS-5014: Agent "ORAAGENT" timed out starting process "/u01/app/12.2.0.1/grid/bin/lsnrctl" for action "check": details at "(:CLSN00009:)" in "/u01/app/grid/diag/crs/dntodu013/crs/trace/crsd_oraagent_grid.trc"
CRS-5017: The resource action "ora.LISTENER.lsnr check" encountered the following error:
(:CLSN00009:)Command Aborted. For details refer to "(:CLSN00109:)" in "/u01/app/grid/diag/crs/dntodu013/crs/trace/crsd_oraagent_grid.trc".


處理過程：

[root@dntodu013 ~]# ps -ef | grep LISTENER | awk '{print "kill -9 "$2}' | bash
bash: line 290: kill: (183555) - No such process
bash: line 294: kill: (183660) - No such process
bash: line 315: kill: (194046) - No such process
bash: line 316: kill: (194072) - No such process
bash: line 332: kill: (200089) - No such process
bash: line 333: kill: (200115) - No such process
bash: line 334: kill: (200324) - No such process
bash: line 335: kill: (200351) - No such process
bash: line 336: kill: (200539) - No such process
[root@dntodu013 ~]#
[root@dntodu013 ~]#
[root@dntodu013 ~]# ps -ef | grep LISTENER
grid     201274 158077  0 11:58 ?        00:00:00 /u01/app/12.2.0.1/grid/bin/lsnrctl status LISTENER
root     201787  86578  0 11:58 pts/2    00:00:00 grep --color=auto LISTENER
[root@dntodu013 ~]#
[root@dntodu013 ~]#
[root@dntodu013 ~]# ps -ef | grep LISTENER | awk '{print "kill -9 "$2}' | bash
bash: line 1: kill: (203020) - No such process
[root@dntodu013 ~]# ps -ef | grep LISTENER
grid     203358 158077  0 11:58 ?        00:00:00 /u01/app/12.2.0.1/grid/bin/lsnrctl status LISTENER_SCAN1
root     203558  86578  0 11:58 pts/2    00:00:00 grep --color=auto LISTENER
[root@dntodu013 ~]# /u01/app/12.2.0.1/grid/bin/srvctl start listener -n dntodu013


參考官檔：

https://support.oracle.com/epmos/faces/DocumentDisplay?_afrLoop=5325629693181&id=2184058.1&displayIndex=5&_afrWindowMode=0&_adf.ctrl-state=r4hfvgag7_29#SYMPTOM


文件內容：

Applies to:

Oracle Database - Enterprise Edition - Version 11.2.0.4 and later
Oracle Database Cloud Schema Service - Version N/A and later
Oracle Database Exadata Cloud Machine - Version N/A and later
Oracle Cloud Infrastructure - Database Service - Version N/A and later
Oracle Database Cloud Exadata Service - Version N/A and later
Information in this document applies to any platform.

Symptoms

GI "srvctl start listener" fails:

$ srvctl start listenerPRCR-1079 : Failed to start resource ora.LISTENER.lsnrCRS-5014:
 Agent "/u01/app/11.2.0.4/grid/bin/oraagent.bin" timed out starting 
process "/u01/app/11.2.0.4/grid/bin/lsnrctl" for action "clean": details
 at "(:CLSN00009:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log"CRS-5017: The resource action "ora.LISTENER.lsnr clean" encountered the following error:(:CLSN00009:)Utils:execCmd
 aborted. For details refer to "(:CLSN00106:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log".
CRS-5014: Agent "/u01/app/11.2.0.4/grid/bin/oraagent.bin" timed out 
starting process "/u01/app/11.2.0.4/grid/bin/lsnrctl" for action 
"check": details at "(:CLSN00009:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log"CRS-5017: The resource action "ora.LISTENER.lsnr check" encountered the following error:(:CLSN00009:)Utils:execCmd
 aborted. For details refer to "(:CLSN00109:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log".
CRS-2680: Clean of 'ora.LISTENER.lsnr' on 'racnode1' failed


In agen trace:
2016-09-18 08:35:47.873: [ AGFW][299448640]{1:8926:484} Preparing STOP command for: ora.LISTENER.lsnr racnode1 12016-09-18 08:35:47.873: [ AGFW][299448640]{1:8926:484} ora.LISTENER.lsnr racnode1 1 state changed from: UNKNOWN to: STOPPING2016-09-18 08:35:47.873: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00108:) clsn_agent::stop {2016-09-18 08:35:47.873: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] LsnrAgent::stop {2016-09-18
 08:35:47.873: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
getResAttrib: attrib name USR_ORA_OPI value false len 52016-09-18 08:35:47.873: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] lsnrctl stop LISTENER
2016-09-18 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} 
[stop] getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18
 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
Utils::execCmd 1 USR_ORA_ENV:ORACLE_BASE=/u01/app/grid 
oracleHome:/u01/app/11.2.0.4/grid CrsHome:/u01/app/11.2.0.4/grid2016-09-18
 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] Adding 
Environment Variables ORACLE_HOME=/u01/app/11.2.0.4/grid2016-09-18 
08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] Adding 
Environment Variables TNS_ADMIN=/u01/app/11.2.0.4/grid/network/admin/2016-09-18
 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] Adding 
Environment variable from USR_ORA_ENV ORACLE_BASE=/u01/app/grid2016-09-18
 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
Utils:execCmd action = 2 flags = 38 ohome = (null) cmdname = lsnrctl.2016-09-18
 08:35:47.874: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00010:)2016-09-18
 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
(:CLSN00010:)LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 
18-SEP-2016 08:35:472016-09-18 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00010:)2016-09-18
 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
(:CLSN00010:)Copyright (c) 1991, 2013, Oracle. All rights reserved.2016-09-18 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00010:)2016-09-18
 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
(:CLSN00010:)Connecting to 
(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))2016-09-18 08:35:47.975: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00010:)........2016-09-18
 08:36:47.885: [ AGENT][303651136]{1:8926:484} {1:8926:484} Created 
alert : (:CRSAGF00113:) : Aborting the command: stop for resource: 
ora.LISTENER.lsnr racnode1 12016-09-18 08:36:47.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] (:CLSN00110:) clsn_agent::abort {2016-09-18 08:36:47.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] abort {2016-09-18
 08:36:47.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] 
Agent::abort last call info: "Agent::Agent refreshAttr"2016-09-18 08:36:47.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] abort command: stop2016-09-18 08:36:47.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] tryActionLock {2016-09-18
 08:36:47.913: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] 
(:CLSN00009:)Utils:execCmd abort request: killing 
/u01/app/11.2.0.4/grid/bin/lsnrctl2016-09-18 08:36:47.913: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] clsnUtils::error Exception type=2 string=CRS-5014:
 Agent "/u01/app/11.2.0.4/grid/bin/oraagent.bin" timed out starting 
process "/u01/app/11.2.0.4/grid/bin/lsnrctl" for action "stop": details 
at "(:CLSN00009:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log"
2016-09-18 08:36:47.913: [ AGFW][299448640]{1:8926:484} Agent sending
 reply for: RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18 08:36:47.914: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] clsnUtils::error Exception type=2 string=CRS-5017: The resource action "ora.LISTENER.lsnr stop" encountered the following error:(:CLSN00009:)Utils:execCmd
 aborted. For details refer to "(:CLSN00108:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log".
2016-09-18 08:36:47.914: [ora.LISTENER.lsnr][284932416]{1:8926:484} [stop] (:CLSN00108:) clsn_agent::stop }2016-09-18
 08:36:47.914: [ AGFW][299448640]{1:8926:484} Agent sending reply for: 
RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18 08:36:51.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] got lock2016-09-18 08:36:51.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] tryActionLock }2016-09-18 08:36:51.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] abort }2016-09-18 08:36:51.885: [ora.LISTENER.lsnr][303651136]{1:8926:484} [stop] (:CLSN00110:) clsn_agent::abort }2016-09-18
 08:36:51.885: [ AGFW][303651136]{1:8926:484} Command: stop for 
resource: ora.LISTENER.lsnr racnode1 1 completed with status: TIMEDOUT2016-09-18
 08:36:51.886: [ AGFW][299448640]{1:8926:484} Agent sending reply for: 
RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18 
08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18 
08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
Utils::execCmd 1 USR_ORA_ENV:ORACLE_BASE=/u01/app/grid 
oracleHome:/u01/app/11.2.0.4/grid CrsHome:/u01/app/11.2.0.4/grid2016-09-18
 08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] Adding
 Environment Variables ORACLE_HOME=/u01/app/11.2.0.4/grid2016-09-18 
08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] Adding 
Environment Variables TNS_ADMIN=/u01/app/11.2.0.4/grid/network/admin/2016-09-18
 08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] Adding
 Environment variable from USR_ORA_ENV ORACLE_BASE=/u01/app/grid2016-09-18
 08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
Utils:execCmd action = 3 flags = 38 ohome = (null) cmdname = lsnrctl.2016-09-18
 08:36:51.886: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] (:CLSN00010:)2016-09-18
 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
(:CLSN00010:)LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 
18-SEP-2016 08:36:512016-09-18 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] (:CLSN00010:)2016-09-18
 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
(:CLSN00010:)Copyright (c) 1991, 2013, Oracle. All rights reserved.2016-09-18 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] (:CLSN00010:)2016-09-18
 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
(:CLSN00010:)Connecting to 
(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))2016-09-18 08:36:51.988: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] (:CLSN00010:)........2016-09-18
 08:38:51.900: [ AGENT][293337408]{1:8926:484} {1:8926:484} Created 
alert : (:CRSAGF00113:) : Aborting the command: check for resource: 
ora.LISTENER.lsnr racnode1 12016-09-18 08:38:51.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] (:CLSN00110:) clsn_agent::abort {2016-09-18 08:38:51.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] abort {2016-09-18
 08:38:51.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] 
Agent::abort last call info: "Agent::Agent refreshAttr"2016-09-18 08:38:51.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] abort command: check2016-09-18 08:38:51.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] tryActionLock {2016-09-18
 08:38:51.973: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] 
(:CLSN00009:)Utils:execCmd abort request: killing 
/u01/app/11.2.0.4/grid/bin/lsnrctl2016-09-18 08:38:51.974: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] clsnUtils::error Exception type=2 string=CRS-5014:
 Agent "/u01/app/11.2.0.4/grid/bin/oraagent.bin" timed out starting 
process "/u01/app/11.2.0.4/grid/bin/lsnrctl" for action "check": details
 at "(:CLSN00009:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log"
2016-09-18 08:38:51.974: [ AGFW][299448640]{1:8926:484} Agent sending
 reply for: RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18 08:38:51.974: [ora.LISTENER.lsnr][282831168]{1:8926:484} [check] clsnUtils::error Exception type=2 string=CRS-5017: The resource action "ora.LISTENER.lsnr check" encountered the following error:(:CLSN00009:)Utils:execCmd
 aborted. For details refer to "(:CLSN00109:)" in 
"/u01/app/11.2.0.4/grid/log/racnode1/agent/crsd/oraagent_grid/oraagent_grid.log".
2016-09-18 08:38:51.975: [ AGFW][299448640]{1:8926:484} Agent sending
 reply for: RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18 08:38:55.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] got lock2016-09-18 08:38:55.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] tryActionLock }2016-09-18 08:38:55.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] abort }2016-09-18 08:38:55.900: [ora.LISTENER.lsnr][293337408]{1:8926:484} [check] (:CLSN00110:) clsn_agent::abort }2016-09-18
 08:38:55.900: [ AGFW][293337408]{1:8926:484} Command: check for 
resource: ora.LISTENER.lsnr racnode1 1 completed with status: TIMEDOUT2016-09-18 08:38:55.900: [ AGFW][299448640]{1:8926:484} ora.LISTENER.lsnr racnode1 1 state changed from: STOPPING to: UNKNOWN2016-09-18
 08:38:55.900: [ AGFW][299448640]{1:8926:484} Agent sending last reply 
for: RESOURCE_STOP[ora.LISTENER.lsnr racnode1 1] ID 4099:21552016-09-18
 08:38:55.908: [ AGFW][299448640]{1:8926:484} Agent received the 
message: RESOURCE_CLEAN[ora.LISTENER.lsnr racnode1 1] ID 4100:22262016-09-18 08:38:55.908: [ AGFW][299448640]{1:8926:484} Preparing CLEAN command for: ora.LISTENER.lsnr racnode1 12016-09-18 08:38:55.908: [ AGFW][299448640]{1:8926:484} ora.LISTENER.lsnr racnode1 1 state changed from: UNKNOWN to: CLEANING2016-09-18 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] (:CLSN00106:) clsn_agent::clean {2016-09-18 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] LsnrAgent::clean {2016-09-18 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] lsnrctl clean LISTENER
2016-09-18 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} 
[clean] getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18
 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
Utils::execCmd 1 USR_ORA_ENV:ORACLE_BASE=/u01/app/grid 
oracleHome:/u01/app/11.2.0.4/grid CrsHome:/u01/app/11.2.0.4/grid2016-09-18
 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] Adding
 Environment Variables ORACLE_HOME=/u01/app/11.2.0.4/grid2016-09-18 
08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] Adding 
Environment Variables TNS_ADMIN=/u01/app/11.2.0.4/grid/network/admin/2016-09-18
 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] Adding
 Environment variable from USR_ORA_ENV ORACLE_BASE=/u01/app/grid2016-09-18
 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
Utils:execCmd action = 4 flags = 38 ohome = (null) cmdname = lsnrctl.2016-09-18
 08:38:55.909: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
getOracleHomeAttrib: oracle_home = /u01/app/11.2.0.4/grid2016-09-18 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] (:CLSN00010:)2016-09-18
 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
(:CLSN00010:)LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 
18-SEP-2016 08:38:552016-09-18 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] (:CLSN00010:)2016-09-18
 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
(:CLSN00010:)Copyright (c) 1991, 2013, Oracle. All rights reserved.2016-09-18 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] (:CLSN00010:)2016-09-18
 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] 
(:CLSN00010:)Connecting to 
(DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))2016-09-18 08:38:56.011: [ora.LISTENER.lsnr][293337408]{1:8926:484} [clean] (:CLSN00010:)
ps command show's lisener process is there:
$ ps -ef|grep lsnr....grid 42962 33731 0 13:57 ? 00:00:00 /u01/app/11.2.0.4/grid/bin/lsnrctl status LISTENERgrid 68619 1 0 Aug16 ? 06:44:22 /u01/app/11.2.0.4/grid/bin/tnslsnr LISTENER -inherit
However, the following command hangs:
$ lsnrctl service listener
LSNRCTL for Linux: Version 11.2.0.4.0 - Production on 18-SEP-2016 14:15:10
Copyright (c) 1991, 2013, Oracle. All rights reserved.
Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=IPC)(KEY=LISTENER)))==>> hangs here


 

Cause

The cause is unclear, however, no obvious error in listener log.

Solution

As a workaround, kill the listener process, this allowed subsequent "srvctl start listener" command to succeed.





來自 “ ITPUB部落格 ” ，連結：http://blog.itpub.net/28572479/viewspace-2756634/，如需轉載，請註明出處，否則將追究法律責任。

相關文章