Timeout errors after upgrade to 5.3.7

[thomas.ibel_2956]

Related topic: https://forums.inedo.com/topic/3004

---

Hi,

I'm seeing many timeout errors and completely inaccessible ProGet instance after upgrading from 5.2.31 to 5.3.7.

Environment: Windows 2016 with local SQL Server Express 2016 SP2

Event Log

Event code: 3005 
Event message: An unhandled exception has occurred. 
Event time: 7/20/2020 2:38:47 PM 
Event time (UTC): 7/20/2020 12:38:47 PM 
Event ID: 51e4b181688e4d3284390e347e08aeea 
Event sequence: 528 
Event occurrence: 527 
Event detail code: 0 
 
Application information: 
    Application domain: /LM/W3SVC/2/ROOT-1-132397205317290947 
    Trust level: Full 
    Application Virtual Path: / 
    Application Path: C:\Program Files\ProGet\Web\ 
    Machine name: MYPROGET 
 
Process information: 
    Process ID: 3040 
    Process name: w3wp.exe 
    Account name: NT AUTHORITY\NETWORK SERVICE 
 
Exception information: 
    Exception type: InvalidOperationException 
    Exception 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.
   at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.Open()
   at Inedo.Data.SqlServerDatabaseContext.CreateConnection()
   at Inedo.LazyAsync`1.GetValue()
   at Inedo.LazyAsync`1.get_Value()
   at Inedo.Data.DatabaseContext.ExecuteInternal(String storedProcName, GenericDbParameter[] parameters)
   at Inedo.Data.SqlServerDatabaseContext.ExecuteInternal(String storedProcName, GenericDbParameter[] parameters)
   at Inedo.Data.StrongDataReader.<Read>d__11`1.MoveNext()
   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
   at Inedo.ProGet.Data.DB.Context.Feeds_GetFeed(Nullable`1 Feed_Id, String Feed_Name)
   at Inedo.ProGet.Feeds.Feed.GetFeed(String feedName, Context externalDbContext)
   at Inedo.ProGet.WebApplication.FeedEndpoints.FeedEndpointHandler.GetHttpHandler(GetHandlerParams args)
   at Inedo.Web.Handlers.DynamicHttpHandling.GetHandler(HttpContext context, String requestType, String url, String pathTranslated)
   at Inedo.Web.InedoHttpModule.MapHandlerAndBeginRequestAsync(HttpApplication app)
   at Inedo.Web.InedoHttpModule.ProcessBegin(Object sender, EventArgs e, AsyncCallback cb, Object extraData)
   at System.Web.HttpApplication.AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

 
 
Request information: 
    Request URL: https://MyProGet:443/nuget/MyFeed/FindPackagesById()?id='SomePackage'&semVerLevel=2.0.0 
    Request path: /nuget/MyFeed/FindPackagesById() 
    User host address: 10.0.0.4 
    User:  
    Is authenticated: False 
    Authentication Type:  
    Thread account name: NT AUTHORITY\NETWORK SERVICE 
 
Thread information: 
    Thread ID: 284 
    Thread account name: NT AUTHORITY\NETWORK SERVICE 
    Is impersonating: False 
    Stack trace:    at System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource`1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection)
   at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource`1 retry, DbConnectionOptions userOptions)
   at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource`1 retry)
   at System.Data.SqlClient.SqlConnection.Open()
   at Inedo.Data.SqlServerDatabaseContext.CreateConnection()
   at Inedo.LazyAsync`1.GetValue()
   at Inedo.LazyAsync`1.get_Value()
   at Inedo.Data.DatabaseContext.ExecuteInternal(String storedProcName, GenericDbParameter[] parameters)
   at Inedo.Data.SqlServerDatabaseContext.ExecuteInternal(String storedProcName, GenericDbParameter[] parameters)
   at Inedo.Data.StrongDataReader.<Read>d__11`1.MoveNext()
   at System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source)
   at Inedo.ProGet.Data.DB.Context.Feeds_GetFeed(Nullable`1 Feed_Id, String Feed_Name)
   at Inedo.ProGet.Feeds.Feed.GetFeed(String feedName, Context externalDbContext)
   at Inedo.ProGet.WebApplication.FeedEndpoints.FeedEndpointHandler.GetHttpHandler(GetHandlerParams args)
   at Inedo.Web.Handlers.DynamicHttpHandling.GetHandler(HttpContext context, String requestType, String url, String pathTranslated)
   at Inedo.Web.InedoHttpModule.MapHandlerAndBeginRequestAsync(HttpApplication app)
   at Inedo.Web.InedoHttpModule.ProcessBegin(Object sender, EventArgs e, AsyncCallback cb, Object extraData)
   at System.Web.HttpApplication.AsyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
   at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
 
 
Custom event details: 

Administration > Diagnostic Center

7/20/2020 3:18:23 PM
Level:
Error
Category:
Web
Message:
An error occurred processing a GET request to https://MyProGet/nuget/MyFeed/FindPackagesById()?id='SomePackage'&semVerLevel=2.0.0: 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.
Details:
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.
at System.Data.Common.ADP.ExceptionWithStackTrace(Exception e)
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.Data.SqlServerDatabaseContext.<CreateConnectionAsync>d__4.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.Data.DatabaseContext.<ExecuteInternalAsync>d__37.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at Inedo.Data.SqlServerDatabaseContext.<ExecuteInternalAsync>d__7.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.Data.DatabaseContext.<ExecuteTableAsync>d__36`1.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.ProGet.Feeds.NuGet.V2.LocalPackageSource.<FindPackagesByIdAsync>d__15.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.ProGet.Feeds.NuGet.NuGetFeed.<FindPackagesByIdAsync>d__50.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.ODataHandler.<ProcessVirtualRequestAsync>d__10.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.ProGet.WebApplication.FeedEndpoints.NuGet.ODataHandler.<ProcessRequestAsync>d__9.MoveNext()
--- End of stack trace from previous location where exception was thrown ---
at System.Runtime.ExceptionServices.ExceptionDispatchInfo.Throw()
at System.Runtime.CompilerServices.TaskAwaiter.HandleNonSuccessAndDebuggerNotification(Task task)
at Inedo.ProGet.WebApplication.FeedEndpoints.FeedEndpointHandler.FeedRequestHandler.<ProcessRequestAsync>d__11.MoveNext()

[rhessinger]

Hi @thomas-ibel_2956,

We are currently investigating this issue further. As a workaround, could you try increasing the Max Pool Size to 400 in your SQL connection string? Please let us know if that changes anything for you.

Thanks,
Rich

[thomas.ibel_2956]

Thanks @rhessinger ,

I have set the Max Pool Size as you suggested.
ProGet is running now for two hours. Still seeing the same exceptions in Diagnostics Center.
It seems that they occur periodical.

Regards,
Thomas

[rhessinger]

Hi @thomas-ibel_2956,

Thanks for the updated information. I know this is not an ideal solution, but can you up the Max Pool Size to 1,000? We are still looking into what is preventing the connections from being released back to the connection pool, but this may work as a temporary workaround while we are in that process of resolving this.

Thanks,
Rich

[blake.peno_2353]

Seeing the same issue in my internal environments here after upgrading to 5.3.7 from 5.2.26. Figured it was just an issue with hopping so many versions, glad I'm not the only one. I "solved" this issue by reverting back to a vm snapshot to get back to 5.2.26.

Does anyone know if this issue is specific to 5.3.7 or when in the 5.3.x range it started? I'd like to at least get updated to 5.3 as soon as I can for a different fix.

[rhessinger]

Hi @thomas-ibel_2956 & @blake-peno_2353,

Do you have ProGet using IIS or are you using the integrated web server?

Thanks,
Rich

[thomas.ibel_2956]

@rhessinger
I have ProGet using IIS (Version 10).

Regards,
Thomas

[blake.peno_2353]

@rhessinger Same here. IIS.

[gravufo]

This is the exact same issue I reported a while back: https://forums.inedo.com/topic/3004/proget-timeout-at-a-specific-time

It turns out the issue is still present, but doesn't seem to happen at exactly the same time now, since we moved the build schedule. I'm guessing ProGet has a bug that does not release connections.

[atripp]

Hi all, just an update! We will be shipping a potential fix in PG-1783, which adds a new checkbox in advanced settings (unchecked by default):

Close Database Connections Early
EXPERIMENTAL (for debugging/testing only) - As of ProGet 5.3, database connections are left open during the lifecycle of a NuGet API request as a means to reduce overhead; however, this may be causing ProGet to run out of available connections to SQL Server. Set this value true to open/close database connections as needed on NuGet feeds.

We'll update when this is shipped --- but if we can get some folks to verify that this works better (we can't repro, at all ), then we will likely make it the default. Hopefully this will do it. Seems better than raising connection pool limits

If so, then the savings in connection open/close overhead don't seem to make it particularly worthwhile. This "keep open" technique made a ton of differences elsewhere in our software, but since a NuGet API requests may yield a ton of other network requests (via connectors) and block, the pool may be getting drained too quickly...

just a theory, as I mentioned. Anyway hope this helps, stay tuned!!

Thanks!

[pluskal_4199]

I can confirm that on 5.3.8-ci.19 and Close Database Connections Early active I am not getting the SQL pool exhaustion.

[rhessinger]

Hi @pluskal_4199 ,

That is great to hear! How often were you seeing the error prior? Also what OS Version, SQL Server Edition, and SQL Server Version are you running?

Thanks,
Rich

[pluskal_4199]

@rhessinger Hi, I have to take it back. I have increased parallelism in CI/CD pipeline and hit this bug once again.

I deploy in Docker on CentOS 7, SQL Express (tried Developer as well) in a container (tried both the latest 2017 and 2019).

[rhessinger]

Hi @pluskal_4199 ,

Are these builds running at the same time as the Feed Cleanup job for your NuGet feed by chance? Also, are you seeng the same error 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.?

Thanks,
Rich

[pluskal_4199]

I have not configured a Feed Cleanup job so if it is not automatically set, I would say that it is not running at the same time.

The exception is still the same 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.

And now, there are some new exceptions for DropPathMonitorRunner and FeedReplicationRunner Unhandled exception: Snix_Read (provider: SNI_PN7, error: 2 - SNI_ERROR_2) Snix_Read (provider: SNI_PN7, error: 2 - SNI_ERROR_2)

System.Data.SqlClient.SqlException (0x80131904): Snix_Read (provider: SNI_PN7, error: 2 - SNI_ERROR_2)
Snix_Read (provider: SNI_PN7, error: 2 - SNI_ERROR_2)
at System.Data.SqlClient.SqlConnection.OnError (System.Data.SqlClient.SqlException exception, System.Boolean breakConnection, System.Action`1[T] wrapCloseInAction) [0x0004e] in <0864334e7e474248b37afca9b637daa9>:0
at (wrapper remoting-invoke-with-check) System.Data.SqlClient.SqlConnection.OnError(System.Data.SqlClient.SqlException,bool,System.Action`1<System.Action>)
at System.Data.SqlClient.SqlInternalConnection.OnError (System.Data.SqlClient.SqlException exception, System.Boolean breakConnection, System.Action`1[T] wrapCloseInAction) [0x00013] in <0864334e7e474248b37afca9b637daa9>:0
at System.Data.SqlClient.TdsParser.ThrowExceptionAndWarning (System.Data.SqlClient.TdsParserStateObject stateObj, System.Boolean callerHasConnectionLock, System.Boolean asyncClose) [0x00125] in <0864334e7e474248b37afca9b637daa9>:0
at System.Data.SqlClient.TdsParserStateObject.ThrowExceptionAndWarning (System.Boolean callerHasConnectionLock, System.Boolean asyncClose) [0x00000] in <0864334e7e474248b37afca9b637daa9>:0
at System.Data.SqlClient.TdsParserStateObject.ReadAsyncCallbackCaptureException (System.Threading.Tasks.TaskCompletionSource`1[TResult] source) [0x0001e] in <0864334e7e474248b37afca9b637daa9>:0
--- End of stack trace from previous location where exception was thrown ---

at Inedo.Data.SqlServerDatabaseContext.CreateConnectionAsync () [0x0018d] in <ee7a5f9ece0745948bcfc1883d4013bb>:0
at Inedo.Data.DatabaseContext.ExecuteInternalAsync (System.String storedProcName, Inedo.Data.GenericDbParameter[] parameters) [0x00180] in <ee7a5f9ece0745948bcfc1883d4013bb>:0
at Inedo.Data.DatabaseContext.ExecuteTableAsync[TRow] (System.String storedProcName, Inedo.Data.GenericDbParameter[] parameters) [0x00082] in <ee7a5f9ece0745948bcfc1883d4013bb>:0
at Inedo.ProGet.Service.DropPathMonitorRunner.RunAsync (System.Threading.CancellationToken cancellationToken, System.Object arguments) [0x00087] in <3d276f35cd3f4a209bcd73208ec133d9>:0
at Inedo.TaskRunner.RunInternalAsync (System.Object args) [0x001ef] in <ee7a5f9ece0745948bcfc1883d4013bb>:0
ClientConnectionId:503f7eab-92cb-4d5a-8dda-505f9830af2a

[rhessinger]

Hi @pluskal_4199,

Thanks for the information.

The FeedCleanup job is automatically scheduled and you can see the date and time by navigating to Administration -> Scheduled Jobs. Would you be able to tell me if the time that was automatically configured matches when you are seeing the timeout?

Our Docker image currently is running ProGet using mono which comes with its own subset of issues. I'm seeing the SNI_Error is a pretty common error with mono and we have seen mono has more trouble releasing connections than when running within the .NET Framework. The most annoying part of mono, is they don't always give us the most accurate and descriptive error messages. This could just be a similar exception to the max connection pool but based on DB transactions. We are currently in the process of migrating to .NET 5 and we will hopefully have an updated Docker image over the next couple of months. If you are interested, please keep an eye out for more information to come.

I would like to see some of these results on Windows-based installations also to help guide our solution.

Thanks,
Rich

[rhessinger]

Hi All,

We have just released ProGet 5.3.8. Would you please upgrade and test with the Close Database Connections Early setting enabled?

Thanks,
Rich

[thomas.ibel_2956]

Updated to 5.3.8 and activated Close Database Connections Early.
Running for 3 hours now without any timeout errors

Thanks a million @rhessinger and team

Regards,
Thomas

[rhessinger]

Hi @thomas-ibel_2956,

Glad to hear it! Please let me know if this continues or if you start having issues again.

Thanks,
Rich

[pluskal_4199]

@rhessinger Thanks for the detailed explanation. I'll keep an eye on the migration, and asap you release some Docker images I'll be an early adopter :)

Btw. I have moved to 5.3.8 release and it seems that it has fixed it. Was there any other change between 5.3.8 ci.20 and 5.3.8?

[markus4830]

I migrated from version 5.2.31 to 5.3.8 directly. And the issue described here was also there. After changing the settings like rhessinger mentioned everything works so far. This was annoying @inedo... Hopefully there will be a patch soon!?

[rhessinger]

Hi @thomas-ibel_2956,

I am not aware of any other changes that would have affected that specifically. There were a couple more changes to other areas of the system. It is always possible that there was an update to a Debian package that mono depends on that helped to improve connection handling in Docker. But I cannot confirm that was the case. The only thing I can confirm is that the top two layers in the image have a slight difference to them when comparing 5.3.8 and 5.3.8-ci.20 .

Thanks,
Rich

[rhessinger]

Hi @markus4830,

I'm definitely sorry about this. The change was made to help to aide in improvements to other areas of the system related to NuGet. Unfortunately, it looks like it affected the NuGet API. Expect a more permanent solution in the near future.

Thanks,
Rich

[gravufo]

I upgraded to 5.3.8 thinking the fix would work, but it seems the issue is still present, even after activating the new option and removing the Max Pool Size option.
Any idea?

[rhessinger]

Hi @gravufo,

After you enabled the Close Database Connections Early have you tried restarting your web server? You shouldn't have to restart it, but I have seen some issues when there were too many connections open prior to enabling the setting. Coudl you run the following SQL next time you have the issue?

SELECT DB_NAME(dbid) as DBName, COUNT(dbid) as NumberOfConnections, loginame as LoginName
FROM sys.sysprocesses
WHERE dbid > 0 AND DB_NAME(dbid) = 'ProGet'
GROUP BY dbid, loginame 

Thanks,
Rich

[gravufo]

@rhessinger I did not restart after enabling the option, I just did it this morning and will monitor. I'll get back to you with the query result if it happens again. Thanks a lot for the continued support!

[gravufo]

The restart seems to have done the trick. I don't see any NuGet errors since.

Thanks again!

[rhessinger]

Hi @gravufo,

Thanks for following up. Glad to hear it is working!

Thanks,
Rich