Timeout errors after upgrade to 5.3.7

rhessinger

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