Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Connection request timed out

[sungam3r]

Hi. We were faced with the fact that we began to constantly receive exceptions in various of our services associated with a timeout when establishing a connection:

Oracle.ManagedDataAccess.Client.OracleException (0x80004005): Connection request timed out
   at OracleInternal.ConnectionPool.PoolManager`3.Get(ConnectionString csWithDiffOrNewPwd, Boolean bGetForApp, OracleConnection connRefForCriteria, String affinityInstanceName, Boolean bForceMatch)
   at OracleInternal.ConnectionPool.OraclePoolManager.Get(ConnectionString csWithNewPassword, Boolean bGetForApp, OracleConnection connRefForCriteria, String affinityInstanceName, Boolean bForceMatch)
   at OracleInternal.ConnectionPool.OracleConnectionDispenser`3.Get(ConnectionString cs, PM conPM, ConnectionString pmCS, SecureString securedPassword, SecureString securedProxyPassword, OracleConnection connRefForCriteria)
   at Oracle.ManagedDataAccess.Client.OracleConnection.Open()
   at System.Data.Common.DbConnection.OpenAsync(CancellationToken cancellationToken)
--- End of stack trace from previous location where exception was thrown ---
   at Microsoft.EntityFrameworkCore.Storage.RelationalConnection.OpenDbConnectionAsync(Boolean errorsExpected, CancellationToken cancellationToken)

Oracle.EntityFrameworkCore 3.19.80
Oracle.ManagedDataAccess.Core 2.19.80/100

Errors occur both on test environments and in production. At first I suspected that our services were exhausting all available connections in the connection pool (we use pooling as it is enabled by default). I thought about this after reading the documentation. So I wanted to test the hypothesis using performance counters (see #123) but counters work only on Windows and our backend runs in Kubernetes. So I started looking for other ways. I knew about the possibilities to enable tracing. At the same time, I did not want to load our services with tracing. In addition, the trace is not very convenient to write to a file. So I wanted to manually access the inner classes and read the state of the connection pool. Fortunately, I noticed the OracleConnection.Dump() method, which is also used by the tracing itself. I examined the source code for this method and realized that it outputs the status of the pool - the total number of connections in the pool and the number of free connections. This information was perfect for me for analysis. I started calling this method in EF Core interceptor every time a connection level error occurred (Microsoft.EntityFrameworkCore.Diagnostics.ConnectionErrorEventData). The results surprised me. It turns out that the error in most cases occurs when the pool is empty. Output from OracleConnection.Dump():

(DUMP)

What can you advise in such a situation? Also I saw this article.
I want to note that we get errors even during the initial warm up of the services, when we make a call to our databases in advance.

[alexkeh]

Running out of connections to dispense could occur because the Max Pool Size has been hit. At that point, you could increase the Max Pool Size. Also, ensure your DB server too can service the additional sessions.

If the problem is due a connection storm, you have various options to alleviate the issue. You could increase the Min Pool Size to have a larger number of connections ready to be dispensed. You could increase the Connection Timeout to provide ODP.NET more time to acquire a connection. On the DB side, you can set the Connection Rate Limiter to slow down the connection creation rate so as not to overload the DB during a connection storm.

[sungam3r]

It is 100% not due to Max Pool Size. What is a connection storm?

[sungam3r]

Also our connection strings:

dev: Data Source=(DESCRIPTION=(ADDRESS_LIST=(ADDRESS=(PROTOCOL=TCP)(HOST=srvname)(PORT=1525)))(CONNECT_DATA=(SERVER=DEDICATED)(SERVICE_NAME=name)));User Id=user;Password=pwd

prod: Data Source=(DESCRIPTION=(ENABLE=BROKEN)(LOAD_BALANCE=off)(FAILOVER=on)(TRANSPORT_CONNECT_TIMEOUT=10)(ADDRESS=(PROTOCOL=tcp)(HOST=srvname)(PORT=1526))(ADDRESS=(PROTOCOL=tcp)(HOST=srvname)(PORT=1526))(CONNECT_DATA=(SERVICE_NAME=name)(FAILOVER_MODE=(TYPE=session)(METHOD=basic))));User Id=user;Password=pwd

[alexkeh]

A connection storm is a race condition in which connection requests are made much faster than the DB server or DB provider can complete them.

If you're finding that the connection pool is empty when the error occurs and you still have more connections available before hitting Max Pool Size, then raise the Min Pool Size higher and/or increase your Incr Pool Size so that the pool grows faster if your user connection requests tend to increase quickly.

[sungam3r]

Do I understand correctly that for the initial filling of the pool to the Min Pool Size, at least one query to the database must be executed?

[alexkeh]

No need to query. Just the one connection needs to be opened for the ODP.NET to initial filing the pool to at least the Min Pool Size. It's a good practice to populate the pool with sufficient connections to service end users if they all attempt to log in at around the same time, such as when the business day begins. Thus, the first connection should be made early on.

Even if your pool is idle for a long time, the number of connections will not fall below the number of connections for Min Pool Size under normal circumstances.

[sungam3r]

OK. Good. I just meant that we need to initiate the opening of at least one connection. We are just getting an error in this situation. We also began to see this error:

---> Oracle.ManagedDataAccess.Client.OracleException (0x80004005): ORA-12570: Network Session: Unexpected packet read error
     ---> OracleInternal.Network.NetworkException (0x80004005): ORA-12570: Network Session: Unexpected packet read error
     ---> System.Net.Sockets.SocketException (10060): A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond.
       at OracleInternal.Network.ReaderStream.Read(OraBuf OB)
       at OracleInternal.Network.ReaderStream.Read(OraBuf OB)
       at OracleInternal.TTC.OraBufReader.GetDataFromNetwork()
       at OracleInternal.TTC.OraBufReader.Read(Boolean bIgnoreData)
       at OracleInternal.TTC.TTCExecuteSql.ReceiveExecuteResponse(Accessor[]& defineAccessors, Accessor[] bindAccessors, Boolean bHasReturningParams, SQLMetaData& sqlMetaData, SqlStatementType statementType, Int64 noOfRowsFetchedLastTime, Int32 noOfRowsToFetch, Int32& noOfRowsFetched, Int64& queryId, Int32 longFetchSize, Int64 initialLOBFetchSize, Int64[] scnFromExecution, Boolean bAllInputBinds, Int32 arrayBindCount, DataUnmarshaller& dataUnmarshaller, MarshalBindParameterValueHelper& marshalBindParamsHelper, Int64[]& rowsAffectedByArrayBind, Boolean bDefineDone, Boolean& bMoreThanOneRowAffectedByDmlWithRetClause, List`1& implicitRSList, Boolean bLOBArrayFetchRequired)
       at Oracle.ManagedDataAccess.Client.OracleException.HandleError(OracleTraceLevel level, OracleTraceTag tag, OracleTraceClassName className, OracleTraceFuncName funcName, Exception ex, OracleLogicalTransaction oracleLogicalTransaction)
       at OracleInternal.TTC.TTCExecuteSql.ReceiveExecuteResponse(Accessor[]& defineAccessors, Accessor[] bindAccessors, Boolean bHasReturningParams, SQLMetaData& sqlMetaData, SqlStatementType statementType, Int64 noOfRowsFetchedLastTime, Int32 noOfRowsToFetch, Int32& noOfRowsFetched, Int64& queryId, Int32 longFetchSize, Int64 initialLOBFetchSize, Int64[] scnFromExecution, Boolean bAllInputBinds, Int32 arrayBindCount, DataUnmarshaller& dataUnmarshaller, MarshalBindParameterValueHelper& marshalBindParamsHelper, Int64[]& rowsAffectedByArrayBind, Boolean bDefineDone, Boolean& bMoreThanOneRowAffectedByDmlWithRetClause, List`1& implicitRSList, Boolean bLOBArrayFetchRequired)
       at OracleInternal.ServiceObjects.OracleCommandImpl.ExecuteReader(String commandText, OracleParameterCollection paramColl, CommandType commandType, OracleConnectionImpl connectionImpl, OracleDataReaderImpl& rdrImpl, Int32 longFetchSize, Int64 clientInitialLOBFS, OracleDependencyImpl orclDependencyImpl, Int64[] scnForExecution, Int64[]& scnFromExecution, OracleParameterCollection& bindByPositionParamColl, Boolean& bBindParamPresent, Int64& internalInitialLOBFS, OracleException& exceptionForArrayBindDML, OracleConnection connection, OracleLogicalTransaction& oracleLogicalTransaction, IEnumerable`1 adrianParsedStmt, Boolean isDescribeOnly, Boolean isFromEF)
       at Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteReader(Boolean requery, Boolean fillRequest, CommandBehavior behavior)
       at Oracle.ManagedDataAccess.Client.OracleCommand.ExecuteDbDataReader(CommandBehavior behavior)
       at System.Data.Common.DbCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
    --- End of stack trace from previous location where exception was thrown ---
       at Oracle.EntityFrameworkCore.Storage.Internal.OracleRelationalCommandBuilderFactory.OracleRelationalCommandBuilder.OracleRelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
       at Oracle.EntityFrameworkCore.Storage.Internal.OracleRelationalCommandBuilderFactory.OracleRelationalCommandBuilder.OracleRelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
       at Oracle.EntityFrameworkCore.Storage.Internal.OracleRelationalCommandBuilderFactory.OracleRelationalCommandBuilder.OracleRelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
       at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(DbContext _, Boolean result, CancellationToken cancellationToken)
       at Oracle.EntityFrameworkCore.Storage.Internal.OracleExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
       at Microsoft.EntityFrameworkCore.Query.Internal.QueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()
       at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
       at Microsoft.EntityFrameworkCore.Query.ShapedQueryCompilingExpressionVisitor.SingleAsync[TSource](IAsyncEnumerable`1 asyncEnumerable, CancellationToken cancellationToken)
       --- End of inner exception stack trace ---

And the next launch of the same code is successful. We have suspicions that this is due to the entire network infrastructure. Can you give any advice on how this can be diagnosed? Or what can we do? Any special connection string settings possible?

[sungam3r]

Logs from server:

 [19:44:31:288] nscon: doing connect handshake...
 [19:44:31:288] nscon: recving a packet
 [19:44:31:288] nsprecv: entry
 [19:44:31:288] nsprecv: reading from transport...
 [19:44:31:288] nttrd: entry
 [19:44:31:288] nttrd: exit
 [19:44:31:288] ntt2err: entry
 [19:44:31:288] ntt2err: Read unexpected EOF ERROR on 15

UPDATE! This log was taken from our test server and may not be relevant to the problem under discussion at all.

[sungam3r]

Also from client logs we see this: 2020-11-25 11:58:18.578055 ThreadID:1 (ERROR) OracleDatabaseCreator.ExistsAsync() : OracleException.Number: -1000

Note the negative value. I couldn't find any documentation for it.

[sungam3r]

Our research led us here:

ODPM: Connection FailOver Not Working With Default Connection Timeout Value (Doc ID 2423780.1)
+
BUG 22480200 ODPM CONNECTION FAIL OVER NOT WORKING WITH TIMEOUT PROPERTIES
+
Bug 27977039 - ODPM: Connection FailOver Bug 224802200 Backport to 18.1 (Doc ID 27977039.8)

Using ODP.NET Managed driver, connection failover is not happening with default connection timeout. The Failover feature only works if the connection timeout is set to 21 seconds or more

[alexkeh]

I would recommend checking with your network engineer. It could be something specific to the network setup or something happening on the DB side. With so many different types of connection issue and at different times, the error source is likely outside of ODP.NET or at least reliant on some external factor.

The -1000 is sort of a catch all error that ODP.NET uses when something very unusual happens or the error initiates outside ODP.NET itself.

I've seen situations in which cloud firewalls timeout connections that are idle for several minutes. This is the default unless the TCP idle timeout is changed. If it cannot be changed, ODP.NET KeepAlive can be used.

It could be a failover issue if a DB node or DB is failing over right after the error occurs.

[sungam3r]

Good news. After rolling back Oracle.ManagedDataAccess.Core from 2.19.100 to 2.19.80 the service started without problems. Based on our experiments, I get the impression that some internal backward incompatible changes were made between versions 80 and 100, which affected the success of the connection. These changes influenced the fact that the bugs described above began to appear. Perhaps some of the default values have been changed in the code?

Our connection string (which works fine in sqlplus but gives timeout in production):

(DESCRIPTION=
   (ENABLE=BROKEN)
     (LOAD_BALANCE=off)
                   (FAILOVER=on)
                     (TRANSPORT_CONNECT_TIMEOUT=10)
                               (ADDRESS=(PROTOCOL=tcp)(HOST=srv1)(PORT=1526))
                               (ADDRESS=(PROTOCOL=tcp)(HOST=srv2)(PORT=1526))
   (CONNECT_DATA=(SERVICE_NAME=abcdef)(FAILOVER_MODE=(TYPE=session)(METHOD=basic))))

We weren't hoping that rolling back to version 80 would fix the problem. We expected to do another experiment, namely to swap the names of the two hosts (srv1 and srv2) used in the connection string. The assumption is Oracle.ManagedDataAccess.Core client tries to connect to hosts in order and cannot failover if the first one not primary.

@alexkeh I will be very grateful to you for any information. I know that some bugs were fixed in version 100, but we cannot use it now.

[sungam3r]

To clarify, I meant that the failover mechanism does not work (presumably). The first in the list is the host on which the listener is running, and this listener does not have a service_name registered. There should be a failover - the search should continue further, but something wrong happens.

[alexkeh]

The bugs fixed for each new ODP.NET Core are documented in each NuGet package README. Here are the bugs fixed in the 19.9 patch:
31873207 ORA-12614 ENCOUNTERED WHILE USING SINGLE-SESSION PROXY AUTHENTICATION
26123054 "UNEXPECTED PACKET RECEIVED" ERROR IS ENCOUNTERED WHEN NULL RETURNED FROM A SELECT QUERY
29669425 GETDECIMAL() THROWS SYSTEM.INVALIDCASTEXCEPTION: 'SPECIFIED CAST IS NOT VALID.'
31626886 KEEPALIVE ON LINUX AND MACOS VIA NEW CORE INTERFACE
32067106 BULKCOPY IS NOT WORKING WITH ODPM/C
32033930 TWO-SESSION PROXY CONNECTION USING SEPS FAILS WITH ORA-01017
31917192 DESERIALIZATION OF XML FILE WITH ORACLE PROVIDER TYPES THROWS EXCEPTION

For the 19.10 patch:
31386112 - DERIVEDPARAMETERS ENCOUNTERS ORA-00418 FOR TABLE_TYPE OUTPUT PARAMETER
31637904 - UNABLE TO PROCESS IN-BAND NOTIFICATION FOR CMAN OUTAGE AND PDB RELOCATION
31537092 - ACCUMULATION OF SOCKETS WITH CLOSE_WAIT STATE
31226406 - EZCONNECT+ DOES NOT SUPPORT DRCP CONNECTION CLASS AND PURITY

Do any of these bug fixes affect ODP.NET functionality you use? I don't see any that affect failover directly. It's possible a code change was made to fix an internally found bug not part of the public bug list.

[sungam3r]

Do any of these bug fixes affect ODP.NET functionality you use?

I'm not sure. Probably not.

It's possible a code change was made to fix an internally found bug not part of the public bug list.

I think that in our case it should be called a regression rather than a fix. 2.19.80 works fine, 1.19.100 gives timeout and the inability to connect to the database. Tomorrow I will have time to do more experiments. I'm interested in the behavior of v2.19.90.