Issue connecting to Oracle DB while running on Kubernetes

[0x4Graham]

Hi,

I am having an issue when trying to connect to an Oracle DB from Kubernetes. However, the same application works perfectly when connecting to the db from my local machine.

I've added some trace logging and you can see the error I get below:

2019-10-16 12:42:31.839710 TID:16 (CFG) (ENV) Machine Name : baseapp-helm-dev-56b96fd86b-jmr7s
2019-10-16 12:42:31.843577 TID:16 (CFG) (ENV) User Name : baseappuser
2019-10-16 12:42:31.844338 TID:16 (CFG) (ENV) OS Version : Unix 4.19.50.1
2019-10-16 12:42:31.844402 TID:16 (CFG) (ENV) 64-bit OS : True
2019-10-16 12:42:31.844433 TID:16 (CFG) (ENV) 64-bit Process : True
2019-10-16 12:42:31.844495 TID:16 (CFG) (ENV) .NET Core Runtime Version : 3.0.0
2019-10-16 12:42:31.844537 TID:16 (CFG) (ENV) Application Directory : /src/app
2019-10-16 12:42:31.844561 TID:16 (CFG) (VER) Oracle Data Provider for .NET Core Driver Version : 2.0.19.1
2019-10-16 12:42:32.135277 TID:16 (CFG) (VER) Oracle Data Provider for .NET Core Driver Informational Version : 2.0.19.1:20190703
2019-10-16 12:42:32.141105 TID:16 (CFG) (SQLNET) FilePath : (null)
2019-10-16 12:42:32.141228 TID:16 (CFG) (TNSNAMES) FilePath : (null)
2019-10-16 12:42:32.154095 TID:16 (PUB) (OCFG) OracleConfiguration.TraceFileLocation() : /src/app
2019-10-16 12:42:32.154383 TID:16 (PUB) (OCFG) OracleConfiguration.TraceLevel() : 7
2019-10-16 12:42:31.827256 TID:16 (PUB) (ENT) OracleConnection.Open() (conid=30223109) (state=Closed) (sessid=0) (implid=0) (pooling=T) (txnid=n/a)
2019-10-16 12:42:32.211122 TID:16 (PRI) (ENT) (CP) OracleConnectionDispenser..cctor()
2019-10-16 12:42:32.212485 TID:16 (PRI) (EXT) (CP) OracleConnectionDispenser..cctor()
2019-10-16 12:42:32.212607 TID:16 (PRI) (ENT) (CP) OracleConnectionDispenser.Get()
2019-10-16 12:42:32.215404 TID:16 (PRI) (ENT) (CP) PoolManager.ctor()
2019-10-16 12:42:32.217209 TID:16 (PRI) (EXT) (CP) PoolManager.ctor()
2019-10-16 12:42:32.219060 TID:16 (PRI) (ENT) (CP) PoolManager.Initialize() (constr=User Id=PROJECTMOON_DEV;Data Source=invmapplorac3b1:1521/fareeagle;)
2019-10-16 12:42:32.221648 TID:16 (PRI) (EXT) (CP) PoolManager.Initialize() (pmid=10818129) (constr=User Id=PROJECTMOON_DEV;Data Source=invmapplorac3b1:1521/fareeagle;)
2019-10-16 12:42:32.229329 TID:16 (PRI) (BUF) (OBP.CTOR) (poolid:8253412) (OracleConnectionDispenser`3.GetPM)
2019-10-16 12:42:32.234281 TID:16 (PRI) (ENT) (CP) OraclePoolManager.Get()
2019-10-16 12:42:32.340199 TID:16 (PRI) (ENT) (CP) PoolManager.Get() (txnid=n/a) (bForceMatch=F)
2019-10-16 12:42:32.340819 TID:16 (PRI) (ENT) (CP) PoolManager.Get() MultiTenant : Searching for a idle connection, retryCountWithoutAffinity: 0
2019-10-16 12:42:32.345775 TID:16 (PRI) (ENT) PoolManager.ProcessCriteriaCtx_NonEnlistedConnection()
2019-10-16 12:42:32.345832 TID:16 (PRI) (EXT) PoolManager.ProcessCriteriaCtx_NonEnlistedConnection()
2019-10-16 12:42:32.354709 TID:16 (PRI) (ENT) (CP) PoolManager.CreateNewPR() (txnid=n/a)
2019-10-16 12:42:33.533596 TID:16 (PRI) (ENT) TimeStamp.GetLocalTZOffset()
2019-10-16 12:42:33.535150 TID:16 (PRI) (EXT) TimeStamp.GetLocalTZOffset()
2019-10-16 12:42:33.539004 TID:15 (PRI) (ENT) (CP) PoolManager.CreateNewPRThreadFunc()
2019-10-16 12:42:33.539290 TID:15 (PRI) (ENT) (CP) PoolManager.CreateNewPRThreadFunc() (initiated by TID:16)
2019-10-16 12:42:33.548479 TID:15 (PRI) (SVC) (ENT) OracleConnectionImpl.Connect() (oper=open) (aff=n/a) (inst=) (affmatch=n/a) (pr.service=) (pr.pdb=) (pr.edition=) (sessid=-1:-1) (F;F;F;;N) (pmid=10818129)
2019-10-16 12:42:33.549371 TID:15 (PRI) (BUF) (COBP.CTOR) (poolid:1) (parentpoolid:8253412) (OracleConnectionImpl.Connect)
2019-10-16 12:42:33.613320 TID:15 (CFG) (SQLNET) FilePath : (null)
2019-10-16 12:42:33.613410 TID:15 (CFG) (TNSNAMES) FilePath : (null)
2019-10-16 12:42:33.651675 TID:15 (NET) (ENT) EZConnect.ResolveSimple()
2019-10-16 12:42:33.651838 TID:15 (NET) Resolving EZConnect+ string: invmapplorac3b1:1521/fareeagle
2019-10-16 12:42:33.711440 TID:15 (NET) (EXT) EZConnect.ResolveSimple()
2019-10-16 12:42:33.738085 TID:15 (NET) (ENT) TcpTransportAdapter.Connect()
2019-10-16 12:42:33.741708 TID:15 (NET) Trying (host=invmapplorac3b1) (port=1521)
2019-10-16 12:42:33.741754 TID:15 (NET) (ENT) TcpTransportAdapter.Connect()
2019-10-16 12:42:33.743947 TID:15 (NET) (ENT) TcpTransportAdapter.ConnectIterate()
2019-10-16 12:42:33.744742 TID:15 (NET) Trying (address=10.0.116.106) (port=1521)

And a bit further down, here is more logging where the error seems to happen (I have removed some of the generated stuff so that it could be more readable)

AUTH_TERMINAL.!!baseapp-helm-dev-56b96fd86b-jmr7s AUTH_PROGRAM_NM...NetCoreBaseApp.dll AUTH_MACHINE.CCbaseapp-helm-dev-56b96fd86b-jmr7s\baseapp-helm-dev-56b96fd86b-jmr7s AUTH_PID...1:1 AUTH_SID...baseappuser
AUTH_CONNECT_STRING...(DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=invmapplorac3b1)(PORT=1521))(CONNECT_DATA=(SERVICE_NAME=fareeagle)(CID=(PROGRAM=/src/app/NetCoreBaseApp.dll)(HOST=baseapp-helm-dev-56b96fd86b-jmr7s)(USER=baseappuser))))..
..SESSION_CLIENT_CHARSET...178 SESSION_CLIENT_LIB_TYPE...0 SESSION_CLIENT_DRIVER_NAME...ODPC.NET : 19.1.0.0.0 SESSION_CLIENT_VERSION...318832640 SESSION_CLIENT_LOBATTR...1

AUTH_ALTER_SESSION.YYALTER SESSION SET NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA' TIME_ZONE='Etc/GMT'...

(PRI) (TTC) (ENT) TTCAuthenticate.ReceiveOAuthResponse()

AMERICAN AMERICA $ AMERICA, WE8MSWIN1252 GREGORIAN DD-MON-RR AMERICAN BINARY HH.MI.SSXFF AM.9 DD-MON-RR HH.MI.SSXFF AM.:HH.MI.SSXFF AM TZR.;.DD-MON-RR HH.MI.SSXFF AM TZR.<$.4 BINARY.2 BYTE.= FALSE.> .<< .
ORA-00604: error occurred at recursive SQL level 1.ORA-06502: PL/SQL: numeric or value error: character string buffer too small.ORA-06512: at line 18.

[alexkeh]

Could be Bug 30355981 as symptoms are very similar. This bug hasn't been fixed yet.

[alexkeh]

@grey007
What OS and version are you running your .NET Core 3 app on?

[0x4Graham]

I cannot access that information that bug information, I don't have access.

OS Version : Unix 4.19.50.1
NET Core Runtime Version : 3.0.0
Oracle Data Provider for .NET Core Driver Version : 2.0.19.1
Oracle db: 12g
Kubernetes Version: 14

[0x4Graham]

We're able to catch on the DB side that it is able to make a connection and it executes the following command:

ALTER SESSION SET NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA' TIME_ZONE='Etc/GMT'.

The driver then can't hand what is being returned. Seems to be a .NET issue as the Java application connecting from Kubernetes work fine.

If you change your application to use the HostNetwork of Kubernetes, it also works. However this not ideal and would rather fix the root cause first.

[0x4Graham]

Maybe just to add. I don't think it's a Kubernetes related issue.

From my further debugging I came across the following:

When running on my local machine, the following command gets executed
ALTER SESSION SET NLS_LANGUAGE='AMERICAN' NLS_TERRITORY='AMERICA' TIME_ZONE='Etc/GMT'.

And then returns:

[16]AUTH_NLS_LXLAN ==> AMERICAN[9]AUTH_NLS_LXCTERRITORY ==> AMERICA[0]AUTH_NLS_LXCCURRENCY ==> $[1]AUTH_NLS_LXCISOCURR ==&gt; AMERICA[2]AUTH_NLS_LXCNUMERICS ==&gt; .,[10]SESSION_NLS_LXCCHARSET ==&gt; WE8MSWIN1252[12]AUTH_NLS_LXCCALENDAR ==&gt; GREGORIAN[7]AUTH_NLS_LXCDATEFM ==&gt; DD-MON-RR[8]AUTH_NLS_LXCDATELANG ==&gt; AMERICAN[11]AUTH_NLS_LXCSORT ==&gt; BINARY[57]AUTH_NLS_LXCTIMEFM ==&gt; HH.MI.SSXFF AM[58]AUTH_NLS_LXCSTMPFM ==&gt; DD-MON-RR HH.MI.SSXFF AM[59]AUTH_NLS_LXCTTZNFM ==&gt; HH.MI.SSXFF AM TZR[60]AUTH_NLS_LXCSTZNFM ==&gt; DD-MON-RR HH.MI.SSXFF AM TZR[52]AUTH_NLS_LXCUNIONCUR ==&gt; $[50]AL8KW_NLSCOMP ==> BINARY[61]SESSION_NLS_LXCNLSLENSEM ==> BYTE[62]SESSION_NLS_LXCNCHAREXCP ==> FALSE[163] ==> € €�µ<<€

When I run on Kubernetes, the same command get executed but the trace provides the following:

2019-10-17 07:19:08.583496 TID:22 (NET) (SND) 00 00 00 0B 0C 00 00 00 |........|
2019-10-17 07:19:08.583512 TID:22 (NET) (SND) 01 00 02 |... |
2019-10-17 07:19:08.584782 TID:22 (NET) (REC) New receive packet. Header:
2019-10-17 07:19:08.584833 TID:22 (NET) (REC) 00 00 01 F4 06 00 00 00 |........|
2019-10-17 07:19:08.584841 TID:22 (NET) (REC) 00 00 |.. |
2019-10-17 07:19:08.584871 TID:22 (NET) (REC) 17 05 01 01 10 01 13 16 |........|
2019-10-17 07:19:08.584882 TID:22 (NET) (REC) 00 01 08 08 41 4D 45 52 |....AMER|
2019-10-17 07:19:08.584885 TID:22 (NET) (REC) 49 43 41 4E 01 10 00 01 |ICAN....|
2019-10-17 07:19:08.584887 TID:22 (NET) (REC) 07 07 41 4D 45 52 49 43 |..AMERIC|
2019-10-17 07:19:08.584890 TID:22 (NET) (REC) 41 01 09 00 01 01 01 24 |A......$|
2019-10-17 07:19:08.584892 TID:22 (NET) (REC) 00 00 01 07 07 41 4D 45 |.....AME|
2019-10-17 07:19:08.584895 TID:22 (NET) (REC) 52 49 43 41 01 01 00 01 |RICA....|
2019-10-17 07:19:08.584897 TID:22 (NET) (REC) 02 02 2E 2C 01 02 00 01 |...,....|
2019-10-17 07:19:08.584900 TID:22 (NET) (REC) 0C 0C 57 45 38 4D 53 57 |..WE8MSW|
2019-10-17 07:19:08.584902 TID:22 (NET) (REC) 49 4E 31 32 35 32 01 0A |IN1252..|
2019-10-17 07:19:08.584905 TID:22 (NET) (REC) 00 01 09 09 47 52 45 47 |....GREG|
2019-10-17 07:19:08.584907 TID:22 (NET) (REC) 4F 52 49 41 4E 01 0C 00 |ORIAN...|
2019-10-17 07:19:08.584910 TID:22 (NET) (REC) 01 09 09 44 44 2D 4D 4F |...DD-MO|
2019-10-17 07:19:08.584914 TID:22 (NET) (REC) 4E 2D 52 52 01 07 00 01 |N-RR....|
2019-10-17 07:19:08.584917 TID:22 (NET) (REC) 08 08 41 4D 45 52 49 43 |..AMERIC|
2019-10-17 07:19:08.584919 TID:22 (NET) (REC) 41 4E 01 08 00 01 06 06 |AN......|
2019-10-17 07:19:08.584922 TID:22 (NET) (REC) 42 49 4E 41 52 59 01 0B |BINARY..|
2019-10-17 07:19:08.584924 TID:22 (NET) (REC) 00 01 0E 0E 48 48 2E 4D |....HH.M|
2019-10-17 07:19:08.584927 TID:22 (NET) (REC) 49 2E 53 53 58 46 46 20 |I.SSXFF |
2019-10-17 07:19:08.584929 TID:22 (NET) (REC) 41 4D 01 39 00 01 18 18 |AM.9....|
2019-10-17 07:19:08.584931 TID:22 (NET) (REC) 44 44 2D 4D 4F 4E 2D 52 |DD-MON-R|
2019-10-17 07:19:08.584934 TID:22 (NET) (REC) 52 20 48 48 2E 4D 49 2E |R HH.MI.|
2019-10-17 07:19:08.584936 TID:22 (NET) (REC) 53 53 58 46 46 20 41 4D |SSXFF AM|
2019-10-17 07:19:08.584939 TID:22 (NET) (REC) 01 3A 00 01 12 12 48 48 |.:....HH|
2019-10-17 07:19:08.584941 TID:22 (NET) (REC) 2E 4D 49 2E 53 53 58 46 |.MI.SSXF|
2019-10-17 07:19:08.584946 TID:22 (NET) (REC) 46 20 41 4D 20 54 5A 52 |F AM TZR|
2019-10-17 07:19:08.584948 TID:22 (NET) (REC) 01 3B 00 01 1C 1C 44 44 |.;....DD|
2019-10-17 07:19:08.584951 TID:22 (NET) (REC) 2D 4D 4F 4E 2D 52 52 20 |-MON-RR |
2019-10-17 07:19:08.584953 TID:22 (NET) (REC) 48 48 2E 4D 49 2E 53 53 |HH.MI.SS|
2019-10-17 07:19:08.584956 TID:22 (NET) (REC) 58 46 46 20 41 4D 20 54 |XFF AM T|
2019-10-17 07:19:08.584958 TID:22 (NET) (REC) 5A 52 01 3C 00 01 01 01 |ZR.<....|
2019-10-17 07:19:08.584961 TID:22 (NET) (REC) 24 01 34 00 01 06 06 42 |$.4....B|
2019-10-17 07:19:08.584963 TID:22 (NET) (REC) 49 4E 41 52 59 01 32 00 |INARY.2.|
2019-10-17 07:19:08.584966 TID:22 (NET) (REC) 01 04 04 42 59 54 45 01 |...BYTE.|
2019-10-17 07:19:08.584968 TID:22 (NET) (REC) 3D 00 01 05 05 46 41 4C |=....FAL|
2019-10-17 07:19:08.584970 TID:22 (NET) (REC) 53 45 01 3E 00 01 0B 0B |SE.>....|
2019-10-17 07:19:08.584973 TID:22 (NET) (REC) 80 00 80 04 B5 3C 3C 80 |.....<<.|
2019-10-17 07:19:08.584975 TID:22 (NET) (REC) 00 00 00 01 A3 00 04 01 |........|
2019-10-17 07:19:08.584978 TID:22 (NET) (REC) 01 01 03 00 02 02 5C 00 |.......|
2019-10-17 07:19:08.584980 TID:22 (NET) (REC) 00 00 00 00 00 00 00 00 |........|
2019-10-17 07:19:08.584982 TID:22 (NET) (REC) 00 00 00 00 00 00 00 00 |........|
2019-10-17 07:19:08.584985 TID:22 (NET) (REC) 00 00 00 00 00 00 00 02 |........|
2019-10-17 07:19:08.584989 TID:22 (NET) (REC) 02 5C 00 96 4F 52 41 2D |...ORA-|
2019-10-17 07:19:08.584991 TID:22 (NET) (REC) 30 30 36 30 34 3A 20 65 |00604: e|
2019-10-17 07:19:08.584994 TID:22 (NET) (REC) 72 72 6F 72 20 6F 63 63 |rror occ|
2019-10-17 07:19:08.584996 TID:22 (NET) (REC) 75 72 72 65 64 20 61 74 |urred at|
2019-10-17 07:19:08.584998 TID:22 (NET) (REC) 20 72 65 63 75 72 73 69 | recursi|
2019-10-17 07:19:08.585001 TID:22 (NET) (REC) 76 65 20 53 51 4C 20 6C |ve SQL l|
2019-10-17 07:19:08.585003 TID:22 (NET) (REC) 65 76 65 6C 20 31 0A 4F |evel 1.O|
2019-10-17 07:19:08.585007 TID:22 (NET) (REC) 52 41 2D 30 36 35 30 32 |RA-06502|
2019-10-17 07:19:08.585009 TID:22 (NET) (REC) 3A 20 50 4C 2F 53 51 4C |: PL/SQL|
2019-10-17 07:19:08.585012 TID:22 (NET) (REC) 3A 20 6E 75 6D 65 72 69 |: numeri|
2019-10-17 07:19:08.585014 TID:22 (NET) (REC) 63 20 6F 72 20 76 61 6C |c or val|
2019-10-17 07:19:08.585016 TID:22 (NET) (REC) 75 65 20 65 72 72 6F 72 |ue error|
2019-10-17 07:19:08.585018 TID:22 (NET) (REC) 3A 20 63 68 61 72 61 63 |: charac|
2019-10-17 07:19:08.585021 TID:22 (NET) (REC) 74 65 72 20 73 74 72 69 |ter stri|
2019-10-17 07:19:08.585023 TID:22 (NET) (REC) 6E 67 20 62 75 66 66 65 |ng buffe|
2019-10-17 07:19:08.585026 TID:22 (NET) (REC) 72 20 74 6F 6F 20 73 6D |r too sm|
2019-10-17 07:19:08.585028 TID:22 (NET) (REC) 61 6C 6C 0A 4F 52 41 2D |all.ORA-|
2019-10-17 07:19:08.585030 TID:22 (NET) (REC) 30 36 35 31 32 3A 20 61 |06512: a|
2019-10-17 07:19:08.585033 TID:22 (NET) (REC) 74 20 6C 69 6E 65 20 31 |t line 1|
2019-10-17 07:19:08.585035 TID:22 (NET) (REC) 38 0A |8. |

Unjumbled, it looks like the following:

AMERICAN AMERICA $ AMERICA ., WE8MSWIN1252 GREGORIAN DD-MON-RR AMERICAN BINARY HH.MI.SSXFF AM DD-MON-RR HH.MI.SSXFF AM HH.MI.SSXFF AM TZR; DD-MON-RR HH.MI.SSXFF AM TZR.< $.4 BINARY 2BYTE FALSE.> .<<. ...

And so it looks to be failing on the data returned.

[alexkeh]

@christianshay
Do you have any recommendations or have you seen this before?

@grey007
I recommend upgrading to ODP.NET Core 19.5, which was just released yesterday. That version is certified for .NET Core 3. However, it's likely you will still hit this bug.

One follow up question is what is Unix 4.19.50.1? Is that macOS, one of the traditional Unix server OSes, or something else?

[0x4Graham]

I upgraded the driver to 19.5 and still had the same issue.

Unix 4.19.50.1 comes from the dotnet core 3.0-bionic SDK image found here: https://hub.docker.com/_/microsoft-dotnet-core-sdk

Also doesn't work on the base 3.0 SDK.

[christianshay]

@grey007. As Alex says, you may be hitting a known bug, but to be sure, can you please give us a testcase that reproduces outside of Kubernetes? A dockerfile plus some example code (as simple as possible) would be good enough. The full database version would be good too. Kubernetes adds a lot of complexity that makes it hard to work with so we should eliminate it from the testcase.

[0x4Graham]

Through lot's of debugging we found the issue. We had system triggers that were throwing errors when connecting to the db. We suspect that the container name was too long or something along those lines was causing the issue.

[alexkeh]

@grey007
Were you able to work around the issue then by shortening the container name?

[0x4Graham]

Instead of shortening the container name, we adjusted the trigger to accept more characters.