OraFAQ Forum: Windows » Unable to connect through SQL*Net after applying latest PSU

Home » Infrastructure » Windows » Unable to connect through SQL*Net after applying latest PSU (12.1 and 12.2)

Show: Today's Messages :: Polls :: Message Navigator
E-mail to friend

Unable to connect through SQL*Net after applying latest PSU [message #673279]

Wed, 14 November 2018 03:59

Michel Cadot
Messages: 68718
Registered: March 2007
Location: Saint-Maur, France, https...

Senior Member
Account Moderator

I post this in Windows forum as I think it is more a Windows stuff.
The environment is Windows 7 Professional Service Pack 1.
After I applied the latest PSU (actually DB Bundle on Windows) I can no more connect to my databases through SQL*Net both on the same server or remotely: the CONNECT statement never returns.

Here' what I see.

In listener.log the connect seems to be successful:

13-NOV. -2018 19:43:00 * (CONNECT_DATA=(SERVICE_NAME=orafaq.myserver)(SERVER=DEDICATED)(UR=A)(CID=(PROGRAM=D:\oracle\ora12102\bin\sqlplus.exe)(HOST=MYSERVER)(USER=Michel))) * (ADDRESS=(PROTOCOL=tcp)(HOST=<ip removed>)(PORT=50709)) * establish * orafaq.myserver * 0

At the same time in listener.trc (trace level USER):

[13-NOV. -2018 19:43:00:986] nstoSetupTimeout: ATO enabled for ctx=0x00000000022B76B0, val=60000(millisecs)
[13-NOV. -2018 19:43:00:986] nstoUpdateActive: Active timeout is 0 (see nstotyp)
[13-NOV. -2018 19:43:00:986] nsopen: opening transport...
[13-NOV. -2018 19:43:00:986] nttcnp: getting sockname
[13-NOV. -2018 19:43:00:986] nttcnp: getting peername
[13-NOV. -2018 19:43:00:986] nttcnr: waiting to accept a connection.
[13-NOV. -2018 19:43:00:986] nttcnr: getting sockname
[13-NOV. -2018 19:43:00:986] nttcnr: connected on source ipaddr <ip removed> port 1532
[13-NOV. -2018 19:43:00:986] nttcnr: connected on destination ipaddr <ip removed> port 50709
[13-NOV. -2018 19:43:00:986] nttvlser: valid node check on incoming node <ip removed>
[13-NOV. -2018 19:43:00:986] nttvlser: Accepted Entry: <ip removed>
[13-NOV. -2018 19:43:00:986] nttctl: set TCP_NODELAY on 604
[13-NOV. -2018 19:43:00:986] nsopen: transport is open
[13-NOV. -2018 19:43:00:986] nsnainit: inf->nsinfflg[0]: 0xd inf->nsinfflg[1]: 0xd
[13-NOV. -2018 19:43:00:986] nsopen: global context check-in (to slot 4) complete
[13-NOV. -2018 19:43:00:986] nsanswer: deferring connect attempt; at stage 5
[13-NOV. -2018 19:43:00:986] nscon: doing connect handshake...
[13-NOV. -2018 19:43:00:986] nscon: got NSPTCN packet
[13-NOV. -2018 19:43:00:986] nsevdansw: exit
[13-NOV. -2018 19:43:00:986] nstoClearTimeout: ATO disabled for ctx=0x00000000022B76B0
[13-NOV. -2018 19:43:00:986] nstoUpdateActive: Active timeout is -1 (see nstotyp)
[13-NOV. -2018 19:43:00:986] nstoControlATO: ATO disabled for ctx=0x00000000022B76B0
[13-NOV. -2018 19:43:00:986] nsglbgetRSPidx: returning ecode=0
[13-NOV. -2018 19:43:00:986] nsglbgetSdPidx: secondary protocol=2
[13-NOV. -2018 19:43:00:986] nsc2addr: (ADDRESS=(PROTOCOL=BEQ)(PROGRAM=D:\Oracle\Ora12102\bin\oracle.exe)(ARGV0=oraclemikc)(ARGS='(LOCAL=NO)'))
[13-NOV. -2018 19:43:00:986] nsbeqaddr: connecting...
[13-NOV. -2018 19:43:01:001] nsopen: opening transport...
[13-NOV. -2018 19:43:01:001] snlpcss: Spawn Oracle completed oracle     (LOCAL=NO) mikc.
[13-NOV. -2018 19:43:01:001] sntpcall: Attempting to open pipe \\.\PIPE\ORANTP208C.2228
[13-NOV. -2018 19:43:01:017] sntpcall: Successfully established pipe 648 to child with 0 retries.
[13-NOV. -2018 19:43:01:017] sntpcall: Attempting to open pipe \\.\PIPE\ORANTP208C.2228.w
[13-NOV. -2018 19:43:01:017] sntpcall: Successfully established pipe 652 to child with 0 retries.
[13-NOV. -2018 19:43:01:017] nsopen: transport is open
[13-NOV. -2018 19:43:01:017] nsopen: global context check-in (to slot 5) complete
[13-NOV. -2018 19:43:01:017] nsbequeath_stg2: doing connect handshake...
[13-NOV. -2018 19:43:01:017] nsbequeath: doing connect handshake...
[13-NOV. -2018 19:43:01:017] sntpwrite: Attempting to write 4 bytes to handle 648
[13-NOV. -2018 19:43:01:017] sntpwrite: WriteFile returned 4 bytes
[13-NOV. -2018 19:43:01:017] sntpwrite: Attempting to write 78 bytes to handle 648
[13-NOV. -2018 19:43:01:017] sntpwrite: WriteFile returned 78 bytes
[13-NOV. -2018 19:43:01:017] sntpwrite: Attempting to write 8 bytes to handle 648
[13-NOV. -2018 19:43:01:017] sntpwrite: WriteFile returned 8 bytes
[13-NOV. -2018 19:43:01:017] sntpread: Attempting to read 4 bytes from handle 652
[13-NOV. -2018 19:43:01:017] sntpread: ReadFile returned 4 bytes
[13-NOV. -2018 19:43:01:017] sntpread: rc = 0, ntresnt[0] = 0
[13-NOV. -2018 19:43:01:017] sntpread: Attempting to read 4 bytes from handle 652
[13-NOV. -2018 19:43:06:602] sntpread: ReadFile returned 4 bytes
[13-NOV. -2018 19:43:06:602] sntpread: rc = 0, ntresnt[0] = 0
[13-NOV. -2018 19:43:06:602] nsbequeath: NSE=0
[13-NOV. -2018 19:43:06:602] nstimarmed: no timer allocated
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: ATO disabled for ctx=0x00000000022DDA20
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: STO disabled for ctx=0x00000000022DDA20
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: RTO disabled for ctx=0x00000000022DDA20
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: PITO disabled for ctx=0x00000000022DDA20
[13-NOV. -2018 19:43:06:602] nstoUpdateActive: Active timeout is -1 (see nstotyp)
[13-NOV. -2018 19:43:06:602] nsclose: closing transport
[13-NOV. -2018 19:43:06:602] sntpclose: Closing pipe 652
[13-NOV. -2018 19:43:06:602] sntpclose: Closing pipe 648
[13-NOV. -2018 19:43:06:602] nsclose: global context check-out (from slot 5) complete
[13-NOV. -2018 19:43:06:602] nstimarmed: no timer allocated
[13-NOV. -2018 19:43:06:602] nsclose: closing transport
[13-NOV. -2018 19:43:06:602] nsclose: global context check-out (from slot 4) complete
[13-NOV. -2018 19:43:06:602] nsbeqaddr: connect handshake is complete

Everything seems fine but client trace (level USER) shows:

(7896) [13-NOV. -2018 19:42:48:537] nrigbni: Unable to get data from navigation file tnsnav.ora
(7896) [13-NOV. -2018 19:42:53:170] snlinGetAddrInfo: getaddrinfo() failed with error 11004
(7896) [13-NOV. -2018 19:42:55:775] snlinGetAddrInfo: getaddrinfo() failed with error 11004
(7896) [13-NOV. -2018 19:42:55:775] nnftmlf_make_local_addrfile: construction of local names file failed
(7896) [13-NOV. -2018 19:42:55:775] nnftmlf_make_system_addrfile: system names file is D:\oracle\ora12102\network\admin\tnsnames.ora
(7896) [13-NOV. -2018 19:42:58:381] snlinGetAddrInfo: getaddrinfo() failed with error 11004
(7896) [13-NOV. -2018 19:43:00:986] snlinGetAddrInfo: getaddrinfo() failed with error 11004
(7896) [13-NOV. -2018 19:43:00:986] niotns: Not trying to enable dead connection detection.
(7896) [13-NOV. -2018 19:43:00:986] niotns: Calling address: (DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=MYSERVER)(PORT=1532)))(CONNECT_DATA=(SERVICE_NAME=orafaq.myserver)(SERVER=DEDICATED)(UR=A)(CID=(PROGRAM=D:\oracle\ora12102\bin\sqlplus.exe)(HOST=MYSERVER)(USER=Michel))))
(7896) [13-NOV. -2018 19:43:00:986] nscall: connecting...
(7896) [13-NOV. -2018 19:43:00:986] nsc2addr: (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=<ip removed>)(PORT=1532))(CONNECT_DATA=(SERVICE_NAME=orafaq.myserver)(SERVER=DEDICATED)(UR=A)(CID=(PROGRAM=D:\oracle\ora12102\bin\sqlplus.exe)(HOST=MYSERVER)(USER=Michel))))
(7896) [13-NOV. -2018 19:43:00:986] nttbnd2addr: using host IP address: <ip removed>
(7896) [13-NOV. -2018 19:43:00:986] nsopen: opening transport...
(7896) [13-NOV. -2018 19:43:00:986] nttcni: Tcp conn timeout = 60000 (ms)
(7896) [13-NOV. -2018 19:43:00:986] nttcni: trying to connect to socket 508.
(7896) [13-NOV. -2018 19:43:00:986] nttcni: connected on source ipaddr <ip removed> port 50709
(7896) [13-NOV. -2018 19:43:00:986] nttctl: set TCP_NODELAY on 508
(7896) [13-NOV. -2018 19:43:00:986] nsopen: transport is open
(7896) [13-NOV. -2018 19:43:00:986] nsnainit: inf->nsinfflg[0]: 0x61 inf->nsinfflg[1]: 0x61
(7896) [13-NOV. -2018 19:43:00:986] nsopen: global context check-in (to slot 0) complete
(7896) [13-NOV. -2018 19:43:00:986] nscon: doing connect handshake...
(7896) [13-NOV. -2018 19:43:00:986] nscon: sending NSPTCN packet

and never gets result and server side trace:

[13-NOV. -2018 19:43:01:017] niotns: Enabling CTO, value=60000 (milliseconds)
[13-NOV. -2018 19:43:01:017] niotns: Not enabling dead connection detection.
[13-NOV. -2018 19:43:01:017] nsc2addr: (ADDRESS=(PROTOCOL=beq))
[13-NOV. -2018 19:43:01:017] nlpcaini: No process parameters set
[13-NOV. -2018 19:43:01:017] nsinherit: connecting...
[13-NOV. -2018 19:43:01:017] sntpinherit: Attempting to make pipe \\.\PIPE\ORANTP208C.2228.w
[13-NOV. -2018 19:43:01:017] sntpinherit: Listening on pipe \\.\PIPE\ORANTP208C.2228.w
[13-NOV. -2018 19:43:01:017] sntpinherit: Attempting to make pipe \\.\PIPE\ORANTP208C.2228
[13-NOV. -2018 19:43:01:017] sntpinherit: Listening on pipe \\.\PIPE\ORANTP208C.2228
[13-NOV. -2018 19:43:01:017] sntpinherit: Successfully established pipe 3252 to parent.
[13-NOV. -2018 19:43:01:017] sntpinherit: Successfully established pipe 2296 to parent.
[13-NOV. -2018 19:43:01:017] nsinherit: doing connect handshake...
[13-NOV. -2018 19:43:01:017] sntpread: Attempting to read 4 bytes from handle 3252
[13-NOV. -2018 19:43:01:017] sntpread: ReadFile returned 4 bytes
[13-NOV. -2018 19:43:01:017] sntpread: rc = 0, ntresnt[0] = 0
[13-NOV. -2018 19:43:01:017] sntpread: Attempting to read 78 bytes from handle 3252
[13-NOV. -2018 19:43:01:017] sntpread: ReadFile returned 78 bytes
[13-NOV. -2018 19:43:01:017] sntpread: rc = 0, ntresnt[0] = 0
[13-NOV. -2018 19:43:01:017] sntpread: Attempting to read 8 bytes from handle 3252
[13-NOV. -2018 19:43:01:017] sntpread: ReadFile returned 8 bytes
[13-NOV. -2018 19:43:01:017] sntpread: rc = 0, ntresnt[0] = 0
[13-NOV. -2018 19:43:01:017] nsinh_hoff: bufl=1025
[13-NOV. -2018 19:43:01:017] nsopen: opening transport...
[13-NOV. -2018 19:43:01:017] nsopen: transport is open
[13-NOV. -2018 19:43:01:017] nsinh_hoff: hoff=0
[13-NOV. -2018 19:43:01:017] sntpwrite: Attempting to write 4 bytes to handle 2296
[13-NOV. -2018 19:43:01:017] sntpwrite: WriteFile returned 4 bytes
[13-NOV. -2018 19:43:01:017] nsinh_hoff: handshake is complete
[13-NOV. -2018 19:43:01:017] nsinh_hoff: ADR="(ADDRESS=(PROTOCOL=tcp)(DEV=604)(HOST=<ip removed>)(PORT=1532))"
[13-NOV. -2018 19:43:01:017] nsc2addr: (ADDRESS=(PROTOCOL=tcp)(DEV=604)(HOST=<ip removed>)(PORT=1532))
[13-NOV. -2018 19:43:01:017] nttbnd2addr: using host IP address: <ip removed>
[13-NOV. -2018 19:43:01:017] nsinh_hoff: inheriting the connection...
[13-NOV. -2018 19:43:01:017] nstoSetupTimeout: ATO enabled for ctx=0x0000000024F04660, val=60000(millisecs)
[13-NOV. -2018 19:43:01:017] nstoUpdateActive: Active timeout is 0 (see nstotyp)
[13-NOV. -2018 19:43:01:017] nsopen: opening transport...
[13-NOV. -2018 19:43:06:602] nserror: nsres: id=0, op=65, ns=12560, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[13-NOV. -2018 19:43:06:602] nsopen: unable to open transport
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: ATO disabled for ctx=0x0000000024F04660
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: STO disabled for ctx=0x0000000024F04660
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: RTO disabled for ctx=0x0000000024F04660
[13-NOV. -2018 19:43:06:602] nstoClearTimeout: PITO disabled for ctx=0x0000000024F04660
[13-NOV. -2018 19:43:06:602] nstoUpdateActive: Active timeout is -1 (see nstotyp)
[13-NOV. -2018 19:43:06:602] nsinh_hoff: unable to open connection
[13-NOV. -2018 19:43:06:602] sntpwrite: Attempting to write 4 bytes to handle 2296
[13-NOV. -2018 19:43:06:602] sntpwrite: WriteFile returned 4 bytes
[13-NOV. -2018 19:43:06:602] sntpclose: Closing pipe 3252
[13-NOV. -2018 19:43:06:602] sntpclose: Closing pipe 2296
[13-NOV. -2018 19:43:06:602] nserror: nsres: id=0, op=73, ns=12560, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[13-NOV. -2018 19:43:06:602] nioqper:  error from nsinherit: failed...
[13-NOV. -2018 19:43:06:602] nioqper:    ns main err code: 12560
[13-NOV. -2018 19:43:06:602] nioqper:    ns (2)  err code: 0
[13-NOV. -2018 19:43:06:602] nioqper:    nt main err code: 0
[13-NOV. -2018 19:43:06:602] nioqper:    nt (2)  err code: 0
[13-NOV. -2018 19:43:06:602] nioqper:    nt OS   err code: 0
[13-NOV. -2018 19:43:06:602] niotns: No broken-connection function available.
[13-NOV. -2018 19:43:06:602] niqme: reporting NS-12560 error as ORA-12560
[13-NOV. -2018 19:43:06:602] niotns: Couldn't connect, returning 12560

which is confirmed by sqlnet.log:

Fatal NI connect error 12560, connecting to:
 (LOCAL=NO)

  VERSION INFORMATION:
	TNS for 64-bit Windows: Version 12.1.0.2.0 - Production
	Oracle Bequeath NT Protocol Adapter for 64-bit Windows: Version 12.1.0.2.0 - Production
	Windows NT TCP/IP NT Protocol Adapter for 64-bit Windows: Version 12.1.0.2.0 - Production
  Time: 13-NOV. -2018 19:43:06
  Tracing to file: D:\Oracle\Admin\MIKC\Network\svr_8744.trc
  Tns error struct:
    ns main err code: 12560
    TNS-12560: TNS:protocol adapter error
    ns secondary err code: 0
    nt main err code: 0
    nt secondary err code: 0
    nt OS err code: 0

I specify that I have disabled Windows firewall (anyway I have previously added a rule stating that sqlplus.exe, oracle.exe and tnslsnr.exe can read and write on any port from/to any destination) and I have Comodo Internet Security which I have disabled the firewall, the anti-virus and the auto-containment components.

Also a tnsping works even remotely and with a different Oracle version:

C:\>tnsping orafaq

TNS Ping Utility for 32-bit Windows: Version 11.2.0.4.0 - Production on 14-NOV. -2018 11:02:50

Copyright (c) 1997, 2013, Oracle.  All rights reserved.

Used parameter files:
E:\oracle\ora11204\network\admin\sqlnet.ora

Used TNSNAMES adapter to resolve the alias
Attempting to contact (DESCRIPTION = (ADDRESS_LIST = (ADDRESS = (PROTOCOL = TCP)(HOST = <ip removed>)(PORT = 1532))) (CONNECT_DATA = (SERVICE_NAME = ORAFAQ.MYSERVER) (SERVER = DEDICATED)))
OK (70 msec)

Also after each attempt to connect "lsnrctl services" shows an increment in "established" value and still 0 for "refused".

Anyone has encountered something like this or has suggestions to investigate?

[Edit: add tnsping remark]
[Edit 2: add "lnsrctl services" remark]

[Updated on: Fri, 16 November 2018 02:31]

Report message to a moderator

Re: Unable to connect through SQL*Net after applying latest PSU [message #673283 is a reply to message #673279]

Wed, 14 November 2018 04:43

John Watson
Messages: 8960
Registered: January 2010
Location: Global Village

Senior Member

I cannot suggest anything, but I can say that this is probably not an issue with the October bundle patch itself. I have applied it to both 12.1 and 18.3 homes on Windows with no problems (well, not with that problem anyway) so it may be site specific. Like all good support people, I can blame the user.

One possibility that I always worry about on Windows is permissions. I don't really understand the security model in release 12, particularly now that you can install the Oracle Home into a "virtual user" account. Could it be something to do with that?

Report message to a moderator

Re: Unable to connect through SQL*Net after applying latest PSU [message #673287 is a reply to message #673283]

Wed, 14 November 2018 05:32

Michel Cadot
Messages: 68718
Registered: March 2007
Location: Saint-Maur, France, https...

Senior Member
Account Moderator

I agree with you this is not bundle issue and I also tend to think this is about Windows permissions.

Focusing on these lines:

[13-NOV. -2018 19:43:01:017] nsopen: opening transport...
[13-NOV. -2018 19:43:06:602] nserror: nsres: id=0, op=65, ns=12560, ns2=0; nt[0]=0, nt[1]=0, nt[2]=0; ora[0]=0, ora[1]=0, ora[2]=0
[13-NOV. -2018 19:43:06:602] nsopen: unable to open transport

I only find one reference on the web and one on MOS.

On MOS, note 466110.1 "Windows: Connections Via the Listener Hang or Error While Local Connections are Successful".
I checked the proposed "solution", putting the listener owner in "Local Administrators" group, but this failed.
Anyway, the user I use worked without this before and it seems to me this "solution" introduces a quite serious security hole.

On the web, poster said the problem was in the end that the owner of the listener and the one of the database instance were not the same one.
This is not my case.

[Updated on: Fri, 16 November 2018 02:33]

Report message to a moderator

Previous Topic:	SQL Loader Data Load into table Automation
Next Topic:	Install Oracle 12c Database

Goto Forum:

-=] Back to Top [=-

[ Syndicate this forum (XML) ] [

]

Current Time: Tue Dec 03 11:23:25 CST 2024