Error in GetSession() when ApplyPreAuthenticateFilters

1

Hi,

we have connected Servicestack to our oauth2 server (keycloak) and it works fine.
But when we have multiple users we get connection time out because all connection pools are full.

We can see it throws an exception in

internal static async Task<IAuthSession> GetSessionInternalAsync(this IRequest httpReq, bool reload, bool async, CancellationToken token=default)

It seems that it generates alot of connections but dont release them.

Here is the stacktrace

Note: it says AspNetMembership, it’s not membership (just and old name since we migrated from that)

2023-09-06T18:02:22.014864735Z: [INFO]        Error in GetSession() when ApplyPreAuthenticateFilters
2023-09-06T18:02:22.014977436Z: [INFO]        System.InvalidOperationException: Timeout expired.  The timeout period elapsed prior to obtaining a connection from the pool.  This may have occurred because all pooled connections were in use and max pool size was reached.
2023-09-06T18:02:22.015146836Z: [INFO]           at Microsoft.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
2023-09-06T18:02:22.015308937Z: [INFO]           at Microsoft.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
2023-09-06T18:02:22.015324337Z: [INFO]           at Microsoft.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry, SqlConnectionOverrides overrides)
2023-09-06T18:02:22.015328737Z: [INFO]           at Microsoft.Data.SqlClient.SqlConnection.Open(SqlConnectionOverrides overrides)
2023-09-06T18:02:22.015468237Z: [INFO]           at ServiceStack.OrmLite.OrmLiteConnection.Open() in /home/runner/work/ServiceStack/ServiceStack/ServiceStack.OrmLite/src/ServiceStack.OrmLite/OrmLiteConnection.cs:line 129
2023-09-06T18:02:22.015651538Z: [INFO]           at ServiceStack.OrmLite.OrmLiteConnectionFactory.OpenDbConnection() in /home/runner/work/ServiceStack/ServiceStack/ServiceStack.OrmLite/src/ServiceStack.OrmLite/OrmLiteConnectionFactory.cs:line 98
2023-09-06T18:02:22.015801538Z: [INFO]           at API.Host.MembershipProviderWrapper.GetUserProfile(String userName) in /app/API.Host/MembershipProviderWrapper.cs:line 49
2023-09-06T18:02:22.015890039Z: [INFO]           at API.Host.MembershipProviderWrapper.GetUserInfo(String userName, KeyCloakRealm realm) in /app/API.Host/MembershipProviderWrapper.cs:line 96
2023-09-06T18:02:22.015992239Z: [INFO]           at API.ServiceModel.Security.AspNetMembership.AspnetMembershipAuthSession.GetUserInfo(IAuthSession session, IMembershipProviderWrapper membershipWrapper, KeyCloakRealm realm) in /app/API.ServiceModel/Security/AspNetMembership/AspnetMembershipAuthSession.cs:line 46
2023-09-06T18:02:22.016115239Z: [INFO]           at API.ServiceModel.Security.AspNetMembership.AspnetMembershipAuthSession.TokenToSession(IAuthSession session, JsonObject token, IRequest request) in /app/API.ServiceModel/Security/AspNetMembership/AspnetMembershipAuthSession.cs:line 109
2023-09-06T18:02:22.016279940Z: [INFO]           at ServiceStack.Auth.JwtAuthProviderReader.CreateSessionFromPayload(IRequest req, JsonObject jwtPayload) in /home/runner/work/ServiceStack/ServiceStack/ServiceStack/src/ServiceStack/Auth/JwtAuthProviderReader.cs:line 850
2023-09-06T18:02:22.016415240Z: [INFO]           at ServiceStack.Auth.JwtAuthProviderReader.AuthenticateBearerToken(IRequest req, IResponse res, String bearerToken) in /home/runner/work/ServiceStack/ServiceStack/ServiceStack/src/ServiceStack/Auth/JwtAuthProviderReader.cs:line 595
2023-09-06T18:02:22.016586441Z: [INFO]           at ServiceStack.Auth.JwtAuthProviderReader.PreAuthenticateAsync(IRequest req, IResponse res) in /home/runner/work/ServiceStack/ServiceStack/ServiceStack/src/ServiceStack/Auth/JwtAuthProviderReader.cs:line 541
2023-09-06T18:02:22.016739841Z: [INFO]           at ServiceStack.ServiceStackHost.ApplyPreAuthenticateFiltersAsync(IRequest httpReq, IResponse httpRes) in /home/runner/work/ServiceStack/ServiceStack/ServiceStack/src/ServiceStack/ServiceStackHost.Runtime.cs:line 97
2023-09-06T18:02:22.016891342Z: [INFO]           at ServiceStack.ServiceExtensions.GetSessionInternalAsync(IRequest httpReq, Boolean reload, Boolean async, CancellationToken token) in /home/runner/work/ServiceStack/ServiceStack/ServiceStack/src/ServiceStack/

We also retrieved this error message

ResponseStatus	Object { ErrorCode: "InvalidOperationException", Message: "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool. This may have occurred because all pooled connections were in use and max pool size was reached.", Errors: [] }
2

Looks like your AspNetMembership is opening the database connection, where’s the issue in ServiceStack?

3

You might be right here. I was trying to find the cause for it but i will check how the connection could be opened and not closed.

4

I cant see the cause of this. We have the same setup of code except we have upgraded to .net 7 and latest servicestack nuget packages and now it seems ormlite is not closing connections.

Any clue?

5

Can you provide code examples of how the OrmLite connections are being handled by any custom code? Eg, what other DB operations are you performing in the same request (if any), and can you show related code there?

Not saying you are using Razor related to this request, but for example, I know it is easy to incorrectly dispose of DB connections used in a Razor page which will cause similar issues.

In the end, we would need more info and ideally a way to reproduce the problem you are seeing, so the more info the better.

6

Look at your StackTrace, your MembershipProviderWrapper.GetUserProfile(String userName) is making the database call.

7

Hi, we can’t see we doing anything wrong here.

In apphost we have

container.AddSingleton<IDbConnectionFactory>(c => new OrmLiteConnectionFactory(Configuration.GetConnectionString("db"), SqlServerDialect.Provider));

Then we have our class

public class MembershipProviderWrapper : RepositoryBase, IMembershipProviderWrapper

which has this

public UserProfile GetUserProfile(string userName)
        {
            using (var db = DbFactory.Open())
            {
                return db.Select<UserProfile>(u => u.Email == userName).FirstOrDefault();
            }
        }

But it seems that it doesnt release the connections?

8

That’s where the StackTrace says the Exception occurs where it can’t open any new connections, which I’m assuming is the result of your App having a DB Connection Leak elsewhere, i.e. where it’s not disposed after usage. Check all your usages to make sure your disposing the db connection after it’s opened.

9

But if i undestand it correctly it’s enough to have

using (var db = DbFactory.Open())

Then it will be disposed after?

10

Right this will dispose the connection after usage.

Which can be reduced in the latest C# version to use a using declaration:

using var db = DbFactory.Open();

Your connection leak is happening elsewhere.

11

I’ve checked and we are only connected to the database with using statement around all DbFactory.Open()
So It must be something else

12

Is there any way i can add logging every time a connection is opened and closed.
So i can see what causing this?

13

Created this… will have a try


public class LoggingDbConnectionFactory : OrmLiteConnectionFactory
{
    public LoggingDbConnectionFactory(string connectionString, IOrmLiteDialectProvider dialectProvider)
        : base(connectionString, dialectProvider)
    {
            OnDispose = dbConn =>        {
            LogConnectionEvent(dbConn, "Closed");
        };
    }

    public override IDbConnection OpenDbConnection(string namedConnection)
    {
        var dbConn = base.OpenDbConnection(namedConnection);
        LogConnectionEvent(dbConn, "Opened");
        return dbConn;
    }
    
    

    private void LogConnectionEvent(IDbConnection dbConn, string eventType)
    {
        var connectionId = dbConn.GetConnectionId();
        var dbName = dbConn.Database;

        // You can replace this with your preferred logging mechanism
        Console.WriteLine($"Connection {connectionId} to database '{dbName}' {eventType}");
    }

}
14

You could implement your own IDbConnectionFactory decorator that logs before returning the OrmLiteConnectionFactory.OpenDbConnection() and CreateDbConnection() methods.

ok yeah that’s the approach I’d use.

15

Ok, all connectionids are guid.empty.
Can i set them to i can distinguish them?

16

Weird that it’s empty since it’s set when DB Connections are open, but you can set it with:

if (dbConn is OrmLiteConnection ormLiteConn)
  ormLiteConn.ConnectionId = Guid.NewGuid();