U4-9920 - SQL error "Timeout expired. The timeout period elapsed prior to obtaining a connection from the pool." after upgrade to 7.6.1

Created by Markus Johansson 16 May 2017, 09:12:39 Updated by Murray Roke 30 Aug 2017, 22:03:01

Upgrades a website from Umbraco 7.5.6 to 7.6.1 yesterday and are now experiencing issues with this.

The site, that has some (or lots) of custom code, was running very nice on 7.5.6 but after the upgrade this error shows up after the site has been running for 10-15 minutes. About 140 nodes in the solution.

"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."

Full stack trace and error:

Server Error in '/' Application.

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.

Description: An unhandled exception occurred during the execution of the current web request. Please review the stack trace for more information about the error and where it originated in the code.

Exception 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.

Source Error:

An unhandled exception was generated during the execution of the current web request. Information regarding the origin and location of the exception can be identified using the exception stack trace below.

Stack Trace:

[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.] System.Data.ProviderBase.DbConnectionFactory.TryGetConnection(DbConnection owningConnection, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) +445 System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) +318 System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) +211 System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) +393 System.Data.SqlClient.SqlConnection.Open() +122 Umbraco.Core.Persistence.FaultHandling.<>c__DisplayClass1.b__0() +15 Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction(Func1 func) +383 Umbraco.Core.Persistence.Database.OpenSharedConnection() +77 Umbraco.Core.Persistence.<Query>d__71.MoveNext() +183 System.Collections.Generic.List1..ctor(IEnumerable1 collection) +452 System.Linq.Enumerable.ToList(IEnumerable`1 source) +70 Umbraco.Core.Sync.DatabaseServerMessenger.ProcessDatabaseInstructions() +889 Umbraco.Core.Sync.DatabaseServerMessenger.Sync() +311 Umbraco.Web.UmbracoModule.OnRouteAttempt(RoutableAttemptEventArgs args) +53 Umbraco.Web.UmbracoModule.ProcessRequest(HttpContextBase httpContext) +309 System.Web.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() +142 System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) +92

Comments

Jeavon Leopold 16 May 2017, 09:17:24

@enkelmedia do you have any packages installed that are using the legacy SQLHelper classes, such as SEOChecker? I observed this issue also on a upgraded site and traced it to the legacy SQLHelper that was been used by SEOChecker, something seems to have changed which means the SQLHelper is leaving connections open until they run out. My workaround was to disable SEO checker (by removing the modules in web.config), since then the issue has not occurred. SEO Checker v2 is in the works which doesn't use the legacy SQLHelper.


Markus Johansson 16 May 2017, 10:11:39

Thanks @crumpled_jeavon!

I'll give that a try. Strange that the call to the legazy helper stopped working after the upgrade? Feels like the Umbraco core should close the connection even if it's a call to the legazy helper?


Markus Johansson 16 May 2017, 12:43:46

When it comes SEO Checker the solution seams to be around the corner: https://our.umbraco.org/projects/website-utilities/seo-checker/bugs/85752-issues-with-legazy-sql-helper#comment-271664

But for other stuff that are using the old SqlHelpers this might still be an issue.


Ivan Doroshenko 03 Aug 2017, 14:20:15

Hello guys,

I have the same issue now after upgrade from 7.5.4 to 7.6.3 and I have no installed SEO Checker at the project. Please, advice how can I find the cause of this issue. @crumpled_jeavon

Thanks Ivan


Jeavon Leopold 03 Aug 2017, 14:47:13

@Ivan.Doroshenko I would suggest you use SQL Profiler to see whats going on. Also check if you have any old third party packages/dlls or code that might be using the Legacy SQLHelper


Ivan Doroshenko 03 Aug 2017, 14:51:13

@crumpled_jeavon I've used the Resharper to find usages of SQLHelper and it's used only in old Umrbaco libraries like cms.dll and businesslogic.dll


Markus Johansson 03 Aug 2017, 15:54:22

@Ivan.Doroshenko Did you upgrade to latest version of SEO Checker? That solved the issue for me, I'm not using SQLHelper in any other code or package.


Ivan Doroshenko 03 Aug 2017, 16:08:13

@enkelmedia this project does not have an installed SEO Checker. But it has an Ucommerce. Can it cause this?


Markus Johansson 03 Aug 2017, 16:15:16

Everything that uses the SQLHelper will leak connections to the db. If you have any code or packages that does you need to address this.


Ivan Doroshenko 03 Aug 2017, 17:07:05

@enkelmedia there are no SQLHelper usages in our code, only the calls to ApplicationContext.Current.DatabaseContext.Database.

How can I find the usages in the packages? Is there any way to log/profile all the SqlConnection usages in the app?


Markus Johansson 03 Aug 2017, 17:39:01

Okey, are you closing the connections? Or wrapping the code with using statements? You Can check the nr of open connections using this approach: https://stackoverflow.com/questions/8738941/how-to-monitor-active-connection-pool-in-sql-server


Arnstein Berg 09 Aug 2017, 08:20:00

I have the same issue, after upgrading from 7.5.4 to 7.6.3. I then upgraded to 7.6.4, but the issue remains. When checking open connections to SQL Server I see there are a lot of connections running this stagement:

(@userId int,@nodeId int,@logHeader nvarchar(6),@comment nvarchar(94))insert into umbracoLog (userId, nodeId, logHeader, logComment) values (@userId, @nodeId, @logHeader, @comment)

It always happens after the application is restarted and each call gets slower and slower until the issue occur, unless I manage to intercept before the pool limit is reached and publish some content. It doesn't matter what I publish or if I make changes. If I can just get into the backend and press Publish on any node, everything works fine until next restart.

I don't have deep understanding of the Umbraco code, but it seems that this could be a combination of stale connections in some logging code (async log4net-appenders may cause this), and the XML cache not initializing properly until a publish is done. I guess it could be a different problem entirely, but this is what I have observed. I currently run 7.6.4 with uCommerce installed. No other packages.


Markus Johansson 09 Aug 2017, 08:52:38

@post@arnsteinberg.no Looks like the legazy log helper that probably uses the SqlHelper which is the problem. I guess that some packages uses this helper. @Shandem Is there any fixes for this or do everyone have to avoid the SqlHelper (and legazy loghelper) to be safe?


Shannon Deminick 09 Aug 2017, 09:04:28

Which legacy LogHelper are you referring to?

The only time Umbraco writes to umbracoLog is during an Audit - like when saving content or something. And that is all done with non legacy SQL interaction.

I've never noticed that umbraco.BusinessLogic.Log is not marked obsolete, but this should definitely and absolutely not be used. The umbracoLog table is for auditing information only not for actual logging. Logging has been moved to log4net for many years now and you can either use Umbraco's static LogHelper or the ILogger instance which is on the ApplicationContext.ProfilingLogger


Arnstein Berg 09 Aug 2017, 10:07:28

I see from the log that many of these calls come from umbraco.BusinessLogic.Log.AddSynced(LogTypes type, Int32 userId, Int32 nodeId, String comment). It seems it is called in the context of ScheduledPubishing, and fails with the message "An error occurred adding an audit trail log to the umbracoLog table". This method uses SqlHelper, as far as I can see from https://github.com/umbraco/Umbraco-CMS/blob/dev-v7/src/umbraco.businesslogic/Log.cs (line 170)


Markus Johansson 09 Aug 2017, 11:25:00

@Shandem I know about the new way to perform logging, but this issue (U4-9920) was posted because something changed in the core. I personally had issues with SEO Checker and Richard Soeteman solved this by eliminating all use of the old SQLHelper. I look at it and found out that the issue probably is that the SqlHelper never closes the connection to the database resulting in too many connection and this timeout error. I'm not sure but I figured that if the legazy Log-class (umbraco.BusinessLogic.Log) uses the SqlHelper which it does (https://github.com/umbraco/Umbraco-CMS/blob/ca0de5acd30488875bd14f601a27f4f0e1199704/src/umbraco.businesslogic/Log.cs#L161) that might be the problem? As the SqlHelper doesn't close the connection?


Shannon Deminick 09 Aug 2017, 12:50:29

Yup it could definitely be a problem depending on how the legacy SqlHelper is called (i.e. on what type of thread). Did you mean to link to 'this' issue or to a different one?

@arnstein do you have a stack trace? I have just discovered that the LogScrubber actually uses this old class but only to call into CleanLogs not AddSynced. I don't think this is the culprit since this doesn't occur very often but we should fix that anyways.

This class could/should be updated to not use the old SqlHelper, at least that will help old code and packages still using this. It also needs to be marked as obsolete.


Markus Johansson 09 Aug 2017, 13:10:29

@Shandem Sorry, the "link" was to this issue. Added the ref. to make it clear.


Arnstein Berg 09 Aug 2017, 14:32:55

It seems there's a sequence of exceptions that happens every 10s. I have listed one "iteration" of these exceptions below. Hard to tell what sets it off, but as I said it happens on each app restart, unless I manage to log onto the backend and hit publish on any node before the connection pool limit is reached. Could it be a retry-pattern maybe?

2017-07-20 11:04:32,277 [P4764/D2/T30] ERROR umbraco.DataLayer.SqlHelper1[[System.Data.SqlClient.SqlParameter, System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]] - Error executing query insert into umbracoLog (userId, nodeId, logHeader, logComment) values (@userId, @nodeId, @logHeader, @comment) System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.<ExecuteAction>b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at umbraco.DataLayer.CurrentConnectionUsing..ctor() at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteNonQuery(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) 2017-07-20 11:04:32,277 [P4764/D2/T30] ERROR umbraco.BusinessLogic.Log - An error occurred adding an audit trail log to the umbracoLog table umbraco.DataLayer.SqlHelperException: Umbraco Exception (DataLayer): SQL helper exception in ExecuteNonQuery ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.<ExecuteAction>b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at umbraco.DataLayer.CurrentConnectionUsing..ctor() at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteNonQuery(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) --- End of inner exception stack trace --- at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) at umbraco.BusinessLogic.Log.AddSynced(LogTypes type, Int32 userId, Int32 nodeId, String comment) 2017-07-20 11:04:32,293 [P4764/D2/T28] ERROR umbraco.DataLayer.SqlHelper1[[System.Data.SqlClient.SqlParameter, System.Data, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089]] - Error executing query insert into umbracoLog (userId, nodeId, logHeader, logComment) values (@userId, @nodeId, @logHeader, @comment) System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.<ExecuteAction>b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at umbraco.DataLayer.CurrentConnectionUsing..ctor() at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteNonQuery(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) 2017-07-20 11:04:32,293 [P4764/D2/T28] ERROR umbraco.BusinessLogic.Log - An error occurred adding an audit trail log to the umbracoLog table umbraco.DataLayer.SqlHelperException: Umbraco Exception (DataLayer): SQL helper exception in ExecuteNonQuery ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.<ExecuteAction>b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at umbraco.DataLayer.CurrentConnectionUsing..ctor() at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteNonQuery(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) --- End of inner exception stack trace --- at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) at umbraco.BusinessLogic.Log.AddSynced(LogTypes type, Int32 userId, Int32 nodeId, String comment)


Arnstein Berg 09 Aug 2017, 15:01:23

Now I checked what is written in the umbracoLog table (should probably have done that earlier) and after a restart I see about 100 entries only a few ms apart, saying "No connection string was found. Indicating a fresh Umbraco7 instance. Determining took: 0 ms.". I have a connectionstring specified that works later, so that's not the thing. But there may be several issues here: A race condition in reading the config on startup, an upgrade checker logging exessively, and also using an old logger method which causes the system to hang. Is this coming from Umbraco, or could it be uCommerce?


Ivan Doroshenko 09 Aug 2017, 15:10:35

@arnstein I'm still getting this exception at my client's project. And we also have uCommerce there. I hope you'll find a solution. Please, make a note if you find something. I will appreciate it.


Arnstein Berg 09 Aug 2017, 15:56:33

@Ivan.Doroshenko Yes, I will update this post if I find something elsewhere. @enkelmedia do you by any chance have uCommerce installed? If that is the case that could be it. However, I see now that the exessive logging in umbracoLog mentioned earlier, only happens on a few restarts. So there must be other things that steals connections as well. This issue first occurred after upgrading Umbraco, and I did not upgrade uCommerce at that time.


Ivan Doroshenko 09 Aug 2017, 18:30:32

@arnstein @Shandem I've found the same repeating error in the logs:

2017-08-09 00:02:25,656 [P4196/D2/T90] ERROR umbraco.BusinessLogic.Log - An error occurred adding an audit trail log to the umbracoLog table umbraco.DataLayer.SqlHelperException: Umbraco Exception (DataLayer): SQL helper exception in ExecuteNonQuery ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at System.Reflection.MethodBase.Invoke(Object obj, Object[] parameters) at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteNonQuery(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteNonQuery(String commandText, IParameter[] parameters) --- End of inner exception stack trace --- at umbraco.DataLayer.SqlHelper`1.ExecuteNonQuery(String commandText, IParameter[] parameters) at umbraco.BusinessLogic.Log.AddSynced(LogTypes type, Int32 userId, Int32 nodeId, String comment)


Shannon Deminick 10 Aug 2017, 04:21:47

Thanks everyone for helping out here.

I would suggest that you try to disable uCommerce and see what happens. As i mentioned, there is no usage of this class or method in Umbraco especially during startup, that simply is not part of the Umbraco codebase. The only time this code is used in umbraco are for a couple legacy webforms views, for cleaning the logs (which does nto use the AddSynced method and only runs occasionally), and in the legacy membership providers (from a very very long time ago)


Markus Johansson 10 Aug 2017, 07:15:12

@Shannon Is it impossible to make sure that the SQLHelper closes the connection? I'm not sure what "happened" but this error started to show when I upgraded to 7.6 - I mean there are packages out there that uses these methods and I guess that (sadly) people will not blame the package but "Umbraco" for the errors/issues. Either to fix the issue or at least mark the methods as obsolete and be clear about that you will cause issues if you use them?


Shannon Deminick 10 Aug 2017, 08:04:08

Yes basically, there was actually tons of fixes for this in 7.6 due to connection leaks with the SqlHelper. Previously there was actually lots of different connections created even in the same request if this was used.

I would need to replicate this issue because that old Log class is disposing connections but I'd have to verify. Yes it's unfortunate that this class is not marked as obsolete but I would like to know what is using it.


Markus Johansson 10 Aug 2017, 08:25:01

@Shandem I see - my bet is that a lot of old packages and maybe some custom code in different projects is using this class - My issues was not related to anything in the at that point.


Arnstein Berg 11 Aug 2017, 07:57:54

Found it! I added a print of the callstack in AddSynced(), recompiled umbraco.businesslogic.dll and added it to my solution. Then this callstack came out:

at umbraco.BusinessLogic.Log.AddSynced(LogTypes type, Int32 userId, Int32 nodeId, String comment) at umbraco.BusinessLogic.Log.Add(LogTypes type, User user, Int32 nodeId, String comment) at UCommerce.Umbraco7.Installer.UmbracoInstallerLoggingService.Log[T](String customMessage) at UCommerce.Umbraco7.Installer.Installer.InstallInternal() at UCommerce.Umbraco7.Installer.Installer.PreStart(Object sender, EventArgs e) at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) at System.Web.HttpApplication.PipelineStepManager.ResumeSteps(Exception error) at System.Web.HttpApplication.BeginProcessRequestNotification(HttpContext context, AsyncCallback cb) at System.Web.HttpRuntime.ProcessRequestNotificationPrivate(IIS7WorkerRequest wr, HttpContext context) at System.Web.Hosting.PipelineRuntime.ProcessRequestNotificationHelper(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags) at System.Web.Hosting.PipelineRuntime.ProcessRequestNotification(IntPtr rootedObjectsPointer, IntPtr nativeRequestContext, IntPtr moduleData, Int32 flags)

It's the uCommerce installer that is causing this. It actually logs, on every request until something is published, to the database, that it can't find the connectionstring to the database :-P So I headed over to uCommerce to see if I could find anything on this, and in the [https://ucommerce.net/support/release-notes 7.7.0.17130 changelog] I found this: "FIX: Now Umbraco.Core.Logging.LogHelper instead of deprecated BusinessLogic.Log doing Ucommerce installation.".

So it seems the issue is fixed in uCommerce 7.7. I'm on 7.5 and haven't had the chance to upgrade yet, but I will try that. I will also check if the excessive logging is still there, but I guess that could also be an issue related to Umbraco 7.6 changes, that is fixed in uCommerce 7.7.

You can quick-fix the connection pool issue however, by just blocking out system events from the audit log. Of course that would filter out all system events, like restarts and such, but that's probably not a big problem. Just add this to the UmbracoSettings.config, and you're good:

system


Ivan Doroshenko 12 Aug 2017, 15:36:32

@arnstein wow! thank you so much. I will try to apply your fix and let you know. thanks again.


Frederik Raabye 15 Aug 2017, 10:35:24

I am getting what appears to be a similar error in 7.6.5: "The timeout period elapsed prior to obtaining a connection from the pool."

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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() at Umbraco.Core.Persistence.Database.<Query>d__71.MoveNext() at System.Collections.Generic.List1..ctor(IEnumerable1 collection) at System.Linq.Enumerable.ToList[TSource](IEnumerable`1 source) at Umbraco.Core.Sync.DatabaseServerMessenger.ProcessDatabaseInstructions() at Umbraco.Core.Sync.DatabaseServerMessenger.Sync() at Umbraco.Web.UmbracoModule.OnRouteAttempt(RoutableAttemptEventArgs args) at Umbraco.Web.UmbracoModule.ProcessRequest(HttpContextBase httpContext) at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Only custom code is ad fs auth for users and SEOChecker.


Jose Guay 18 Aug 2017, 20:09:26

Hello @Ivan.Doroshenko and @Shandem.

We upgraded our instance of Umbraco from 7.5.11 to 7.6.4 a couple of weeks ago and ever since we are hitting this very same problem. In our case, we don't have UCommerce, the only package we have installed is Umbraco Courier.

This is the errors we are getting:

2017-08-18 14:51:39,990 [P14720/D3/T11] ERROR Umbraco.Core.UmbracoApplicationBase - An unhandled exception occurred umbraco.DataLayer.SqlHelperException: Umbraco Exception (DataLayer): SQL helper exception in ExecuteReader ---> System.Reflection.TargetInvocationException: Exception has been thrown by the target of an invocation. ---> 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, TaskCompletionSource1 retry, DbConnectionOptions userOptions, DbConnectionInternal oldConnection, DbConnectionInternal& connection) at System.Data.ProviderBase.DbConnectionInternal.TryOpenConnectionInternal(DbConnection outerConnection, DbConnectionFactory connectionFactory, TaskCompletionSource1 retry, DbConnectionOptions userOptions) at System.Data.SqlClient.SqlConnection.TryOpenInner(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.TryOpen(TaskCompletionSource1 retry) at System.Data.SqlClient.SqlConnection.Open() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.<>c__DisplayClass1.b__0() at Umbraco.Core.Persistence.FaultHandling.RetryPolicy.ExecuteAction[TResult](Func1 func) at Umbraco.Core.Persistence.Database.OpenSharedConnection() --- End of inner exception stack trace --- at System.RuntimeMethodHandle.InvokeMethod(Object target, Object[] arguments, Signature sig, Boolean constructor) at System.Reflection.RuntimeMethodInfo.UnsafeInvokeInternal(Object obj, Object[] parameters, Object[] arguments) at System.Reflection.RuntimeMethodInfo.Invoke(Object obj, BindingFlags invokeAttr, Binder binder, Object[] parameters, CultureInfo culture) at umbraco.DataLayer.CurrentConnectionUsing..ctor() at umbraco.DataLayer.SqlHelpers.SqlServer.SqlServerHelper.ExecuteReader(String commandText, SqlParameter[] parameters) at umbraco.DataLayer.SqlHelper1.ExecuteReader(String commandText, IParameter[] parameters) --- End of inner exception stack trace --- at umbraco.DataLayer.SqlHelper`1.ExecuteReader(String commandText, IParameter[] parameters) at InfoCaster.Umbraco.UrlTracker.Modules.UrlTrackerModule.UrlTrackerDo(String callingEventName, Boolean ignoreHttpStatusCode) in d:\kipusoep\Documents\GitHub\UrlTracker\Modules\UrlTrackerModule.cs:line 212 at InfoCaster.Umbraco.UrlTracker.Modules.UrlTrackerModule.context_AcquireRequestState(Object sender, EventArgs e) in d:\kipusoep\Documents\GitHub\UrlTracker\Modules\UrlTrackerModule.cs:line 76 at System.Web.HttpApplication.SyncEventExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)

Has this been addressed in 7.6.5? Any ideas?

Thank you Jose Guay


Arnstein Berg 18 Aug 2017, 20:41:54

@jrguay It seems you may have InfoCaster.Umbraco.UrlTracker installed, and this is using the deprecated and problematic SqlHelper. Could be an old package that hasn't been properly uninstalled.

You could probably try to remove it, as mentioned here: https://our.umbraco.org/forum/extending-umbraco-and-using-the-api/87454-what-is-infocaster-does-anything-break-if-i-delete-the-dll


Jose Guay 18 Aug 2017, 21:11:30

Thank you Amstein. That makes sense. I'll try that and post here if this helped solve the problem.


Jose Guay 21 Aug 2017, 15:10:50

Hi guys. Thank you for the help Amstein. It seems that was the culprit and everything is working fine now.


Arnstein Berg 21 Aug 2017, 20:40:29

Excellent! @Shandem: If this SqlHelper is a dangerous and potentially crashes the site by locking up the database, wouldn't it be better to have it throw an ObsoleteException, or maybe have it return an empty result? Then there will be clearer which package causes the problem, and easier to diagnose. Of course things will break, but that is already happening.


Markus Johansson 22 Aug 2017, 12:04:49

I would agree with @arnstein


Shannon Deminick 23 Aug 2017, 00:51:12

I'll have to loop @zpqrtbnk in on this one. IIRC the SqlHelper has always been 'dangerous' however in 7.6+ it perhaps is more dangerous since if it's not disposed like it should have been then it will leak connections (though it already did that before but maybe not so severely). Stephan what are your thoughts on this?


Stephan 23 Aug 2017, 01:43:24

A few things: when seeing the "timeout elapsed prior to...", the interesting part is not ''where'' this happens (could be anything) but ''why'' the connection pool is exhausted, ie the list of current connections and their associated last executed SQL. Quite probably, one SQL must be repeated ''a lot'' and that's what we want to identify. It probably corresponds to an invalid usage of the old SqlHelper.

Since 7.6 SqlHelper uses the DatabaseContext.Database instance instead of creating ''another instance''. In 7.5 one could end up with two database connections being used during the same requests, with some weird consequences. In 7.6, only one connection is used. However, it implies that SqlHelper must be used properly (disposed) in order not to leak connections.

I don't think SqlHelper is particularly dangerous. The issue seems to appear when it's used in weird ways that used to work but don't anymore. I'm afraid killing SqlHelper entirely is going to cause more compatibility issues - it's a large breaking change - not even sure it's OK in eg 7.8 (@Shandem ?). I'm always happy to break things but here I'm afraid it might be too much.

I'd love to see the SQL and code that's causing the pool exhaustion. Wondering if there's a way we can make the helper more robust (detect if it's not disposed at end of request...). Could also blog about it to raise ppl awareness.


Shannon Deminick 23 Aug 2017, 02:14:56

I'm fairly positive its because the SqlHelper is not being disposed, most of the code that i've seen in packages, etc... don't do this so i'm pretty sure that's the issue.


Stephan 23 Aug 2017, 21:02:56

Update: the SqlHelper is not meant to be disposed. That was the case, previously, because it was creating its own database connection. Now, it hooks into the persistence layer to make sure it is re-using the "ambient" UmbracoDatabase instance, and its connection. This instance is controlled by the Scope, and we have a mechanism that ensures that it is disposed at the end of a request.

So the theory is that we ''do'' ensure that the connection is closed and disposed.

In practice it seems it is not always the case. Ideas: *There ''could'' be some issues in the SqlHelper itself *The mechanism that releases the connection "at end of request"... requires a request. Quite probably, using a SqlHelper in any kind of background task would lead to a leaked connection

I'm going to run a few tests on the SqlHelper itself to make sure it works as intended.

As for the second idea... it's kinda hard to have a SqlHelper that's backward compatible ''and'' nice with connections. Might have an idea though... will think about it.


Arnstein Berg 23 Aug 2017, 21:52:28

@zpqrtbnk I think you are right about idea #2. I always experience this at application startup. See my comment from aug 11, with the stacktrace of the method causing this problem. This is triggered by the ApplicationStarting event as far as I know. I'm not sure if ApplicationStarting runs in scope of the initial request, or outside, but I expect the latter, and that might explain why the connection leaks.


Murray Roke 30 Aug 2017, 22:03:01

I'm having this issue also, we have a bunch of packages installed, including UrlTracker. Is there a way to determine which packages are responsible? Upgrading UrlTracker seems to have fixed the issue tho.


Priority: Major

Type: Bug

State: Open

Assignee:

Difficulty: Normal

Category:

Backwards Compatible: True

Fix Submitted:

Affected versions: 7.6.5

Due in version:

Sprint:

Story Points:

Cycle: