Timeout errors after upgrade to 5.3.7

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