Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

First pooled connection fails when using UseHourOffsetForUnsupportedTimezone #429

Open
Aaron-Ritter-IDEXX opened this issue Dec 18, 2024 · 11 comments
Labels

Comments

@Aaron-Ritter-IDEXX
Copy link

Aaron-Ritter-IDEXX commented Dec 18, 2024

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 alexkeh added the bug label Dec 20, 2024
@alexkeh
Copy link
Member

alexkeh commented Dec 20, 2024

I've created Bug 37419098 to track this issue.

@alexkeh
Copy link
Member

alexkeh commented Dec 21, 2024

@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
Copy link
Member

alexkeh commented Jan 8, 2025

@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
Copy link
Author

@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
Copy link
Author

Aaron-Ritter-IDEXX commented Jan 15, 2025

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.

@Aaron-Ritter-IDEXX
Copy link
Author

@alexkeh a reminder that this is open

@alexkeh
Copy link
Member

alexkeh commented Jan 29, 2025

I've asked the developer reviewing the issue for an update. I'll let you know what he says when he reports back.

@alexkeh
Copy link
Member

alexkeh commented Jan 30, 2025

@Aaron-Ritter-IDEXX My team has been unable to reproduce the problem with your setup details so far. However, we have an idea of what the problem is and created a combination diagnostic fix. The fix may work, but if not, it includes enhanced diagnostics for us to diagnose it better.

We cannot distribute diagnostic software via NuGet Gallery. Can you open up an Oracle Support service request? If you don't know how, your DBA does. Once the SR is open, inform the support analyst you are hitting bug 37419098 and working with me directly on the Oracle DB ODP.NET team. The analyst can then give you access to the diagnostic fix that will be part of the bug log.

The problem will be resolved or not. If resolved, we'll incorporate the fix into the ODP.NET code line. If not, you'll share the enhanced diagnostics and upload those to the SR for us to analyze and we'll give you a new drop to validate.

@Aaron-Ritter-IDEXX
Copy link
Author

@alexkeh Alright, sounds like a good plan. I'll ask our DBA team to get it started.

@Aaron-Ritter-IDEXX
Copy link
Author

FYI, I was told earlier in the week that the build is "in processing" and am waiting for further updates.

@alexkeh
Copy link
Member

alexkeh commented Feb 7, 2025

We had some problems building the diagnostic fix. I think they were resolved. We should have the possible fix available to try out soon.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

2 participants