First pooled connection fails when using UseHourOffsetForUnsupportedTimezone

[Aaron-Ritter-IDEXX]

I'm using the Oracle.ManagedDataAccess.Core package version 23.6.1 (though this problem seems to be present in older versions as well) and trying to connect to a v.19c database with an old time zones file (v.14) from a system set to the UTC time zone. The first attempt to connect always fails with a "connection timeout", while subsequent attempts succeed.

It fails at first because the "Etc/UTC" zone isn't available in the database. Now, I have the UseHourOffsetForUnsupportedTimezone option enabled, so it then retries using the hour offset, but that fails due to a NullReferenceException inside the package code, and then the attempt to get a connection from the pool eventually times out.

Of course, we could try to update the database's time zone file, but this seems to be a potential bug in the package, so I'd like to discuss this first.

Here are some relevant parts from the trace log:

2024-12-18 19:08:23.947031 TID:12  (PRI) (TTC) (CID1) timezone_file version client: 43, server : 14  
2024-12-18 19:08:23.947482 TID:12  (PRI) (SVC) (EXT) (CID1) OracleConnectionImpl.DoDataTypeNegotiation()
2024-12-18 19:08:23.954282 TID:12  (PRI) (SVC) (ENT) (CID1) OracleConnectionImpl.DoAuthentication()
2024-12-18 19:08:23.958324 TID:12  (PRI) (SVC) (ENT) (CID1) OracleGlobalizationImpl.GetLocaleSpecificNLSValues() Connecting with session time zone as :Etc/UTC
2024-12-18 19:08:23.958847 TID:12  (PRI) (TTC) (ENT) (CID1) TTCAuthenticate.WriteOSessKeyMessage()

2024-12-18 19:08:23.987888 TID:12  (PRI) (TTC) (ENT) (CID1) TTCAuthenticate.ReceiveOAuthResponse()
2024-12-18 19:08:23.988346 TID:12  (NET) (REC) (CID1) ReaderStream.ProcessHeaderData() New receive packet with length:OB.DAFlags:DAFlags 11:0:0
2024-12-18 19:08:23.988383 TID:12  (NET) (REC) (CID1) 00 00 00 0B 0C 20 00 00   |..... ..|
2024-12-18 19:08:23.988388 TID:12  (NET) (REC) (CID1) 01 00                     |..      |
2024-12-18 19:08:23.988660 TID:12  (NET)       Got a BREAK marker packet
2024-12-18 19:08:23.988680 TID:12  (NET)       Marker data = 1
2024-12-18 19:08:23.988686 TID:12  (NET) (REC) (CID1) ReaderStream.ProcessHeaderData() Recv length:OB.DAFlags:DAFlags 11:0:0
2024-12-18 19:08:23.991992 TID:12  (NET) (SND) (CID1) Packet.send() data length = 11
2024-12-18 19:08:23.992035 TID:12  (NET) (SND) (CID1) 00 00 00 0B 0C 00 00 00   |........|
2024-12-18 19:08:23.992056 TID:12  (NET) (SND) (CID1) 01 00 02                  |...     |
2024-12-18 19:08:23.992535 TID:12  (NET) (REC) (CID1) ReaderStream.ProcessHeaderData() New receive packet with length:OB.DAFlags:DAFlags 11:0:0
2024-12-18 19:08:23.992558 TID:12  (NET) (REC) (CID1) 00 00 00 0B 0C 20 00 00   |..... ..|
2024-12-18 19:08:23.992563 TID:12  (NET) (REC) (CID1) 01 00                     |..      |
2024-12-18 19:08:23.992574 TID:12  (NET)       Got a RESET marker packet
2024-12-18 19:08:23.992580 TID:12  (NET)       Marker data = 2
2024-12-18 19:08:23.992598 TID:12  (NET) (REC) (CID1) ReaderStream.ProcessHeaderData() New receive packet with length:OB.DAFlags:DAFlags 135:0:0
2024-12-18 19:08:23.992612 TID:12  (NET) (REC) (CID1) 00 00 00 87 06 00 00 00   |........|
2024-12-18 19:08:23.992616 TID:12  (NET) (REC) (CID1) 00 00                     |..      |
2024-12-18 19:08:23.992624 TID:12  (NET) (REC) (CID1) 04 01 01 00 00 02 02 5C   |.......\|
2024-12-18 19:08:23.992626 TID:12  (NET) (REC) (CID1) 00 00 00 00 00 00 00 00   |........|
2024-12-18 19:08:23.992635 TID:12  (NET) (REC) (CID1) 00 00 00 00 00 00 00 00   |........|
2024-12-18 19:08:23.992637 TID:12  (NET) (REC) (CID1) 00 02 00 00 00 00 00 00   |........|
2024-12-18 19:08:23.992639 TID:12  (NET) (REC) (CID1) 02 02 5C 00 58 4F 52 41   |..\.XORA|
2024-12-18 19:08:23.992640 TID:12  (NET) (REC) (CID1) 2D 30 30 36 30 34 3A 20   |-00604: |
2024-12-18 19:08:23.992642 TID:12  (NET) (REC) (CID1) 65 72 72 6F 72 20 6F 63   |error oc|
2024-12-18 19:08:23.992644 TID:12  (NET) (REC) (CID1) 63 75 72 72 65 64 20 61   |curred a|
2024-12-18 19:08:23.992645 TID:12  (NET) (REC) (CID1) 74 20 72 65 63 75 72 73   |t recurs|
2024-12-18 19:08:23.992647 TID:12  (NET) (REC) (CID1) 69 76 65 20 53 51 4C 20   |ive SQL |
2024-12-18 19:08:23.992648 TID:12  (NET) (REC) (CID1) 6C 65 76 65 6C 20 31 0A   |level 1.|
2024-12-18 19:08:23.992650 TID:12  (NET) (REC) (CID1) 4F 52 41 2D 30 31 38 38   |ORA-0188|
2024-12-18 19:08:23.992651 TID:12  (NET) (REC) (CID1) 32 3A 20 74 69 6D 65 7A   |2: timez|
2024-12-18 19:08:23.992658 TID:12  (NET) (REC) (CID1) 6F 6E 65 20 72 65 67 69   |one regi|
2024-12-18 19:08:23.992660 TID:12  (NET) (REC) (CID1) 6F 6E 20 6E 6F 74 20 66   |on not f|
2024-12-18 19:08:23.992662 TID:12  (NET) (REC) (CID1) 6F 75 6E 64 0A            |ound.   |
2024-12-18 19:08:23.992668 TID:12  (NET) (REC) (CID1) ReaderStream.ProcessHeaderData() Recv length:OB.DAFlags:DAFlags 135:0:0

2024-12-18 19:08:24.002061 TID:12  (PRI) (SVC) (ERR) (CID1) OracleException.HandleError() from OracleConnectionImpl.DoAuthentication()(txnid=n/a) Oracle.ManagedDataAccess.Client.OracleException (0x80004005): ORA-00604: error occurred at recursive SQL level 1
ORA-01882: timezone region not found
https://docs.oracle.com/error-help/db/ora-00604/
   at OracleInternal.ServiceObjects.OracleConnectionImpl.CheckForAnyErrorFromDB(TTCError ttcOER, Object traceObj)
   at OracleInternal.ServiceObjects.OracleConnectionImpl.DoAuthentication(OracleConnection connRefForCriteria, String userId, OracleOpaqueString opaquePassw, String proxyUserId, OracleOpaqueString opaqueProxyPassw, OracleOpaqueString opaqueNewPassw, Boolean bDoExternalAuth, OracleAccessToken accessToken, Boolean bOpenEndUserSession, Boolean bAsync, Boolean bUsingFastConnect)

2024-12-18 19:08:24.002500 TID:12  (PRI) (SVC) (EXT) (CID1) 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=49068367) 
2024-12-18 19:08:24.002545 TID:12  (PRI) (CP)  PoolManager.CreateNewPRThreadFunc() Connection creation failed. (bMaxSemObtained = True) (m_bReconnectForReplay = None)
2024-12-18 19:08:24.002594 TID:12  (PRI) (CP)  PoolManager.CreateNewPRThreadFunc() [MAX:REL:18] PM.CreateNewPRThreadFunc() : Max Sempahore count=99
2024-12-18 19:08:24.002619 TID:12  (PRI) (CP)  PoolManager.CreateNewPRThreadFunc() [INCR:REL:2] PM.CreateNewPRThreadFunc() : Incr Sempahore count=4
2024-12-18 19:08:24.002672 TID:4   (PRI) (CP)  PoolManager.CreateNewPR() New connection is available
2024-12-18 19:08:24.002701 TID:4   (PRI) (ENT) (CP) PoolManager.CreateNewPR() (TIMEOUT) (G)
2024-12-18 19:08:24.002738 TID:4   (PRI) (ENT) (CP) PoolManager.CreateNewPR() ORA-01882: timezone region not found 49068367
2024-12-18 19:08:24.002746 TID:4   (PRI) (ENT) (CP) PoolManager.CreateNewPR() UseHourOffsetForUnsupportedTimezone is true. Try Connecting with session time zone as the hour offset
2024-12-18 19:08:24.002741 TID:12  (PRI) (EXT) (CP) PoolManager.CreateNewPRThreadFunc()
2024-12-18 19:08:24.002751 TID:4   (PRI) (ENT) (CP) PoolManager.CreateNewPR() Connecting with session time zone as the hour offset
2024-12-18 19:08:24.002789 TID:4   (PRI) (CP)  PoolManager.CreateNewPR() Waiting for idle connection to be available or new connection to be created

Finally, here's where it starts to retry the connection using the hour offset, which fails:

2024-12-18 19:08:24.703764 TID:7   (PRI) (SVC) (ENT) (CID1) OracleGlobalizationImpl.GetLocaleSpecificNLSValues() Connecting with session time zone as :+00:00
2024-12-18 19:08:24.703913 TID:7   (PRI) (ENT) (CID1) OracleException.HandleError() from OracleConnectionImpl.Connect()
2024-12-18 19:08:24.704144 TID:7   (PRI) (SVC) (ERR) (CID1) OracleException.HandleError() from OracleConnectionImpl.Connect()(txnid=n/a) System.NullReferenceException: Object reference not set to an instance of an object.
   at OracleInternal.TTC.TTCAuthenticate.ReInit(MarshallingEngine marshallingEngine, Int32 lcid, Boolean b_setUseHourOffset)
   at OracleInternal.ServiceObjects.OracleConnectionImpl.Connect(ConnectionString cs, Boolean bOpenEndUserSession, OracleConnection connRefForCriteria, String instanceName, Boolean bAsync)
2024-12-18 19:08:24.704173 TID:7   (PRI) (EXT) (CID1) OracleException.HandleError() from OracleConnectionImpl.Connect()
2024-12-18 19:08:24.704233 TID:7   (PRI) (SVC) (ENT) OracleConnectionImpl.get_ServiceName() (CONNECTION_OPTION:SERVICE_NAME=) (ISNULL=FALSE)
2024-12-18 19:08:24.704260 TID:7   (PRI) (SVC) (EXT) (CID1) 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=49068367) 
2024-12-18 19:08:24.704280 TID:7   (PRI) (CP)  PoolManager.CreateNewPRThreadFunc() Connection creation failed. (bMaxSemObtained = True) (m_bReconnectForReplay = None)
2024-12-18 19:08:24.704596 TID:7   (PRI) (ENT) OracleException.HandleError() from PoolManager.CreateNewPRThreadFunc()
2024-12-18 19:08:24.704728 TID:7   (PRI) (ERR) (CP) OracleException.HandleError() from PoolManager.CreateNewPRThreadFunc()(txnid=n/a) System.Exception: m_semIncrPoolSize.Release() threw exception with count = 4
   at OracleInternal.ConnectionPool.PoolManager`3.CreateNewPRThreadFunc(Object state)
2024-12-18 19:08:24.704749 TID:7   (PRI) (EXT) OracleException.HandleError() from PoolManager.CreateNewPRThreadFunc()
2024-12-18 19:08:24.704765 TID:7   (PRI) (EXT) (CP) PoolManager.CreateNewPRThreadFunc()
2024-12-18 19:09:09.002089 TID:4   (PRI) (ENT) (CP) PoolManager.CreateNewPR() (TIMEOUT) (G)

Note the NullReferenceException deep in TTCAuthenticate. This seems to be out of my control. Note also that the final (TIMEOUT) log line is from 45 seconds later; I have the connection timeout set to 45 seconds.

[alexkeh]

I've created Bug 37419098 to track this issue.

[alexkeh]

@Aaron-Ritter-IDEXX Can you provide the full ODP.NET trace? You can either post it to this thread or email it to dotnet_us(at)oracle.com.

[alexkeh]

@Aaron-Ritter-IDEXX This is a reminder to provide the full ODP.NET trace so that the ODP.NET dev team can debug the issue.

[Aaron-Ritter-IDEXX]

@alexkeh

Thanks, and sorry for the delay. I went on a long vacation just before you responded. I meant to check in on this occasionally, but I got caught up in the festivities and forgot about it.

I have emailed a full log, since it contains data that I'd rather not make public.

[Aaron-Ritter-IDEXX]

Come to think of it, I believe we encountered the same problem in the Oracle.ManagedDataAccess package for .NET Framework, in versions 21.x.x and up, which is why we're still using the 19.x.x one. Back then, I didn't dig into the trace logs, but it had the same symptom of the first connection often timing out.