Troubleshooting Guide ORA-609 : Opiodr aborting process unknown ospid (Doc ID 1121357.1)

Posted 2022-02-02 Lucifer三思而后行

In this Document

• • APPLIES TO:
  • PURPOSE
  • TROUBLESHOOTING STEPS
  • REFERENCES

APPLIES TO:

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

PURPOSE

ORA-609 is being reported in the alert log.  The error is intermittent and may not occur for days at a time.

Mon Oct 12 10:03:39 2009  
Errors in file e:\\app\\oracle\\diag\\rdbms\\center\\center\\trace\\center_ora_7464.trc:  
ORA-00609: could not attach to incoming connection  
ORA-12537: TNS:connection closed  
ORA-609 : opiodr aborting process unknown ospid (2436\\_7464)

Sqlnet.log that is local to the database server may report these errors:

Fatal NI connect error 12537, connecting to:  
(LOCAL=NO)  
  
VERSION INFORMATION:  
TNS for 64-bit Windows: Version 11.1.0.7.0 - Production  
Oracle Bequeath NT Protocol Adapter for 64-bit Windows: Version 11.1.0.7.0 - Production  
Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 11.1.0.7.0 - Production  
Time: 12-OCT-2009 10:03:39  
Tracing to file: E:\\app\\oracle\\product\\11.1.0\\db_1\\NETWORK\\trace\\svr1_7464.trc  
Tns error struct:  
ns main err code: 12537  
TNS-12537: TNS:connection closed  
ns secondary err code: 12560  
nt main err code: 0  
nt secondary err code: 0  
nt OS err code: 0

Listener log shows the connection was established with no apparent errors.  This is because the connection failed AFTER the listener has handed off the connection to the server process.

12-OCT-2009 10:03:39 * (CONNECT_DATA=(SID=ORCL)) * (ADDRESS=(PROTOCOL=tcp)(HOST=123.456.1.123)(PORT=3158)) * establish * ORCL * 0  
12-OCT-2009 10:03:39 * (CONNECT_DATA=(SID=ORCL)) * (ADDRESS=(PROTOCOL=tcp)(HOST=123.456.1.123)(PORT=3159)) * establish * ORCL * 0

Notice in this example Oracle Net Server trace, filename “svr_7464.trc”

Here the problem is seen when receiving the connection packet from client.  Note that the ORA-609 does not appear in the Oracle Net trace.  The ORA-609 is represented by the accompanying ns=12537 in this trace snippet.

[000001 12-OCT-2009 10:03:39:116] nscon: doing connect handshake...  
[000001 12-OCT-2009 10:03:39:116] nscon: recving a packet  
[000001 12-OCT-2009 10:03:39:116] nsprecv: entry  
[000001 12-OCT-2009 10:03:39:116] nsprecv: reading from transport...  
[000001 12-OCT-2009 10:03:39:116] nttrd: entry  
[000001 12-OCT-2009 10:03:39:163] nttrd: exit  
[000001 12-OCT-2009 10:03:39:163] ntt2err: entry  
[000001 12-OCT-2009 10:03:39:163] ntt2err: Read unexpected EOF ERROR on 7104  
[000001 12-OCT-2009 10:03:39:163] ntt2err: exit  
[000001 12-OCT-2009 10:03:39:163] nsprecv: error exit  
[000001 12-OCT-2009 10:03:39:163] nserror: entry  
[000001 12-OCT-2009 10:03:39:163] nserror: nsres: id=0, op=68, ns=12537, ns2=12560; nt[0]=507, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0  
[000001 12-OCT-2009 10:03:39:163] nscon: error exit  
[000001 12-OCT-2009 10:03:39:163] nsdo: nsctxrnk=0  
[000001 12-OCT-2009 10:03:39:163] nsdo: error exit  
[000001 12-OCT-2009 10:03:39:163] nsinh_hoff: error recving request

Other times tracking ORA-609 via Alert and Oracle Net server traces, shows issue further on during handshake.

Alert.log except here:

Mon Dec 21 15:52:15 2009  
ORA-609 : opiodr aborting process unknown ospid (21631120_1)

[21-DEC-2009 15:52:15:025] nscon: sending NSPTAC packet  
[21-DEC-2009 15:52:15:025] nspsend: entry  

[21-DEC-2009 15:52:15:031] ntt2err: Read unexpected EOF ERROR on 14  
[21-DEC-2009 15:52:15:031] ntt2err: exit  
[21-DEC-2009 15:52:15:031] nsprecv: error exit  
[21-DEC-2009 15:52:15:031] nserror: entry  
[21-DEC-2009 15:52:15:031] nserror: nsres: id=0, op=68, ns=12537, ns2=12560; nt[0]=507, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0  
[21-DEC-2009 15:52:15:031] nsrdr: error exit  
[21-DEC-2009 15:52:15:031] nsdo: nsctxrnk=0  
[21-DEC-2009 15:52:15:031] nsdo: error exit  
[21-DEC-2009 15:52:15:031] nsnareceive: error exit  
[21-DEC-2009 15:52:15:031] nserror: entry  
[21-DEC-2009 15:52:15:031] nserror: nsres: id=0, op=68, ns=12537, ns2=12532; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0  
[21-DEC-2009 15:52:15:031] nacomrc: received 12637 bytes  
[21-DEC-2009 15:52:15:031] nacomrc: failed with error 12637  
[21-DEC-2009 15:52:15:031] nacomrc: exit  
[21-DEC-2009 15:52:15:031] na_receive_packet: failed with error 12637  
[21-DEC-2009 15:52:15:031] na_receive_packet: exit  
[21-DEC-2009 15:52:15:031] na_server: failed with error 12637

It is common to find corresponding errors in the sqlnet.log file that is local to the instance.

E.g.

Fatal NI connect error 12537, connecting to:  
(LOCAL=NO)  
  
VERSION INFORMATION:  
TNS for Solaris: Version 11.2.0.2.0 - Production  
Oracle Bequeath NT Protocol Adapter for Solaris: Version 11.2.0.2.0 - Production  
TCP/IP NT Protocol Adapter for Solaris: Version 11.2.0.2.0 - Production  
Time: 21-DEC-2009 15:52:15  
Tracing not turned on.  
Tns error struct:  
ns main err code: 12537  
TNS-12537: TNS:connection closed  
ns secondary err code: 12560  
nt main err code: 0  
nt secondary err code: 0  
nt OS err code: 0

Matched to an event in the Oracle Net Server Trace

TROUBLESHOOTING STEPS

1. Find the incoming client(s) making the connections from the listener.log.
Alert log will show an ORA-609 error similar to following :

Mon Oct 05 12:41:49 2009  
ORA-609 : opiodr aborting process unknown ospid (21131406_1)

Go to the listener.log and find the entry for this connection.  The entry in the listener.log should look similar to the following:

05-OCT-2009 12:41:49 * (CONNECT_DATA=(SID=orcl)) *  
(ADDRESS=(PROTOCOL=tcp)(HOST=sample.com)(PORT=1234)) * establish * orcl * 0

Notice the client address in our example is “sample.com”.   One option is to locate several clients and enable client tracing at those sites.  You might inspect the log file (ORACLE_HOME/network/log) at the client(s) and check specifically for timeout errors that might have occurred at the same timestamp.

2. Oracle Net Level 16 Client tracing. Add to a clients SQLNET.ORA file

DIAG_ADR_ENABLED=off                  # Disable ADR if version 11g  
  
TRACE_LEVEL_CLIENT = 16               # Enable level 16 trace  
TRACE_TIMESTAMP_CLIENT = ON           # Set timestamp in the trace files  
TRACE_DIRECTORY_CLIENT = <DIRECTORY>  # Control trace file location  
  
TRACE_FILELEN_CLIENT =<n>     #Control size of trace set in kilobytes eg 20480  
TRACE_FILENO_CLIENT =<n>      #Control number of trace files per process

If the connection model is JDBC thin, Javanet tracing of a client is required. See Document 793415.1 How to Perform the Equivalent of SQL*Net Client Tracing with Oracle JDBC Thin Driver.
If 11.2 JDBC thin client used, the following note can be used Document 1050942.1 How to Trace the Network Packets Exchanged Between JDBC and the RDBMS in Release 11.2

3. Oracle Net Level 16 Server tracing. Add to server side SQLNET.ORA file

DIAG_ADR_ENABLED=off                  # Disable ADR if version 11g  
TRACE_LEVEL_SERVER = 16               # Enable level 16 trace  
TRACE_TIMESTAMP_SERVER = ON           # Set timestamp in the trace files  
TRACE_DIRECTORY_SERVER = <DIRECTORY>  # Control trace file location  
  
TRACE_FILELEN_SERVER =<n>   #Control size of trace set in kilobytes eg 20480  
TRACE_FILENO_SERVER =<n>       #Control number of trace files per process

Cyclic tracing will allow you to control the size of and number of trace files that are produced.

The TRACE_FILELEN parameter is for the size of a trace file.
The TRACE_FILENO parameter is the number of traces per process.

Important Notes:  
  
The SQLNET.ORA file is only read once on creation of a process. RDBMS Background process and shared server dispatchers will need to be restarted for parameter changes in the SQLNET.ORA to be picked up. Once a process has started to be traced, tracing will not stop until that the process stops.   
  
In an environment where both GRID and RDBMS homes are installed, instance would reference a sqlnet.ora file in RDBMS_HOME/network/admin by default.  (Whereas the listener would refer to GRID_HOME/network/admin for its .ora files)  
  
Please note, that enabling Oracle Net server tracing can produce large amounts of trace, in a very short time frame. Even with cyclic tracing, each process will have the TRACE_FILENO_SERVER value amount of traces produced. Optimal tracing workflow should be to enable tracing, reproduce problem and then disable tracing. Thus limiting amount of time tracing is enabled.  
  
Setting TRACE_FILENO_SERVER to 1 and TRACE_FILELEN_SERVER = 20480, could be a solution to lowering the amount of trace generated per process. Remember the trace file will be overwritten and you could lose the important data covering the failure.

4. Errorstack: Setup errorstack to capture failure. This can be particular useful when capturing an Oracle Net client trace is not feasible.

SQL> alter system set events '609 errorstack(3)';

Once a few traces have been collected while the error is reproduced:

SQL> alter session set events '609 off';

Once you get a failure:

• Review the SQLNET.LOG file on server.
• Find the matching entry in the ALERT. LOG, compare via timestamp.
• From the entry in the SQLNET.LOG file, you will have the Oracle Net server trace name, from the line “Tracing to file”.
• Open the server trace and grep / search for the Connection ID value.
• Then search the clients trace client directory for the same Connection ID value.

You’ll then having matching client and server traces.
This process is described in full in Document 374116.1 How to Match Oracle Net Client and Server Trace Files

Upload for review:

• Matching Oracle Net client and server traces or matching Javanet and Server trace.
• ALERT.LOG and LISTENER.LOG files. (Only required to upload data cover issue, not all the log files)
• SQLNET.LOG from server ORACLE_HOME/network/log
• Trace from errorstack.

Known Issues:

• Often the ORA-609 is reported due to client disconnecting before the connection can be established fully. Timeout parameters INBOUND_CONNECT_TIMEOUT_<listener_name> in the  LISTENER.ORA file and SQLNET.INBOUND_CONNECT_TIMEOUT in the SQLNET.ORA need to be reviewed.  If using the default of 60 seconds, (no explicit setting), then it is likely these parameters will need to be increased.
• Review and check network settings for the server machine where the database is running. Ensure settings are all correct and as expected and DNS servers are available
• If the server platform is Microsoft Windows, check the Windows Services for TNS listener and database ensure each service is started using the same account.

Note:  Some helpful information about finding diagnostic output.

Note 438148.1  How to Find the alert.log File (11g and Later)

REFERENCES

NOTE:1050942.1 - How to Trace the Network Packets Exchanged Between JDBC and the RDBMS
NOTE:609.1 - ORA-609 TNS-12537 and TNS-12547 in 11g Alert.log
NOTE:793415.1 - How to Perform the Equivalent of SQL*Net Client Tracing with Oracle JDBC Thin Driver
NOTE:438148.1 - How to Find the alert.log File (11g and Later)