Workflow Soluiton

We're experiencing a significant number of timeouts in a number of web services in our production environment.  It's important to note that we're only being informed of these exceptions in workflows which call other workflows.  By default, we have 60 second timeouts on the majority of our integration components.  However, the issue seems to be impacting all production workflows which I explain later in this post.

Here are examples of some of the timeout exceptions:

Example 1:
System.Net.WebException: The operation has timed out at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters) at wsCWx_CIA_Server_Build.CIAService.CWxStartCIATask(String CRId, String TaskId) at wsCWx_CIA_Server_Build.CWxStartCIATask.Run(IData data) at LogicBase.Core.ExecutionEngine.SinglePathProcessComponentExecutionDelegate.Execute(IData data, IOrchestrationComponent comp, String& outputPath, IExecutionEngine engine, TLExecutionContext context) at LogicBase.Core.ExecutionEngine.AbstractExecutionEngine.DoRunComp(IOrchestrationComponent comp, IData data, TLExecutionContext context)

Example 2:
System.Net.WebException: The operation has timed out at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters) at wsCWxServerBuildTurnoverService.TurnoverService.Turnover(String CRNumber, String TaskNumber) at wsCWxServerBuildTurnoverService.Turnover.Run(IData data) at LogicBase.Core.ExecutionEngine.SinglePathProcessComponentExecutionDelegate.Execute(IData data, IOrchestrationComponent comp, String& outputPath, IExecutionEngine engine, TLExecutionContext context) at LogicBase.Core.ExecutionEngine.AbstractExecutionEngine.DoRunComp(IOrchestrationComponent comp, IData data, TLExecutionContext context)

Example 3:
System.Net.WebException: The operation has timed out at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters) at WTS_RemediationDynamicService.WTS_Remediation.Execute(String EachServer, Int32 ServerID) at WTS_RemediationDynamicService.ExecuteSpawn.Run(IData data) at LogicBase.Core.ExecutionEngine.SinglePathProcessComponentExecutionDelegate.Execute(IData data, IOrchestrationComponent comp, String& outputPath, IExecutionEngine engine, TLExecutionContext context) at LogicBase.Core.ExecutionEngine.AbstractExecutionEngine.DoRunComp(IOrchestrationComponent comp, IData data, TLExecutionContext context)

Example 4:
System.Net.WebException: The operation has timed out at System.Web.Services.Protocols.WebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.HttpWebClientProtocol.GetWebResponse(WebRequest request) at System.Web.Services.Protocols.SoapHttpClientProtocol.Invoke(String methodName, Object[] parameters) at SNRTroubleshootDynamicService.SNRTroubleshoot.Execute(String EachServer, Int32 ServerID) at SNRTroubleshootDynamicService.RunTroubleshoot.Run(IData data) at LogicBase.Core.ExecutionEngine.SinglePathProcessComponentExecutionDelegate.Execute(IData data, IOrchestrationComponent comp, String& outputPath, IExecutionEngine engine, TLExecutionContext context) at LogicBase.Core.ExecutionEngine.AbstractExecutionEngine.DoRunComp(IOrchestrationComponent comp, IData data, TLExecutionContext context)

The list goes on and on, but I wanted to provide a few examples.  My initial thought was something on the IIS side so I kicked off one of the workflows that we're experiencing timeouts for in debug with identical inputs.  The workflow hangs in debug for approximately 100 seconds with a message stating "Executing BuildLogInfoService.asmx\GetRemedyBuildDataByCR..." in the status window.  After the 100 seconds elapses the workflow takes off and completes successfully in about 1 second.  We are NOT using IIS in debug so I feel fairly confident that this is not an issue with IIS or a configuration within IIS or our application pools.  The particular workflow that I included designer and soapUI screenshots for does not call any other workflows -- it is one of our more simple services that makes 6 calls to a database and returns the data as part of the service.

When I call the same web service via soapUI I see similar results.  When working, the web service generally returns within 500-600ms.  Now the web service often takes 100000ms (100s) to return.

This issue first occurred on May, 9 and we were able to resolve it by cycling LogicBase.  The next occurrence was yesterday, May, 15.  We cycled LogicBase extension and got some relief, but were still noticing 100s returns intermittently.  The issue is occurring again today and seems to be worse than the previous 2 occurrences.  Nothing significant in our production environment has changed since this issue began occurring.

I found this exception in our logs for Ensemble indicating that there are no connections available in the pool.  Could this be the cause of our issues?  I cycled LogicBase services again and a few minutes after doing so our service are now functional again, but that has proven to only be a temporarly fix.

Application Name: Ensemble2006

Process ID: 16720

Date :May-16-2012 10:29:32 AM

Log Level :Error

Log Category :DALProxy

Machine Name: TASPMOBPA111

Message:

[DAL] Error executing sql query. Query

[DAL] SELECT [User].[UserID] AS [UserID], [User].[Password] AS [Password], [User].[AccountActive] AS [AccountActive], [User].[Theme] AS [Theme], [User].[MenuRenderer] AS [MenuRenderer], [User].[CanChangePassword] AS [CanChangePassword], [User].[Language] AS [Language], [User].[ContactOwnerID] AS [ContactOwnerID], [User].[SecurityAnswer] AS [SecurityAnswer], [User].[MenuStyle] AS [MenuStyle], [User].[DisplayName] AS [DisplayName], [User].[Office] AS [Office], [User].[USNChanged] AS [USNChanged], [User].[LastName] AS [LastName], [User].[DefaultShowSecondaryMenu] AS [DefaultShowSecondaryMenu], [User].[FirstName] AS [FirstName], [User].[PerUserSalt] AS [PerUserSalt], [User].[OrganizationTitle] AS [OrganizationTitle], [User].[IsContact] AS [IsContact], [User].[MiddleInitial] AS [MiddleInitial], [User].[PasswordHint] AS [PasswordHint], [User].[MustChangePassword] AS [MustChangePassword], [User].[IsActiveDirectoryUser] AS [IsActiveDirectoryUser], [User].[AccountExpires] AS [AccountExpires], [User].[Salutation] AS [Salutation], [User].[Manager] AS [Manager], [User].[VIP] AS [VIP], [User].[Description] AS [Description], [User].[Location] AS [Location], [User].[IsLocked] AS [IsLocked], [User].[ShowNotifications] AS [ShowNotifications], [User].[Title] AS [Title], [User].[SelectTimeZone] AS [SelectTimeZone], [User].[SecurityQuestion] AS [SecurityQuestion], [User].[PasswordExpireDate] AS [PasswordExpireDate], [User].[ShowSecondaryMenu] AS [ShowSecondaryMenu], [User].[HomePage] AS [HomePage], [User].[DynamicallyTimeZone] AS [DynamicallyTimeZone], [User].[EmployeeID] AS [EmployeeID], [User].[NickName] AS [NickName], [User].[OrganizationUnit] AS [OrganizationUnit], [User].[PrimaryEmail] AS [PrimaryEmail], [User].[BlankPasswordAllowed] AS [BlankPasswordAllowed], [User].[PasswordNeverExpires] AS [PasswordNeverExpires], [User].[Initials] AS [Initials], [User].[LastLoggedInTime] AS [LastLoggedInTime], [User].[ADLoginName] AS [ADLoginName], [User].[WebPage] AS [WebPage] FROM [User] WHERE ([User].[UserID] = @UserID0)

[DAL] -- error.ToString() --

[DAL] 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.

[DAL] at System.Data.ProviderBase.DbConnectionFactory.GetConnection(DbConnection owningConnection)

[DAL] at System.Data.ProviderBase.DbConnectionClosed.OpenConnection(DbConnection outerConnection, DbConnectionFactory connectionFactory)

[DAL] at System.Data.SqlClient.SqlConnection.Open()

[DAL] at LogicBase.Framework.DataLayer.DALProxy.ExecuteCommandMultipleRecords(IDbCommand cmd, Type entityType)

There is a limit to how many connections you can have to a SQL server. In .NET, I believe the limit is 50 - which is usually enough.

It seems you are exceeding that limit. This is usually casued by not closing the connection when your DB call is complete.

You could try increasing the connection pool in the connection string by adding Max Pool Size=100.

If your queries bomb out, then the connection is not closed properly and it's left open .NET is supposed to have Garbage Collection that closes any connections, but sometimes that does not work porperly.

What I find myself doing is restarting the WF servervice at least one per week to "clean out" and problems before they start.

Maybe one of the Symantec employees can weigh in on this?

Rob