Inedo Community Forums Forums
    • Recent
    • Tags
    • Popular
    • Login

    Welcome to the Inedo Forums! Check out the Forums Guide for help getting started.

    If you are experiencing any issues with the forum software, please visit the Contact Form on our website and let us know!

    Timeout errors after upgrade to 5.3.7

    Scheduled Pinned Locked Moved Support
    28 Posts 7 Posters 141 Views 3 Watching
    Loading More Posts
    • Oldest to Newest
    • Newest to Oldest
    • Most Votes
    Reply
    • Reply as topic
    Log in to reply
    This topic has been deleted. Only users with topic management privileges can see it.
    • T Offline
      thomas.ibel_2956
      last edited by atripp

      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()
      1 Reply Last reply Reply Quote 1
      • rhessingerR Offline
        rhessinger inedo-engineer
        last edited by

        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

        Products Engineer, Inedo

        1 Reply Last reply Reply Quote 0
        • T Offline
          thomas.ibel_2956
          last edited by

          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

          1 Reply Last reply Reply Quote 0
          • rhessingerR Offline
            rhessinger inedo-engineer
            last edited by

            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

            Products Engineer, Inedo

            B 1 Reply Last reply Reply Quote 0
            • B Offline
              blake.peno_2353 @rhessinger
              last edited by 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.

              1 Reply Last reply Reply Quote 0
              • rhessingerR Offline
                rhessinger inedo-engineer
                last edited by

                Hi @thomas-ibel_2956 & @blake-peno_2353,

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

                Thanks,
                Rich

                Products Engineer, Inedo

                T B 2 Replies Last reply Reply Quote 0
                • T Offline
                  thomas.ibel_2956 @rhessinger
                  last edited by

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

                  Regards,
                  Thomas

                  1 Reply Last reply Reply Quote 0
                  • B Offline
                    blake.peno_2353 @rhessinger
                    last edited by

                    @rhessinger Same here. IIS.

                    1 Reply Last reply Reply Quote 0
                    • G Offline
                      gravufo
                      last edited by

                      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.

                      1 Reply Last reply Reply Quote 1
                      • atrippA Offline
                        atripp inedo-engineer
                        last edited by

                        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!

                        1 Reply Last reply Reply Quote 1
                        • P Offline
                          pluskal_4199
                          last edited by

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

                          1 Reply Last reply Reply Quote 0
                          • rhessingerR Offline
                            rhessinger inedo-engineer
                            last edited by

                            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

                            Products Engineer, Inedo

                            P 1 Reply Last reply Reply Quote 0
                            • P Offline
                              pluskal_4199 @rhessinger
                              last edited by

                              @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).

                              1 Reply Last reply Reply Quote 0
                              • rhessingerR Offline
                                rhessinger inedo-engineer
                                last edited by

                                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

                                Products Engineer, Inedo

                                1 Reply Last reply Reply Quote 0
                                • P Offline
                                  pluskal_4199
                                  last edited by

                                  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
                                  1 Reply Last reply Reply Quote 0
                                  • rhessingerR Offline
                                    rhessinger inedo-engineer
                                    last edited by

                                    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

                                    Products Engineer, Inedo

                                    P 1 Reply Last reply Reply Quote 0
                                    • rhessingerR Offline
                                      rhessinger inedo-engineer
                                      last edited by

                                      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

                                      Products Engineer, Inedo

                                      1 Reply Last reply Reply Quote 0
                                      • T Offline
                                        thomas.ibel_2956
                                        last edited by

                                        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

                                        rhessingerR 2 Replies Last reply Reply Quote 0
                                        • rhessingerR Offline
                                          rhessinger inedo-engineer @thomas.ibel_2956
                                          last edited by

                                          Hi @thomas-ibel_2956,

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

                                          Thanks,
                                          Rich

                                          Products Engineer, Inedo

                                          1 Reply Last reply Reply Quote 0
                                          • P Offline
                                            pluskal_4199 @rhessinger
                                            last edited by

                                            @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?

                                            1 Reply Last reply Reply Quote 0

                                            Hello! It looks like you're interested in this conversation, but you don't have an account yet.

                                            Getting fed up of having to scroll through the same posts each visit? When you register for an account, you'll always come back to exactly where you were before, and choose to be notified of new replies (either via email, or push notification). You'll also be able to save bookmarks and upvote posts to show your appreciation to other community members.

                                            With your input, this post could be even better 💗

                                            Register Login
                                            • 1
                                            • 2
                                            • 1 / 2
                                            • First post
                                              Last post
                                            Inedo Website Home • Support Home • Code of Conduct • Forums Guide • Documentation