What causes SocketException with Entity Framework Core, npgsql and RDS proxy?

Question

We're currently using .NET Core 7 with Npgsql.EntityFrameworkCore.PostgreSQL 7.0.4.

We're using AWS RDS Proxy in front of RDS Aurora Postgres. Our proxy has an idle connection timeout of 30 minutes. The proxy manages its own connection pool.

In the application, we register DbContext with something along the lines of

.AddDbContextPool<SomeDbContext>((opts, options) =>
{
    string connectionString = “server=***;port=*****;userid=***;password=***;database=***;pooling=true;Maximum Pool Size=750;”;
    options.UseNpgsql(connectionString);
})

The issue we are seeing is a SocketException (125). I can't seem to find any background on what could cause an socket exception with npgsql, I have my suspicions but am hoping you may have other ideas on what could be done here. I'm looking for assistance on the following questions:

If RDS proxy manages connection pooling, is it best practice to NOT use connection pooling at the application (entity framework) layer?
What could cause these SocketExceptions? I'm thinking it could be something at the proxy terminated the connection, but I cannot prove this out.
Would adding opts => { opts.EnableRetryOnFailure(); } the UseNpgsql call assist with these SocketExceptions? Is there any downside or recommendations on what to use for EnableRetryOnFailure?
We're seeing the client session was pinned to the database connection [dbConnection=3708774091] for the remainder of the session. The proxy can't reuse this connection until the session ends. Reason: A parse message was detected in our database logs.

Would EF application layer connection pooling cause this session pinning at the database layer?

We did receive two exceptions at 2023-08-23T14:04:33.0203540Z and 2023-08-23T14:04:22.5017591Z.

I'm attaching our RDS proxy logs for around this timeframe as well

Here is the full stack trace:

System.InvalidOperationException: An exception has been raised that is likely due to a transient failure.
 ---> Npgsql.NpgsqlException (0x80004005): Exception while reading from stream
 ---> System.IO.IOException: Unable to read data from the transport connection: Operation canceled.
 ---> System.Net.Sockets.SocketException (125): Operation canceled
   --- End of inner exception stack trace ---
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.ThrowException(SocketError error, CancellationToken cancellationToken)
   at System.Net.Sockets.Socket.AwaitableSocketAsyncEventArgs.System.Threading.Tasks.Sources.IValueTaskSource<System.Int32>.GetResult(Int16 token)
   at System.Net.Security.SslStream.EnsureFullTlsFrameAsync[TIOAdapter](CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at System.Net.Security.SslStream.ReadAsyncInternal[TIOAdapter](Memory`1 buffer, CancellationToken cancellationToken)
   at System.Runtime.CompilerServices.PoolingAsyncValueTaskMethodBuilder`1.StateMachineBox`1.System.Threading.Tasks.Sources.IValueTaskSource<TResult>.GetResult(Int16 token)
   at Npgsql.Internal.NpgsqlReadBuffer.<Ensure>g__EnsureLong|42_0(NpgsqlReadBuffer buffer, Int32 count, Boolean async, Boolean readingNotifications)
   at Npgsql.Internal.NpgsqlConnector.<ReadMessage>g__ReadMessageLong|234_0(NpgsqlConnector connector, Boolean async, DataRowLoadingMode dataRowLoadingMode, Boolean readingNotifications, Boolean isReadingPrependedMessage)
   at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
   at Npgsql.NpgsqlDataReader.NextResult(Boolean async, Boolean isConsuming, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteReader(CommandBehavior behavior, Boolean async, CancellationToken cancellationToken)
   at Npgsql.NpgsqlCommand.ExecuteDbDataReaderAsync(CommandBehavior behavior, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Storage.RelationalCommand.ExecuteReaderAsync(RelationalCommandParameterObject parameterObject, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.InitializeReaderAsync(AsyncEnumerator enumerator, CancellationToken cancellationToken)
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   --- End of inner exception stack trace ---
   at Npgsql.EntityFrameworkCore.PostgreSQL.Storage.Internal.NpgsqlExecutionStrategy.ExecuteAsync[TState,TResult](TState state, Func`4 operation, Func`4 verifySucceeded, CancellationToken cancellationToken)
   at Microsoft.EntityFrameworkCore.Query.Internal.SplitQueryingEnumerable`1.AsyncEnumerator.MoveNextAsync()

Here are the logs from our RDS proxy

2023-08-23T14:04:22.498Z [INFO] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=510502570] The client connection closed. Reason: The TCP channel was closed by either the client or the proxy.
2023-08-23T14:04:22.499Z [INFO] [dbConnection=3701033682] The database connection closed. Reason: The client connection that borrowed this database connection from the connection pool was closed in the middle of a request.
2023-08-23T14:04:33.017Z [INFO] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=1105256637] The client connection closed. Reason: The TCP channel was closed by either the client or the proxy.
2023-08-23T14:04:33.017Z [INFO] [dbConnection=954315266] The database connection closed. Reason: The client connection that borrowed this database connection from the connection pool was closed in the middle of a request.
2023-08-23T14:04:38.878Z [INFO] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3043571052] A new client connected from 1.1.1.75:47330.
2023-08-23T14:04:38.886Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3043571052] Received Startup Message: [username="postgres_user", database="postgres_database", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=true]
2023-08-23T14:04:38.888Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3043571052] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres_user" with TLS on.
2023-08-23T14:04:38.895Z [INFO] [dbConnection=2238437353] A TCP connection was established from the proxy at 1.1.1.126:2847 to the database at 1.1.1.110:5432.
2023-08-23T14:04:38.911Z [DEBUG] [dbConnection=2238437353] The new database connection successfully authenticated with TLS on.
2023-08-23T14:04:38.912Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3043571052] The client connection borrowed the database connection [dbConnection=2238437353] for the next query/transaction.
2023-08-23T14:04:38.878Z [INFO] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3303912027] A new client connected from 1.1.1.75:47354.
2023-08-23T14:04:38.887Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3303912027] Received Startup Message: [username="postgres_user", database="postgres_database", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=true]
2023-08-23T14:04:38.888Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3303912027] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres_user" with TLS on.
2023-08-23T14:04:38.890Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3303912027] The client connection borrowed the database connection [dbConnection=678548563] for the next query/transaction.
2023-08-23T14:04:38.878Z [INFO] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3829434519] A new client connected from 1.1.1.75:47340.
2023-08-23T14:04:38.885Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3829434519] Received Startup Message: [username="postgres_user", database="postgres_database", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=true]
2023-08-23T14:04:38.887Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3829434519] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres_user" with TLS on.
2023-08-23T14:04:38.888Z [DEBUG] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3829434519] The client connection borrowed the database connection [dbConnection=3708774091] for the next query/transaction.
2023-08-23T14:04:38.888Z [WARN] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3829434519] The client session was pinned to the database connection [dbConnection=3708774091] for the remainder of the session. The proxy can't reuse this connection until the session ends. Reason: A parse message was detected.
2023-08-23T14:04:38.890Z [WARN] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3303912027] The client session was pinned to the database connection [dbConnection=678548563] for the remainder of the session. The proxy can't reuse this connection until the session ends. Reason: A parse message was detected.
2023-08-23T14:04:38.912Z [WARN] [proxyEndpoint=rds-cluster-proxy-read-only] [clientConnection=3043571052] The client session was pinned to the database connection [dbConnection=2238437353] for the remainder of the session. The proxy can't reuse this connection until the session ends. Reason: A parse message was detected.
2023-08-23T14:04:45.234Z [INFO] [proxyEndpoint=default] [clientConnection=2399728112] The client connection closed. Reason: The client requested that the connection close.
2023-08-23T14:04:45.234Z [INFO] [proxyEndpoint=default] [clientConnection=1377620299] The client connection closed. Reason: The client requested that the connection close.
2023-08-23T14:04:45.234Z [DEBUG] [proxyEndpoint=default] [clientConnection=2399728112] The database connection [dbConnection=932082872] borrowed from the connection pool is being released to the connection pool.
2023-08-23T14:04:45.234Z [INFO] [dbConnection=932082872] The database connection closed. Reason: The idle connection exceeded the maximum connection duration.
2023-08-23T14:04:45.235Z [DEBUG] [proxyEndpoint=default] [clientConnection=1377620299] The database connection [dbConnection=2504791415] borrowed from the connection pool is being released to the connection pool.
2023-08-23T14:04:45.235Z [INFO] [dbConnection=2504791415] The database connection closed. Reason: The idle connection exceeded the maximum connection duration.
2023-08-23T14:04:45.235Z [INFO] [proxyEndpoint=default] [clientConnection=2781387260] The client connection closed. Reason: The client requested that the connection close.
2023-08-23T14:04:45.239Z [DEBUG] [proxyEndpoint=default] [clientConnection=2781387260] The database connection [dbConnection=1866471884] borrowed from the connection pool is being released to the connection pool.
2023-08-23T14:04:46.236Z [INFO] [proxyEndpoint=default] [clientConnection=1236912432] A new client connected from 1.1.1.84:44090.
2023-08-23T14:04:46.244Z [DEBUG] [proxyEndpoint=default] [clientConnection=1236912432] Received Startup Message: [username="postgres_user", database="postgres_database", protocolMajorVersion=3, protocolMinorVersion=0, sslEnabled=true]
2023-08-23T14:04:46.245Z [DEBUG] [proxyEndpoint=default] [clientConnection=1236912432] Proxy authentication with PostgreSQL native password authentication succeeded for user "postgres_user" with TLS on.
2023-08-23T14:04:46.245Z [DEBUG] [proxyEndpoint=default] [clientConnection=1236912432] The client connection borrowed the database connection [dbConnection=3058493730] for the next query/transaction.

What causes SocketException with Entity Framework Core, npgsql and RDS proxy?

0 Answers0