Hey guys!
I hope someone can help me figure out a strange problem I'm in trouble with Oracle 12c SEO (12.1.0.1). All of our instances regulary (~1 month) became unavailable for new connections while existing connections keep running. The only solution to fix it online is to restart the listener. Even a restart of an instance doesn't fix it. Regarding "new connections" is not the complete truth but I have to go in more detail to explain it.
We are running mutltiple database servers on Windows 2012R2. Each server has multiple instances and one listener. The instances have no listener configured so they use the default. Further each instance has a service name that is different from it's SID.
Now, what does it look like, when the issue appears:
1. The instances are still registered at the listener whith both, the service name and the SID and they re-registering regulary.
2. TNSPING results are OK.
3. Connecting to an instance localy using sqplus and SID/NTS method (SET ORACLE_SID; connect user/pass) is still possible.
4. Connecting with the EZCONNECT method (user/pass@'//host:port/service') isn't possible. Neither remote nor local (sqlplus or jdbc).
5. The listener log/trace doesn't indicate any issues. It always states an establish connection to the instance.
As I've already mentioned the current solution is to restart the listener and after ~1 minute everything is running fine for the next ~1 month.
Because of many tests I've did in the past few month I'm pretty sure that I can eleminate some reasons for this issue:
- Network problems (it happened on systems on different physical networks and server types; further see 4.)
- OS specific (it also happend on a test system with Windows 8.1.)
- Firewall (it doesn't matter if the firewall is active or not)
I already contacted the ORACLE support but although I've provided all requested logs/traces they couldn't find the reason. So I hope someone in this forum has a clue.
I've attached some logs/traces from an issue that happened yesterday on a complete new server that I want to use temporarily for a migration. The traces are from connection tests to the instance with the service name db-test-wp1 (SID TST10). The first folder holds a trace from a succsesful connection using NTS method and the second one the trace from the failed EZCONNECT one.
They do not include any security relevant data.
What I've noticed are the "Fatal NI connect error 12560" messages in the instance trace. But although I'm interessted in eliminate the reason too I don't belive that this is the same reason for the listener issue.
If you need more information feel free to request them.
EDIT
Below are the attached logs in plain text and shortened as requested.
EDIT 2
Removed local nts trace; updated posts with information
Questions from users:
Q: What ORA- errors do I get when the connection fails to establish?
A: As I've already posted below, I don't get any ORA- error nor any other Oracle specific error message! Java Applications only state that the connection fails with java specific error messages (io error or something similar). The sqlplus client also only jumps to the next line after authentication and nothing more happens, e.g.:
sqlplus> connect user/scott@'//localhost:1521/db-test-wp1'
| <-- next line, nothing happens ...really...nothing
Q: Is the environment virtualized?
A: In short: It doesn't matter because this issue appears on both platforms (physical and virtualized).
Q: How long is the listener.log / size of Windows event log
A: The listener.log (size?) is something around 100MB, more or less. The Windows event log.. I don't know at the moment. But if you aim at file size limits I can guarantee that this shouldn't be the reason. E.g. the server from which I've posted the logs below is fairly new installed.
sqlnet.ora
SQLNET.AUTHENTICATION_SERVICES = (NTS)
NAMES.DIRECTORY_PATH = (TNSNAMES, EZCONNECT)
listener.log
13-APR-2017 14:48:04 * service_update * tst10 * 0
13-APR-2017 14:49:10 * service_update * dev10 * 0
13-APR-2017 14:49:11 * (CONNECT_DATA=(CID=(PROGRAM=)(HOST=)(USER=sigfriedj))(COMMAND=status)(ARGUMENTS=64)(SERVICE=LISTENER)(VERSION=202375424)) * status * 0
13-APR-2017 14:49:26 * (CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.52)(PORT=50641)) * establish * db-test-wp1 * 0
13-APR-2017 14:49:47 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=58080)) * establish * db-entw-wp1 * 0
Thu Apr 13 14:51:06 2017
13-APR-2017 14:51:00 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=58307)) * establish * db-entw-wp1 * 0
13-APR-2017 14:51:13 * service_update * asc10 * 0
13-APR-2017 14:51:13 * service_update * izd10 * 0
13-APR-2017 14:51:46 * service_update * par10 * 0
13-APR-2017 14:51:55 * service_update * afo10 * 0
13-APR-2017 14:52:19 * service_update * dmo10 * 0
13-APR-2017 14:52:56 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=58662)) * establish * db-entw-wp1 * 0
13-APR-2017 14:54:48 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=59017)) * establish * db-entw-wp1 * 0
13-APR-2017 14:55:13 * (CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.52)(PORT=50644)) * establish * db-test-wp1 * 0
13-APR-2017 14:56:47 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=59392)) * establish * db-entw-wp1 * 0
13-APR-2017 14:58:00 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=59636)) * establish * db-entw-wp1 * 0
13-APR-2017 14:58:06 * service_update * tst10 * 0
13-APR-2017 14:59:10 * service_update * dev10 * 0
13-APR-2017 14:59:56 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=60036)) * establish * db-entw-wp1 * 0
13-APR-2017 15:00:49 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.140)(PORT=49485)) * establish * db-test-wp1 * 0
13-APR-2017 15:00:57 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.140)(PORT=49486)) * establish * db-test-wp1 * 0
13-APR-2017 15:01:14 * service_update * izd10 * 0
13-APR-2017 15:01:14 * service_update * asc10 * 0
13-APR-2017 15:01:47 * service_update * par10 * 0
13-APR-2017 15:01:48 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=60409)) * establish * db-entw-wp1 * 0
13-APR-2017 15:01:56 * service_update * afo10 * 0
13-APR-2017 15:02:15 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.140)(PORT=49536)) * establish * db-test-wp1 * 0
13-APR-2017 15:02:21 * service_update * dmo10 * 0
13-APR-2017 15:02:29 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=bem))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.140)(PORT=49543)) * establish * db-test-wp1 * 0
13-APR-2017 15:03:01 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=60663)) * establish * db-entw-wp1 * 0
13-APR-2017 15:04:56 * (CONNECT_DATA=(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))(SERVICE_NAME=db-entw-wp1)(CID=(PROGRAM=JDBC Thin Client)(HOST=__jdbc__)(USER=BEX-APPSVR5$))) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.59)(PORT=61047)) * establish * db-entw-wp1 * 0
13-APR-2017 15:05:02 * service_update * tst10 * 0
13-APR-2017 15:05:05 * service_update * tst10 * 0
Thu Apr 13 15:05:13 2017
Die System-Parameterdatei ist C:\app\oraclepaul7\product\12.1.0\dbhome_1\network\admin\listener.ora
Log-Meldungen wurden geschrieben in: C:\app\oraclepaul7\diag\tnslsnr\bex-dbsvr8\listener\alert\log.xml
Die Trace-Information wurde in C:\app\oraclepaul7\diag\tnslsnr\bex-dbsvr8\listener\trace\ora_1512_1924.trc geschrieben
Die Trace-Ebene ist derzeitig 0
Gestartet mit Pid=1512
Listen auf: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=bex-dbsvr8.bex-components.de)(PORT=1521)))
Listen auf: (DESCRIPTION=(ADDRESS=(PROTOCOL=ipc)(PIPENAME=\\.\pipe\EXTPROC1521ipc)))
Listener completed notification to CRS on start
TIMESTAMP * CONNECT DATA [* PROTOCOL INFO] * EVENT [* SID] * RETURN CODE
13-APR-2017 15:05:59 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50376)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:01 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50377)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:06 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50378)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:08 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50379)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:08 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50380)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:12 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50381)) * establish * db-test-wp1 * 12514
TNS-12514: TNS: Listener kann in Connect-Deskriptor angegebenen Service aktuell nicht auflösen
13-APR-2017 15:06:12 * service_register * dev10 * 0
13-APR-2017 15:06:12 * service_register * par10 * 0
13-APR-2017 15:06:12 * service_register * izd10 * 0
13-APR-2017 15:06:12 * service_register * afo10 * 0
13-APR-2017 15:06:12 * service_register * dmo10 * 0
13-APR-2017 15:06:12 * service_register * tst10 * 0
13-APR-2017 15:06:12 * service_register * asc10 * 0
13-APR-2017 15:06:14 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50382)) * establish * db-test-wp1 * 0
13-APR-2017 15:06:15 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50383)) * establish * db-test-wp1 * 0
13-APR-2017 15:06:15 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50384)) * establish * db-test-wp1 * 0
13-APR-2017 15:06:16 * (CONNECT_DATA=(CID=(PROGRAM=SQL Developer)(HOST=__jdbc__)(USER=mut))(SERVICE_NAME=db-test-wp1)) * (ADDRESS=(PROTOCOL=tcp)(HOST=10.202.2.135)(PORT=50385)) * establish * db-test-wp1 * 0
13-APR-2017 15:06:18 * service_update * tst10 * 0
alert_tst10.log
Fatal NI connect error 12560, connecting to:
(LOCAL=NO)
VERSION INFORMATION:
TNS for 64-bit Windows: Version 12.1.0.1.0 - Production
Oracle Bequeath NT Protocol Adapter for 64-bit Windows: Version 12.1.0.1.0 - Production
Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 12.1.0.1.0 - Production
Time: 13-APR-2017 14:49:32
Tracing not turned on.
Tns error struct:
ns main err code: 12560
TNS-12560: TNS: Fehler bei Protokolladapter
ns secondary err code: 0
nt main err code: 0
nt secondary err code: 0
nt OS err code: 0
Thu Apr 13 14:49:32 2017
opiodr aborting process unknown ospid (2988) as a result of ORA-609
Thu Apr 13 14:50:06 2017
Thread 1 cannot allocate new log, sequence 316
Checkpoint not complete
Current log# 3 seq# 315 mem# 0: C:\DBLOG\TST10\TST10_G3M1.REDO
Thread 1 cannot allocate new log, sequence 316
Private strand flush not complete
Current log# 3 seq# 315 mem# 0: C:\DBLOG\TST10\TST10_G3M1.REDO
Thu Apr 13 14:50:12 2017
Thread 1 advanced to log sequence 316 (LGWR switch)
Current log# 1 seq# 316 mem# 0: C:\DBLOG\TST10\TST10_G1M1.REDO
Thu Apr 13 14:50:13 2017
Archived Log entry 221 added for thread 1 sequence 315 ID 0x60fdf404 dest 1:
Thu Apr 13 14:55:18 2017
opiodr aborting process unknown ospid (208) as a result of ORA-609
Thu Apr 13 15:00:55 2017
opiodr aborting process unknown ospid (5988) as a result of ORA-609
Thu Apr 13 15:01:03 2017
opiodr aborting process unknown ospid (1432) as a result of ORA-609
Thu Apr 13 15:02:21 2017
opiodr aborting process unknown ospid (4344) as a result of ORA-609
Thu Apr 13 15:02:35 2017
opiodr aborting process unknown ospid (4868) as a result of ORA-609
Thu Apr 13 15:06:08 2017
ALTER SYSTEM ARCHIVE LOG
Thu Apr 13 15:06:08 2017
Thread 1 advanced to log sequence 317 (LGWR switch)
Current log# 2 seq# 317 mem# 0: C:\DBLOG\TST10\TST10_G2M1.REDO
Thu Apr 13 15:06:09 2017
Archived Log entry 222 added for thread 1 sequence 316 ID 0x60fdf404 dest 1:
Thu Apr 13 15:14:13 2017
Thread 1 cannot allocate new log, sequence 318
Checkpoint not complete
Current log# 2 seq# 317 mem# 0: C:\DBLOG\TST10\TST10_G2M1.REDO
Thu Apr 13 15:14:16 2017
local connection EZCONNECT (FAILED)
(3336) [13-APR-2017 14:54:37:952] nlstddt_do_alter_trace: --- TRACE CONFIGURATION INFORMATION FOLLOWS ---
(3336) [13-APR-2017 14:54:37:952] nlstddt_do_alter_trace: New trace stream is C:\wts\logs\client__3336.trc
(3336) [13-APR-2017 14:54:37:952] nlstddt_do_alter_trace: New trace level is 16
(3336) [13-APR-2017 14:54:37:952] nlstddt_do_alter_trace: --- TRACE CONFIGURATION INFORMATION ENDS ---
(3336) [13-APR-2017 14:54:37:952] nlstdtp_trace_pfile: --- PARAMETER SOURCE INFORMATION FOLLOWS ---
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source: Attempted load of system pfile source C:\app\oraclepaul7\product\12.1.0\dbhome_1\network\admin\sqlnet.ora
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source: Parameter source loaded successfully
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source:
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source: Attempted load of local pfile source C:\Users\sigfriedj\sqlnet.ora
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source: Parameter source was not loaded
(3336) [13-APR-2017 14:54:37:952] nlstdts_trace_source:
(3336) [13-APR-2017 14:54:37:952] nlstdtp_trace_pfile: -> PARAMETER TABLE LOAD RESULTS FOLLOW <-
(3336) [13-APR-2017 14:54:37:952] nlstdtp_trace_pfile: Successful parameter table load
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: -> PARAMETER TABLE HAS THE FOLLOWING CONTENTS <-
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: DIAG_ADR_ENABLED = OFF
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: LOG_DIRECTORY_CLIENT = C:\wts\logs
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: LOG_FILE_CLIENT = CLIENT
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TRACE_LEVEL_CLIENT = 16
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TNSPING.TRACE_LEVEL = 16
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: NAMES.DIRECTORY_PATH = (TNSNAMES, EZCONNECT)
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TNSPING.TRACE_DIRECTORY = C:\wts\logs
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TRACE_DIRECTORY_CLIENT = C:\wts\logs
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: SQLNET.AUTHENTICATION_SERVICES = (NTS)
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TRACE_TIMESTAMP_CLIENT = ON
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TRACE_FILE_CLIENT = CLIENT_
(3336) [13-APR-2017 14:54:37:952] nlstddp_dump_ptable: TRACE_UNIQUE_CLIENT = ON
(3336) [13-APR-2017 14:54:37:952] nlstdtp_trace_pfile: --- PARAMETER SOURCE INFORMATION ENDS ---
(3336) [13-APR-2017 14:54:37:952] nlstddl_do_alter_log: --- LOG CONFIGURATION INFORMATION FOLLOWS ---
(3336) [13-APR-2017 14:54:37:952] nlstddl_do_alter_log: Log stream will be "C:\wts\logs\client.log"
(3336) [13-APR-2017 14:54:37:952] nlstddl_do_alter_log: Log stream validation not requested
(3336) [13-APR-2017 14:54:37:952] nlstddl_do_alter_log: --- LOG CONFIGURATION INFORMATION ENDS ---
(3336) [13-APR-2017 14:54:37:952] nlstdipi: entry
(3336) [13-APR-2017 14:54:37:952] nlstdipi: exit
(3336) [13-APR-2017 14:54:37:968] nigini: entry
(3336) [13-APR-2017 14:54:37:968] nigini: Count in the NL global area is now 1
(3336) [13-APR-2017 14:54:37:968] nigini: Count in NI gbl area now: 1
(3336) [13-APR-2017 14:54:37:968] nrigbi: entry
(3336) [13-APR-2017 14:54:37:968] nrigbni: entry
(3336) [13-APR-2017 14:54:37:968] nrigbni: Unable to get data from navigation file tnsnav.ora
(3336) [13-APR-2017 14:54:37:968] nrigbni: exit
(3336) [13-APR-2017 14:54:37:968] nrigbi: exit
(3336) [13-APR-2017 14:54:37:968] nigini: exit
(3336) [13-APR-2017 14:54:37:968] nigsui: entry
(3336) [13-APR-2017 14:54:37:968] nigsui: exit (-1)
(3336) [13-APR-2017 14:55:13:078] nigini: entry
(3336) [13-APR-2017 14:55:13:078] nigini: Count in the NL global area is now 2
(3336) [13-APR-2017 14:55:13:078] nigini: Count in NI gbl area now: 2
(3336) [13-APR-2017 14:55:13:078] nigini: exit
(3336) [13-APR-2017 14:55:13:078] niqname: Using nnfsn2a() to build connect descriptor for (possibly remote) database.
(3336) [13-APR-2017 14:55:13:078] nnfgiinit: entry
(3336) [13-APR-2017 14:55:13:078] nncpcin_maybe_init: default name server domain is [root]
(3336) [13-APR-2017 14:55:13:078] nnfgiinit: Installing read path
(3336) [13-APR-2017 14:55:13:078] nnfgsrsp: entry
(3336) [13-APR-2017 14:55:13:078] nnfgsrsp: Obtaining path parameter from names.directory_path or native_names.directory_path
(3336) [13-APR-2017 14:55:13:078] nnfgsrdp: entry
(3336) [13-APR-2017 14:55:13:078] nnfgsrdp: Setting path:
(3336) [13-APR-2017 14:55:13:078] nnfgsrdp: checking element TNSNAMES
(3336) [13-APR-2017 14:55:13:078] nnfgsrdp: checking element EZCONNECT
(3336) [13-APR-2017 14:55:13:078] nnfgsrdp: Path set
(3336) [13-APR-2017 14:55:13:078] nnfun2a: entry
(3336) [13-APR-2017 14:55:13:078] nlolgobj: entry
(3336) [13-APR-2017 14:55:13:078] nnfgrne: entry
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Going though read path adapters
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Switching to TNSNAMES adapter
(3336) [13-APR-2017 14:55:13:078] nnftboot: entry
(3336) [13-APR-2017 14:55:13:078] nlpaxini: entry
(3336) [13-APR-2017 14:55:13:078] nlpaxini: exit
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_local_addrfile: entry
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_local_addrfile: construction of local names file failed
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_local_addrfile: exit
(3336) [13-APR-2017 14:55:13:078] nlpaxini: entry
(3336) [13-APR-2017 14:55:13:078] nlpaxini: exit
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_system_addrfile: entry
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_system_addrfile: system names file is C:\app\oraclepaul7\product\12.1.0\dbhome_1\network\admin\tnsnames.ora
(3336) [13-APR-2017 14:55:13:078] nnftmlf_make_system_addrfile: exit
(3336) [13-APR-2017 14:55:13:078] nnftboot: exit
(3336) [13-APR-2017 14:55:13:078] nnftrne: entry
(3336) [13-APR-2017 14:55:13:078] nnftrne: Original name: //10.202.2.52:1521/db-test-wp1
(3336) [13-APR-2017 14:55:13:078] nnfttran: entry
(3336) [13-APR-2017 14:55:13:078] nnfttran: Error querying //10.202.2.52:1521/db-test-wp1 of attribute A.SMD errcode 408
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Query unsuccessful, skipping to next adapter
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Switching to EZCONNECT adapter
(3336) [13-APR-2017 14:55:13:078] nnfhboot: entry
(3336) [13-APR-2017 14:55:13:078] nnfhboot: exit
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] snlinGetNameInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetNameInfo: exit
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nnfhrne: Using hostname address (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1))(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521))) for name //10.202.2.52:1521/db-test-wp1
(3336) [13-APR-2017 14:55:13:078] nnfgrne: exit
(3336) [13-APR-2017 14:55:13:078] nlolgserv: entry
(3336) [13-APR-2017 14:55:13:078] nnfggav: entry
(3336) [13-APR-2017 14:55:13:078] nnfhgav: exit
(3336) [13-APR-2017 14:55:13:078] nnfgfrm: entry
(3336) [13-APR-2017 14:55:13:078] nnfhfrm: exit
(3336) [13-APR-2017 14:55:13:078] nnfgfrm: exit
(3336) [13-APR-2017 14:55:13:078] nlolgserv: exit
(3336) [13-APR-2017 14:55:13:078] nlolgobj: exit
(3336) [13-APR-2017 14:55:13:078] nlolfmem: entry
(3336) [13-APR-2017 14:55:13:078] nlolfmem: exit
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NI global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NL global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigini: entry
(3336) [13-APR-2017 14:55:13:078] nigini: Count in the NL global area is now 2
(3336) [13-APR-2017 14:55:13:078] nigini: Count in NI gbl area now: 2
(3336) [13-APR-2017 14:55:13:078] nigini: exit
(3336) [13-APR-2017 14:55:13:078] niqname: Using nnfsn2a() to build connect descriptor for (possibly remote) database.
(3336) [13-APR-2017 14:55:13:078] nnfun2a: entry
(3336) [13-APR-2017 14:55:13:078] nlolgobj: entry
(3336) [13-APR-2017 14:55:13:078] nnfgrne: entry
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Going though read path adapters
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Switching to TNSNAMES adapter
(3336) [13-APR-2017 14:55:13:078] nnftrne: entry
(3336) [13-APR-2017 14:55:13:078] nnftrne: Original name: //10.202.2.52:1521/db-test-wp1
(3336) [13-APR-2017 14:55:13:078] nnfttran: entry
(3336) [13-APR-2017 14:55:13:078] nnfttran: Error querying //10.202.2.52:1521/db-test-wp1 of attribute A.SMD errcode 408
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Query unsuccessful, skipping to next adapter
(3336) [13-APR-2017 14:55:13:078] nnfgrne: Switching to EZCONNECT adapter
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] snlinGetNameInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetNameInfo: exit
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nnfhrne: Using hostname address (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1))(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521))) for name //10.202.2.52:1521/db-test-wp1
(3336) [13-APR-2017 14:55:13:078] nnfgrne: exit
(3336) [13-APR-2017 14:55:13:078] nlolgserv: entry
(3336) [13-APR-2017 14:55:13:078] nnfggav: entry
(3336) [13-APR-2017 14:55:13:078] nnfhgav: exit
(3336) [13-APR-2017 14:55:13:078] nnfgfrm: entry
(3336) [13-APR-2017 14:55:13:078] nnfhfrm: exit
(3336) [13-APR-2017 14:55:13:078] nnfgfrm: exit
(3336) [13-APR-2017 14:55:13:078] nlolgserv: exit
(3336) [13-APR-2017 14:55:13:078] nlolgobj: exit
(3336) [13-APR-2017 14:55:13:078] nlolfmem: entry
(3336) [13-APR-2017 14:55:13:078] nlolfmem: exit
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NI global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NL global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigini: entry
(3336) [13-APR-2017 14:55:13:078] nigini: Count in the NL global area is now 2
(3336) [13-APR-2017 14:55:13:078] nigini: Count in NI gbl area now: 2
(3336) [13-APR-2017 14:55:13:078] nigini: exit
(3336) [13-APR-2017 14:55:13:078] niqname: Hst is already an NVstring.
(3336) [13-APR-2017 14:55:13:078] niqname: Inserting CID.
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NI global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigtrm: Count in the NL global area is now 1
(3336) [13-APR-2017 14:55:13:078] nigini: entry
(3336) [13-APR-2017 14:55:13:078] nigini: Count in the NL global area is now 2
(3336) [13-APR-2017 14:55:13:078] nigini: Count in NI gbl area now: 2
(3336) [13-APR-2017 14:55:13:078] nigini: exit
(3336) [13-APR-2017 14:55:13:078] niqname: Hst is already an NVstring.
(3336) [13-APR-2017 14:55:13:078] niqname: Inserting CID.
(3336) [13-APR-2017 14:55:13:078] niotns: entry
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: entry
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: normal exit
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: entry
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: normal exit
(3336) [13-APR-2017 14:55:13:078] niotns: Not trying to enable dead connection detection.
(3336) [13-APR-2017 14:55:13:078] niotns: Calling address: (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj)))(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521)))
(3336) [13-APR-2017 14:55:13:078] nsgettrans_bystring: entry
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: using host IP address: 10.202.2.52
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: exit
(3336) [13-APR-2017 14:55:13:078] ntgettrans: entry
(3336) [13-APR-2017 14:55:13:078] ntgettrans: exit
(3336) [13-APR-2017 14:55:13:078] nsgettrans_bystring: exit
(3336) [13-APR-2017 14:55:13:078] nscall: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: 304 bytes at 0x25618f0
(3336) [13-APR-2017 14:55:13:078] nsmal: normal exit
(3336) [13-APR-2017 14:55:13:078] nscall: connecting...
(3336) [13-APR-2017 14:55:13:078] nlad_expand_hst: Adding an ADDRESS_LIST binding
(3336) [13-APR-2017 14:55:13:078] nlad_expand_hst: Expanding 10.202.2.52
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nlad_expand_hst: Already an IP address
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nlad_expand_hst: Result: (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj)))(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521))))
(3336) [13-APR-2017 14:55:13:078] nlad_pr: entry
(3336) [13-APR-2017 14:55:13:078] nlad_pr: description processing
(3336) [13-APR-2017 14:55:13:078] nlad_pr: entry
(3336) [13-APR-2017 14:55:13:078] nlad_pr: Result: (CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj)))
(3336) [13-APR-2017 14:55:13:078] nlad_pr: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nlad_pr: hostname 10.202.2.52
(3336) [13-APR-2017 14:55:13:078] nlad_pr: Result: (ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521)))
(3336) [13-APR-2017 14:55:13:078] nlad_aand: entry
(3336) [13-APR-2017 14:55:13:078] nlad_aand: entry
(3336) [13-APR-2017 14:55:13:078] nlad_ind: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nlad_ind: hostname 10.202.2.52
(3336) [13-APR-2017 14:55:13:078] nlad_ind: exit
(3336) [13-APR-2017 14:55:13:078] nlad_pr: Result: (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj)))(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521))))
(3336) [13-APR-2017 14:55:13:078] nladini: entry
(3336) [13-APR-2017 14:55:13:078] nladini: exit
(3336) [13-APR-2017 14:55:13:078] nladget: entry
(3336) [13-APR-2017 14:55:13:078] nladget: exit
(3336) [13-APR-2017 14:55:13:078] nsmal: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: 216 bytes at 0x2586e30
(3336) [13-APR-2017 14:55:13:078] nsmal: normal exit
(3336) [13-APR-2017 14:55:13:078] nsc2addr: entry
(3336) [13-APR-2017 14:55:13:078] nsc2addr: (DESCRIPTION=(CONNECT_DATA=(SERVICE_NAME=db-test-wp1)(CID=(PROGRAM=C:\app\oraclepaul7\product\12.1.0\dbhome_1\bin\sqlplus.exe)(HOST=BEX-DBSVR8)(USER=sigfriedj)))(ADDRESS=(PROTOCOL=TCP)(HOST=10.202.2.52)(PORT=1521)))
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinGetAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: using host IP address: 10.202.2.52
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: entry
(3336) [13-APR-2017 14:55:13:078] snlinFreeAddrInfo: exit
(3336) [13-APR-2017 14:55:13:078] nttbnd2addr: exit
(3336) [13-APR-2017 14:55:13:078] nsc2addr: normal exit
(3336) [13-APR-2017 14:55:13:078] nsopen: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: 1880 bytes at 0x27bf4f0
(3336) [13-APR-2017 14:55:13:078] nsmal: normal exit
(3336) [13-APR-2017 14:55:13:078] nsopenmplx: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: 2944 bytes at 0x27bfc50
(3336) [13-APR-2017 14:55:13:078] nsmal: normal exit
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: entry
(3336) [13-APR-2017 14:55:13:078] snsbitini_ts: normal exit
(3336) [13-APR-2017 14:55:13:078] nsiorini: entry
(3336) [13-APR-2017 14:55:13:078] nsbal: entry
(3336) [13-APR-2017 14:55:13:078] nsbgetfl: entry
(3336) [13-APR-2017 14:55:13:078] nsbgetfl: normal exit
(3336) [13-APR-2017 14:55:13:078] nsmal: entry
(3336) [13-APR-2017 14:55:13:078] nsmal: 168 bytes at 0x2586f10
(3336) [13-APR-2017 14:55:13:078] nsmal: normal exit
(3336) [13-APR-2017 14:55:13:078] nsbal: normal exit
(3336) [13-APR-2017 14:55:13:078] nsiorini: exit (0)
(3336) [13-APR-2017 14:55:13:078] nscpxget: entry
(3336) [13-APR-2017 14:55:13:078] snsbitts_ts: entry
(3336) [13-APR-2017 14:55:13:078] snsbitts_ts: acquired the bit
(3336) [13-APR-2017 14:55:13:078] snsbitts_ts: normal exit
(3336) [13-APR-2017 14:55:13:078] snsbitcl_ts: entry
(3336) [13-APR-2017 14:55:13:078] snsbitcl_ts: normal exit
(3336) [13-APR-2017 14:55:13:078] nscpxget: normal exit
(3336) [13-APR-2017 14:55:13:078] nsopenalloc_nsntx: nlhthput on mplx_ht_nsgbu:ctx=27bf4f0, nsntx=27bfc50
(3336) [13-APR-2017 14:55:13:078] nsopenmplx: normal exit
(3336) [13-APR-2017 14:55:13:078] nsopen: opening transport...
(3336) [13-APR-2017 14:55:13:078] nttcon: entry
(3336) [13-APR-2017 14:55:13:078] nttcon: toc = 1
(3336) [13-APR-2017 14:55:13:078] nttcnp: entry
(3336) [13-APR-2017 14:55:13:078] nttcnp: creating a socket.
(3336) [13-APR-2017 14:55:13:078] nttcnp: exit
(3336) [13-APR-2017 14:55:13:078] nttcni: entry
(3336) [13-APR-2017 14:55:13:078] nttcni: Tcp conn timeout = 60000 (ms)
(3336) [13-APR-2017 14:55:13:078] nttcni: TCP Connect TO enabled. Switching to NB
(3336) [13-APR-2017 14:55:13:078] nttctl: entry
(3336) [13-APR-2017 14:55:13:078] nttctl: Setting connection into non-blocking mode
(3336) [13-APR-2017 14:55:13:078] nttcni: trying to connect to socket 540.
(3336) [13-APR-2017 14:55:13:094] ntt2err: entry
(3336) [13-APR-2017 14:55:13:094] ntt2err: exit
(3336) [13-APR-2017 14:55:13:094] ntctst: size of NTTEST list is 1 - not calling poll
(3336) [13-APR-2017 14:55:13:094] sntseltst: Testing for WRITE on socket 540
(3336) [13-APR-2017 14:55:13:094] sntseltst: FOUND: write request on socket 540
(3336) [13-APR-2017 14:55:13:094] nttctl: entry
(3336) [13-APR-2017 14:55:13:094] nttctl: Clea