ORA-12547: TNS:lost contact - "sqlplus / as sysdba" - Oracle 12.2.0.1

In general, when logged in as an Oracle installation user, by setting two environment variables ORACLE_SID and ORACLE_HOME, local bequeath connection "sqlplus / as sysdba" works absolutely fine.

But in this specific case it was throwing ERROR: ORA-12547: TNS:lost contact.

There are many useful links available but none were helpful in my particular scenario.

Also, once, ORACLE_BASE was set, it worked like a charm.

It took me reading through 2000 lines of strace and a whole day of debugging to figure out the issue. 

So, here I am sharing my findings, maybe it will save someone else some time

ISSUE MANIFESTATION:

When attempted to connect by setting basic environment variables, connect request failed with ORA-12547

[dev01] : /home/abhimanyusuri> export ORACLE_SID=DEV01
[dev01] : /home/abhimanyusuri> export ORACLE_HOME=/db/oracle/product/12.2/DBHOME
[dev01] : /home/abhimanyusuri> export PATH=${PATH}:${ORACLE_HOME}/bin:.
[dev01] : /home/abhimanyusuri> which sqlplus
/db/oracle/product/12.2/DBHOME/bin/sqlplus
[dev01] : /home/abhimanyusuri> sqlplus / as sysdba

SQL*Plus: Release 12.2.0.1.0 Production on Tue Sep 11 16:15:11 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.

ERROR:
ORA-12547: TNS:lost contact


Enter user-name: ^C
[dev01] : /home/abhimanyusuri>

But, it was known that, when a custom ".env" is used to set environment, everything works fine.

So, rather than, setting up the environment by sourcing an "env" file, I decided to go with setting variables defined in it, one by one.

WORKAROUND :

Upon setting the very first one i.e. export ORACLE_BASE=/db/oracle, along with the variables mentioned in the above snippet, the connection was successfully established. But why not, without it?

[dev01] : /home/abhimanyusuri> export ORACLE_BASE=/db/oracle
[dev01] : /home/abhimanyusuri> sqlplus / as sysdba

SQL*Plus: Release 12.2.0.1.0 Production on Wed Sep 12 14:02:42 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL>

It is also established from observed behavior that, binaries are in place, intact with desired permissions, otherwise, it would have never worked.

DEBUGGING ROUND1: 

I looked through the following areas and confirmed everything is as required/suggested in metanotes

• Checked SQLNET.EXPIRE_TIME.
• Checked permissions on file ${ORACLE_HOME}/bin/sqlplus -->  6751
• Checked permissions on file ${ORACLE_HOME}/bin/oracle  -->  6751
• Performed relinking as suggested in metalink : ${ORACLE_HOME}/bin/relink all
• Checked /proc/<<PID_PMON>>/environ to rule out if instance was started with wrong env settings.
• Restarted DB instance
• Collected "STRACE" and stared at the o/p for few hours
• Compared straces for successful and unsuccessful connection

NO HELP :(

At this point, being completely clueless about what is happening, decided to start from scratch. 

DEBUGGING ROUND2:

1. Login to the server via Oracle installation user (same user as before).

2. Run oraenv

Upon running oranev, I discovered something strange "The Oracle base has been set to /db/oracle/product/12.2/DBHOME".

Rather than setting $ORACLE_BASE to /db/oracle, it was being set to $ORACLE_HOME.

But connection did work fine post this.

Change approach: Need to shift focus to $ORACLE_BASE.

To further investigate, executed oraenv in debug mode i.e. "sh -x /usr/local/bin/oraenv", which lead to below mentioned code piece

+ ORABASE_EXEC=/db/oracle/product/12.2/DBHOME/bin/orabase
+ '[' x '!=' x ']'
+ OLD_ORACLE_BASE=
+ '[' -w /db/oracle/product/12.2/DBHOME/inventory/ContentsXML/oraclehomeproperties.xml ']'  
+ '[' -f /db/oracle/product/12.2/DBHOME/bin/orabase ']'
+ '[' -x /db/oracle/product/12.2/DBHOME/bin/orabase ']'
++ /db/oracle/product/12.2/DBHOME/bin/orabase
+ ORACLE_BASE=
+ '[' x '!=' x ']'
+ '[' '' '!=' true ']'
+ echo 'The Oracle base has been set to '
The Oracle base has been set to 
+ export ORACLE_BASE
+ '[' x = x ']'
+ '[' '' '!=' true ']'
+ echo 'Resetting ORACLE_BASE to its previous value or ORACLE_HOME'
Resetting ORACLE_BASE to its previous value or ORACLE_HOME
+ '[' '' '!=' '' ']'
+ ORACLE_BASE=/db/oracle/product/12.2/DBHOME
+ '[' '' '!=' true ']'
+ echo 'The Oracle base has been set to /db/oracle/product/12.2/DBHOME'

Checked content and permissions of file "oraclehomeproperties.xml", everything seems in place, here is an excerpt 

[dev01] : /home/abhimanyusuri> ls -ltr /db/oracle/product/12.2/DBHOME/inventory/ContentsXML/oraclehomeproperties.xml
-rw-r-----. 1 abhimanyusuri dba 545 Feb 19  2018 /db/oracle/product/12.2/DBHOME/inventory/ContentsXML/oraclehomeproperties.xml

cat /db/oracle/product/12.2/DBHOME/inventory/ContentsXML/oraclehomeproperties.xml
..
<PROPERTY NAME="ORACLE_BASE" VAL="/db/oracle"/>
..

Still, execution of "orabase" was not returning anything

++ /db/oracle/product/12.2/DBHOME/bin/orabase
+ ORACLE_BASE=
+ '[' x '!=' x ']'
+ '[' '' '!=' true ']'
+ echo 'The Oracle base has been set to '
The Oracle base has been set to

Thought, to peek into STRACE o/p one more time. One big difference between strace o/p from successful and unsuccessful connection was logging in "sqlnet.log" and "log.xml"

Here is an excerpt from both log files at the time of failure

SQLNET.LOG was filled with below error

Fatal NI connect error 12547, connecting to:
(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/db/oracle/product/12.2/DBHOME/bin/oracle)(ARGV0=oracleDEV01)(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))')(DETACH=NO))(CONNECT_DATA=(CID=(PROGRAM=sqlplus)(HOST=DEV01)(USER=abhimanyusuri))))

VERSION INFORMATION:
TNS for Linux: Version 12.2.0.1.0 - Production
Oracle Bequeath NT Protocol Adapter for Linux: Version 12.2.0.1.0 - Production
Time: 11-SEP-2018 23:08:25
Tracing not turned on.
Tns error struct:
ns main err code: 12547

TNS-12547: TNS:lost contact
ns secondary err code: 12560
nt main err code: 517

TNS-00517: Lost contact
nt secondary err code: 32
nt OS err code: 0

diag/rdbms/alert/log.xml had below message

</msg>
<msg time='2018-09-11T23:08:25.738-07:00' org_id='oracle' comp_id='rdbms'
type='UNKNOWN' level='16' host_id='dev01'
host_addr='xxxxxxxxxxx' pid='220600'>
<txt>Oracle Clusterware infrastructure fatal error in oracle (OS PID 220600_139933757714208): Internal error (ID (:CLSB00107:)) - Error -1 (ORA-08275) determining Oracle base
</txt>
</msg>

And again, error related to oracle base.

Please note, this is a single instance database with no ASM/grid, so error is little misleading.

At this point, I had an intuition, that whatever it is, had to be related with $ORACLE_BASE.

So, decided to hammer "oraenv", using ${ORACLE_TRACE} 

[dev01] : /home/abhimanyusuri> export ORACLE_TRACE=T
[dev01] : /home/abhimanyusuri> . oraenv
++ N=
++ C=
++ grep c
++ echo '\c'
++ N=-n
++ '[' 0 = 0 ']'
..
..
ORACLE_SID = [abhimanyusuri] ? ++ read NEWSID
DEV01
++ case "$NEWSID" in
++ ORACLE_SID=DEV01
..
++ ORACLE_BASE=/db/oracle/product/12.2/DBHOME
++ '[' '' '!=' true ']'
++ echo 'The Oracle base has been set to /db/oracle/product/12.2/DBHOME'
The Oracle base has been set to /db/oracle/product/12.2/DBHOME
++ export ORACLE_BASE

Since, all environment variables had been set, decided to go for another iteration, without passing any argument value at prompt and let oracle decipher.

BULLS-EYE, "orabasetab"

[dev01] : /home/abhimanyusuri> . oraenv
+ . oraenv
++ SILENT=
++ '[' 0 -gt 0 ']'
++ case ${ORACLE_TRACE:-""} in
++ set -x
++ N=
..
..
++ ORASID=DEV01
++ echo -n 'ORACLE_SID = [DEV01] ? '
ORACLE_SID = [DEV01] ? ++ read NEWSID

++ case "$NEWSID" in
++ ORACLE_SID=DEV01
++ export ORACLE_SID
+++ dbhome DEV01
..
..
++ case "$OLDHOME" in
++ case "$PATH" in
+++ echo /usr/local/symlinks:/usr/local/scripts:---
#orabasetab file is used to track Oracle Home associated with Oracle Base
..
..
..
..

"ORABASETAB", I had never heard of it before. 

Circled back to o/p of strace and found the reference in there as well. 

Below is an excerpt from strace log

lstat("/etc/orabasetab", 0x------) = -1 ENOENT (No such file or directory)
open("/etc/orabasetab", O_RDONLY) = -1 ENOENT (No such file or directory)
lstat("/db/oracle/product/12.2/DBHOME/install/orabasetab", {st_mode=S_IFREG|0660, st_size=129, ...}) = 0
open("/db/oracle/product/12.2/DBHOME/install/orabasetab", O_RDONLY) = 9
fstat(9, {st_mode=S_IFREG|0660, st_size=129, ...}) = 0
fstat(9, {st_mode=S_IFREG|0660, st_size=129, ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x-----
read(9, "#orabasetab file is used to trac"..., 4096) = 129
read(9, "", 4096)                = 0
close(9)                         = 0

ROOT CAUSE IDENTIFICATION AND FIX:

Upon, checking the content of "orabasetab" file, it was discovered that file had a wrong mapping of ORACLE_HOME and ORACLE_BASE.

[dev01] : /home/abhimanyusuri> cat /db/oracle/product/12.2/DBHOME/install/orabasetab
#orabasetab file is used to track Oracle Home associated with Oracle Base
/db/oracle/product/12.2/DB_HOME_DOESNT_EXIST:/db/oracle:OraDB12Home1:N:

Commented old entry and entered a new line with the right mapping.

Back to business. 

[dev01] : /home/abhimanyusuri> export ORACLE_HOME=/db/oracle/product/12.2/DBHOME
[dev01] : /home/abhimanyusuri> export ORACLE_SID=DEV01
[dev01] : /home/abhimanyusuri> env|egrep -i "ora|tns"
ORACLE_SID=DEV01
ORACLE_HOME=/db/oracle/product/12.2/DBHOME
[dev01] : /home/abhimanyusuri> PATH=${ORACLE_HOME}/bin:${PATH}:
[dev01] : /home/abhimanyusuri> sqlplus / as sysdba

SQL*Plus: Release 12.2.0.1.0 Production on Wed Sep 12 22:50:51 2018

Copyright (c) 1982, 2016, Oracle.  All rights reserved.


Connected to:
Oracle Database 12c Enterprise Edition Release 12.2.0.1.0 - 64bit Production

SQL>

Reference to Oracle metanote for ORABASETAB:

https://docs.oracle.com/en/database/oracle/oracle-database/18/ntdbi/win-orabasetab.html

Thanks,

Suri