Open
Description
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.