Copied to clipboard

Flag this post as spam?

This post will be reported to the moderators as potential spam to be looked at


  • OleP 67 posts 276 karma points
    Dec 08, 2021 @ 09:46
    OleP
    1

    Site suddenly starts exceed pool limits and fail to boot

    Hi there

    We have a site that's been running fine for months, but suddenly on the 19th of october and ever since, the site has been down multiple times a day.

    The pattern is the same every time when looking in the log:

    1. Multiple entries mentioning 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.
      1. System fails to enter log: System.TimeoutException: Failed to enter the lock within timeout.
      2. Boot failed: Umbraco.Core.Exceptions.BootFailedException: Boot failed. ---> System.TimeoutException: Cannot acquire MainDom

    After a retry the site will get back up by itself, but is down in the meantime. There's nothing prior to this in the log explaining it.

    The site is running on a VM in Azure, with a seperate Azure VM as SQL server. It is a high demand site, but the cpu and memory usage on the server is at 20% at most.

    The Umbraco version is at 8.6.8.

    Any quailified guesses why this is happening, and why it started happening all of a sudden?

    Full logs:

    Timeout (there are many variations of this with different strack trace):

    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.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 NPoco.Database.OpenSharedConnectionImp(Boolean isInternal)
       at NPoco.Database.BeginTransaction(IsolationLevel isolationLevel)
       at Umbraco.Core.Scoping.Scope.get_Database() in D:\a\1\s\src\Umbraco.Core\Scoping\Scope.cs:line 242
       at Umbraco.Core.Persistence.Repositories.Implement.RedirectUrlRepository.GetMostRecentUrl(String url) in D:\a\1\s\src\Umbraco.Core\Persistence\Repositories\Implement\RedirectUrlRepository.cs:line 162
       at Umbraco.Core.Services.Implement.RedirectUrlService.GetMostRecentRedirectUrl(String url) in D:\a\1\s\src\Umbraco.Core\Services\Implement\RedirectUrlService.cs:line 76
       at Umbraco.Web.Routing.ContentFinderByRedirectUrl.TryFindContent(PublishedRequest frequest) in D:\a\1\s\src\Umbraco.Web\Routing\ContentFinderByRedirectUrl.cs:line 39
       at System.Linq.Enumerable.Any[TSource](IEnumerable`1 source, Func`2 predicate)
       at Umbraco.Web.Routing.PublishedRouter.FindPublishedContent(PublishedRequest request) in D:\a\1\s\src\Umbraco.Web\Routing\PublishedRouter.cs:line 424
       at Umbraco.Web.Routing.PublishedRouter.FindPublishedContentAndTemplate(PublishedRequest request) in D:\a\1\s\src\Umbraco.Web\Routing\PublishedRouter.cs:line 386
       at Umbraco.Web.Routing.PublishedRouter.PrepareRequest(PublishedRequest request) in D:\a\1\s\src\Umbraco.Web\Routing\PublishedRouter.cs:line 135
       at Umbraco.Web.UmbracoInjectedModule.ProcessRequest(HttpContextBase httpContext) in D:\a\1\s\src\Umbraco.Web\UmbracoInjectedModule.cs:line 138
       at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
       at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)
       at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)`
    

    Failed to enter lock:

    System.TimeoutException: Failed to enter the lock within timeout.
       at Umbraco.Core.SystemLock.Lock(Int32 millisecondsTimeout) in D:\a\1\s\src\Umbraco.Core\SystemLock.cs:line 85
       at Umbraco.Core.Runtime.MainDomSemaphoreLock.AcquireLockAsync(Int32 millisecondsTimeout) in D:\a\1\s\src\Umbraco.Core\Runtime\MainDomSemaphoreLock.cs:line 41
    

    Boot failed:

    Umbraco.Core.Exceptions.BootFailedException: Boot failed. ---> System.TimeoutException: Cannot acquire MainDom
       at Umbraco.Core.Runtime.MainDom.Acquire() in D:\a\1\s\src\Umbraco.Core\Runtime\MainDom.cs:line 172
       at System.Threading.LazyInitializer.EnsureInitializedCore[T](T& target, Boolean& initialized, Object& syncLock, Func`1 valueFactory)
       at Umbraco.Core.Runtime.MainDom.get_IsMainDom() in D:\a\1\s\src\Umbraco.Core\Runtime\MainDom.cs:line 204
       at Umbraco.Core.Runtime.CoreRuntime.AcquireMainDom(IMainDom mainDom) in D:\a\1\s\src\Umbraco.Core\Runtime\CoreRuntime.cs:line 263
       at Umbraco.Core.Runtime.CoreRuntime.Boot(IRegister register, DisposableTimer timer) in D:\a\1\s\src\Umbraco.Core\Runtime\CoreRuntime.cs:line 169
       --- End of inner exception stack trace ---
    
  • Marc Goodson 2128 posts 14220 karma points MVP 8x c-trib
    Dec 11, 2021 @ 14:14
    Marc Goodson
    3

    Hi OleP

    This all seems related to the number of connections available in your SQL Server instance, when Umbraco starts up it uses a SQL query to obtain a 'MainLock', if SQL Server has no connections available, Umbraco cannot start.

    When you try again presumably one is free and it can start.

    Similarly the other error is when a 404 is about to happen, Umbraco's content finder for redirects will lookup a SQL database table to see if a redirect exists for the Url before returning a 404.

    You can run the following SQL on the SQL Server instance, when the issue occurs to see how many connections are in place, and see if over time this increases and never decreases:

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

    Essentially if this number keeps increasing, some code somwhere in the solution, or another solution that is using the database, is grabbing a connection to the db and not releasing it properly, meaning another connection in the pool cannot immediately be made until the blocking connection timesout...

    So do you have any custom code that accesses the database?

    In theory it could be a bug in Umbraco, but you'd expect there to be alot more issues like this reported if that were the case?

    Anyway, hope that helps investigate more...

    regards

    marc

  • OleP 67 posts 276 karma points
    Dec 14, 2021 @ 08:28
    OleP
    0

    Hi Marc

    Thanks for the reply.

    From what we've seen, the number of connections is never above 10. Afaik the maximum available connections is 32,767.

    We do have custom code on the solution, and all data is stored in a separate table than the Umbraco db. All of our custom code is logged, and nothing shows up in the log when the issue happens.

    Since the original post, we've start seeing another error that may be related:

    Umbraco.Core.Exceptions.BootFailedException: Boot failed: Umbraco cannot run. See Umbraco's log file for more details.\n\n-> Umbraco.Core.Exceptions.BootFailedException: Boot failed.\n\n-> System.IO.IOException: The process cannot access the file 'C:\\windows\\TEMP\\UmbracoData\\aad2ba757d1fd0e1d26ac57d2c96ad1d\\NuCache\\NuCache.Content.db' because it is being used by another process.\n   at System.IO.__Error.WinIOError(Int32 errorCode, String maybeFullPath)\r\n   at System.IO.FileStream.Init(String path, FileMode mode, FileAccess access, Int32 rights, Boolean useRights, FileShare share, Int32 bufferSize, FileOptions options, SECURITY_ATTRIBUTES secAttrs, String msgPath, Boolean bFromProxy, Boolean useLongPath, Boolean checkHost)\r\n   at System.IO.FileStream..ctor(String path, FileMode mode, FileAccess access, FileShare share, Int32 bufferSize, FileOptions options)\r\n   at CSharpTest.Net.IO.TransactedCompoundFile..ctor(Options options)\r\n   at CSharpTest.Net.Storage.BTreeFileStoreV2..ctor(Options options)\r\n   at CSharpTest.Net.Collections.BPlusTree`2.OptionsV2.CreateStorage()\r\n   at CSharpTest.Net.Collections.BPlusTree`2.NodeCacheBase..ctor(BPlusTreeOptions`2 options)\r\n   at CSharpTest.Net.Collections.BPlusTree`2.NodeCacheNone..ctor(BPlusTreeOptions`2 options)\r\n   at CSharpTest.Net.Collections.BPlusTree`2..ctor(BPlusTreeOptions`2 ioptions)\r\n   at Umbraco.Web.PublishedCache.NuCache.DataSource.BTree.GetTree(String filepath, Boolean exists) in D:\\a\\1\\s\\src\\Umbraco.Web\\PublishedCache\\NuCache\\DataSource\\BTree.cs:line 32\r\n   at Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService.MainDomRegister() in D:\\a\\1\\s\\src\\Umbraco.Web\\PublishedCache\\NuCache\\PublishedSnapshotService.cs:line 173\r\n   at Umbraco.Core.Runtime.MainDom.Register(Action install, Action release, Int32 weight) in D:\\a\\1\\s\\src\\Umbraco.Core\\Runtime\\MainDom.cs:line 90\r\n   at Umbraco.Web.PublishedCache.NuCache.PublishedSnapshotService..ctor(PublishedSnapshotServiceOptions options, IMainDom mainDom, IRuntimeState runtime, ServiceContext serviceContext, IPublishedContentTypeFactory publishedContentTypeFactory, IdkMap idkMap, IPublishedSnapshotAccessor publishedSnapshotAccessor, IVariationContextAccessor variationContextAccessor, IProfilingLogger logger, IScopeProvider scopeProvider, IDocumentRepository documentRepository, IMediaRepository mediaRepository, IMemberRepository memberRepository, IDefaultCultureAccessor defaultCultureAccessor, IDataSource dataSource, IGlobalSettings globalSettings, IEntityXmlSerializer entitySerializer, IPublishedModelFactory publishedModelFactory, UrlSegmentProviderCollection urlSegmentProviders) in D:\\a\\1\\s\\src\\Umbraco.Web\\PublishedCache\\NuCache\\PublishedSnapshotService.cs:line 133\r\n   at DynamicMethod(Object[] )\r\n   at LightInject.PerContainerLifetime.GetInstance(Func`1 createInstance, Scope scope) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 6169\r\n   at LightInject.ServiceContainer.EmitLifetime(ServiceRegistration serviceRegistration, Action`1 emitMethod, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4656\r\n   at LightInject.ServiceContainer.<>c__DisplayClass153_0.<CreateEmitMethodWrapper>b__0(IEmitter ms) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3856\r\n   at LightInject.ServiceContainer.EmitConstructorDependency(IEmitter emitter, Dependency dependency) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4158\r\n   at LightInject.ServiceContainer.EmitConstructorDependencies(ConstructionInfo constructionInfo, IEmitter emitter, Action`1 decoratorTargetEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4120\r\n   at LightInject.ServiceContainer.EmitNewInstanceUsingImplementingType(IEmitter emitter, ConstructionInfo constructionInfo, Action`1 decoratorTargetEmitMethod) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4081\r\n   at LightInject.ServiceContainer.EmitNewInstance(ServiceRegistration serviceRegistration, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4038\r\n   at LightInject.ServiceContainer.CreateDynamicMethodDelegate(Action`1 serviceEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3777\r\n   at LightInject.ServiceContainer.<>c__DisplayClass198_0.<EmitLifetime>b__1() in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4657\r\n   at LightInject.PerContainerLifetime.GetInstance(Func`1 createInstance, Scope scope) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 6169\r\n   at LightInject.ServiceContainer.EmitLifetime(ServiceRegistration serviceRegistration, Action`1 emitMethod, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4656\r\n   at LightInject.ServiceContainer.<>c__DisplayClass153_0.<CreateEmitMethodWrapper>b__0(IEmitter ms) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3856\r\n   at LightInject.ServiceContainer.EmitConstructorDependency(IEmitter emitter, Dependency dependency) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4158\r\n   at LightInject.ServiceContainer.EmitConstructorDependencies(ConstructionInfo constructionInfo, IEmitter emitter, Action`1 decoratorTargetEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4120\r\n   at LightInject.ServiceContainer.EmitNewInstanceUsingImplementingType(IEmitter emitter, ConstructionInfo constructionInfo, Action`1 decoratorTargetEmitMethod) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4081\r\n   at LightInject.ServiceContainer.EmitNewInstance(ServiceRegistration serviceRegistration, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4038\r\n   at LightInject.ServiceContainer.CreateDynamicMethodDelegate(Action`1 serviceEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3777\r\n   at LightInject.ServiceContainer.<>c__DisplayClass198_0.<EmitLifetime>b__1() in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4657\r\n   at LightInject.PerContainerLifetime.GetInstance(Func`1 createInstance, Scope scope) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 6169\r\n   at LightInject.ServiceContainer.EmitLifetime(ServiceRegistration serviceRegistration, Action`1 emitMethod, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4656\r\n   at LightInject.ServiceContainer.<>c__DisplayClass153_0.<CreateEmitMethodWrapper>b__0(IEmitter ms) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3856\r\n   at LightInject.ServiceContainer.EmitConstructorDependency(IEmitter emitter, Dependency dependency) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4158\r\n   at LightInject.ServiceContainer.EmitConstructorDependencies(ConstructionInfo constructionInfo, IEmitter emitter, Action`1 decoratorTargetEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4120\r\n   at LightInject.ServiceContainer.EmitNewInstanceUsingImplementingType(IEmitter emitter, ConstructionInfo constructionInfo, Action`1 decoratorTargetEmitMethod) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4081\r\n   at LightInject.ServiceContainer.EmitNewInstance(ServiceRegistration serviceRegistration, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4038\r\n   at LightInject.ServiceContainer.<>c__DisplayClass153_0.<CreateEmitMethodWrapper>b__0(IEmitter ms) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3856\r\n   at LightInject.ServiceContainer.CreateDynamicMethodDelegate(Action`1 serviceEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3777\r\n   at LightInject.ServiceContainer.CreateDelegate(Type serviceType, String serviceName, Boolean throwError) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4743\r\n   at LightInject.ServiceContainer.CreateDefaultDelegate(Type serviceType, Boolean throwError) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4705\r\n   at LightInject.ServiceContainer.GetInstance(Type serviceType) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3437\r\n   at Umbraco.Core.Composing.ComponentCollectionBuilder.CreateItem(IFactory factory, Type itemType) in D:\\a\\1\\s\\src\\Umbraco.Core\\Composing\\ComponentCollectionBuilder.cs:line 33\r\n   at System.Linq.Enumerable.WhereSelectArrayIterator`2.MoveNext()\r\n   at System.Linq.Buffer`1..ctor(IEnumerable`1 source)\r\n   at System.Linq.Enumerable.ToArray[TSource](IEnumerable`1 source)\r\n   at Umbraco.Core.Composing.ComponentCollectionBuilder.CreateItems(IFactory factory) in D:\\a\\1\\s\\src\\Umbraco.Core\\Composing\\ComponentCollectionBuilder.cs:line 25\r\n   at Umbraco.Core.Composing.CollectionBuilderBase`3.CreateCollection(IFactory factory) in D:\\a\\1\\s\\src\\Umbraco.Core\\Composing\\CollectionBuilderBase.cs:line 117\r\n   at LightInject.PerContainerLifetime.GetInstance(Func`1 createInstance, Scope scope) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 6169\r\n   at LightInject.ServiceContainer.EmitLifetime(ServiceRegistration serviceRegistration, Action`1 emitMethod, IEmitter emitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4656\r\n   at LightInject.ServiceContainer.<>c__DisplayClass153_0.<CreateEmitMethodWrapper>b__0(IEmitter ms) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3856\r\n   at LightInject.ServiceContainer.CreateDynamicMethodDelegate(Action`1 serviceEmitter) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3777\r\n   at LightInject.ServiceContainer.CreateDelegate(Type serviceType, String serviceName, Boolean throwError) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4743\r\n   at LightInject.ServiceContainer.CreateDefaultDelegate(Type serviceType, Boolean throwError) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 4705\r\n   at LightInject.ServiceContainer.GetInstance(Type serviceType) in C:\\projects\\lightinject\\src\\LightInject\\LightInject.cs:line 3437\r\n   at Umbraco.Core.FactoryExtensions.GetInstance[T](IFactory factory) in D:\\a\\1\\s\\src\\Umbraco.Core\\FactoryExtensions.cs:line 22\r\n   at Umbraco.Core.Runtime.CoreRuntime.Boot(IRegister register, DisposableTimer timer) in D:\\a\\1\\s\\src\\Umbraco.Core\\Runtime\\CoreRuntime.cs:line 187\r\n   at Umbraco.Core.Exceptions.BootFailedException.Rethrow(BootFailedException bootFailedException) in D:\\a\\1\\s\\src\\Umbraco.Core\\Exceptions\\BootFailedException.cs:line 64\r\n   at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()\r\n   at System.Web.HttpApplication.ExecuteStepImpl(IExecutionStep step)\r\n   at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
    

    Something is running more instances than it should.

    The solution has SeoChecker installed, and I'm seeing a large number of 404 requests with all are being logged by SeoChecker. Otherwise it could be some code running async that is not being handled properly.

  • OleP 67 posts 276 karma points
    Dec 21, 2021 @ 12:38
    OleP
    102

    Turned out to be some json serilization of NestedContent that created a stackoverflow.

  • David Sheiles 67 posts 337 karma points
    Oct 22, 2023 @ 05:23
    David Sheiles
    0

    Hi OleP,

    I've been trying to track down this issue for quite some time. I'm also running an Auzre VM with custom tables etc.

    Do you remember how you tracked down the json serialization issue and what you did to correct it?

    Thanks

  • OleP 67 posts 276 karma points
    Oct 22, 2023 @ 06:51
    OleP
    0

    Hi David

    I spent a lot of time in the server log looking at the events around the time of the crashes.

    I think we did something to log every requested url along with the response code. That way we could look for urls that never got a response code, since the site crashed.

    It was an absolute horror to find, since it was only this particular url that caused the error.

    Good luck!

  • David Sheiles 67 posts 337 karma points
    Oct 22, 2023 @ 22:19
    David Sheiles
    0

    Thanks OleP,

    I've resorted to the same sort of logging to figure it out too. Was hoping for a magic answer :)

    Thanks for your help.

Please Sign in or register to post replies

Write your reply to:

Draft