System.TimeoutException when calling wcf service from Biztalk
I am getting the exception shown below. BizTalk is able to call the service when there is very light load. But once I increase the load and the number of messsages to transmit increases after a while I keep getting this message for all the calls to the service.
Event Type: Error
Event Source: BizTalk Server 2006
Event Category: (1)
Event ID: 5799
Date: 11/21/2011
Time: 12:55:38 PM
User: N/A
Computer: CLBIZBTS07S
Description:
The description for Event ID ( 5799 ) in Source ( BizTalk Server 2006 ) cannot be found. The local computer may not have the necessary registry information or message DLL files to display messages from a
remote computer. You may be able to use the /AUXSOURCE= flag to retrieve this description; see Help and Support for details. The following information is part of the event: sndManageServiceEndPoint_WCF,
http://service.com:8100/ManageService.svc/ws, The adapter failed to transmit message going to send port "sndManageServiceEndPoint_WCF" with URL "http://service.com:8100/ManageService.svc/ws". It will be
retransmitted after the retry interval specified for this Send Port. Details:"System.TimeoutException: Client is unable to finish the security negotiation within the configured timeout (00:01:00). The
current negotiation leg is 3 (00:00:20.6239920). ---> System.TimeoutException: The request channel timed out attempting to send after 00:00:20.6239920. Increase the timeout value passed to the call to
Request or increase the SendTimeout value on the Binding. The time allotted to this operation may have been a portion of a longer timeout. ---> System.TimeoutException: The HTTP request to
'http://service.com:8100/ManageService.svc/ws' has exceeded the allotted timeout of 00:00:20.6230000. The time allotted to this operation may have been a portion of a longer
timeout. ---> System.Net.WebException: The operation has timed out
at System.Net.HttpWebRequest.GetRequestStream(TransportContext& context)
at System.Net.HttpWebRequest.GetRequestStream()
at System.ServiceModel.Channels.HttpOutput.WebRequestHttpOutput.GetOutputStream()
--- End of inner exception stack trace ---
at System.ServiceModel.Channels.HttpOutput.WebRequestHttpOutput.GetOutputStream()
at System.ServiceModel.Channels.HttpOutput.Send(TimeSpan timeout)
at System.ServiceModel.Channels.HttpChannelFactory.HttpRequestChannel.HttpChannelRequest.SendRequest(Message message, TimeSpan timeout)
at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
--- End of inner exception stack trace ---
at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Security.IssuanceTokenProviderBase`1.DoNegotiation(TimeSpan timeout)
--- End of inner exception stack trace ---
Server stack trace:
at System.ServiceModel.Security.IssuanceTokenProviderBase`1.DoNegotiation(TimeSpan timeout)
at System.ServiceModel.Security.SspiNegotiationTokenProvider.OnOpen(TimeSpan timeout)
at System.ServiceModel.Security.WrapperSecurityCommunicationObject.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Security.SecurityUtils.OpenCommunicationObject(ICommunicationObject obj, TimeSpan timeout)
at System.ServiceModel.Security.SymmetricSecurityProtocol.OnOpen(TimeSpan timeout)
at System.ServiceModel.Security.WrapperSecurityCommunicationObject.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Channels.SecurityChannelFactory`1.ClientSecurityChannel`1.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Security.SecuritySessionSecurityTokenProvider.DoOperation(SecuritySessionOperation operation, EndpointAddress target, Uri via, SecurityToken currentToken, TimeSpan timeout)
at System.ServiceModel.Security.SecuritySessionSecurityTokenProvider.GetTokenCore(TimeSpan timeout)
at System.IdentityModel.Selectors.SecurityTokenProvider.GetToken(TimeSpan timeout)
at System.ServiceModel.Security.SecuritySessionClientSettings`1.ClientSecuritySessionChannel.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.OnOpen(TimeSpan timeout)
at System.ServiceModel.Channels.CommunicationObject.Open(TimeSpan timeout)
Exception rethrown at [0]:
at System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)
at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)
at System.ServiceModel.ICommunicationObject.Open()
at Microsoft.BizTalk.Adapter.Wcf.Runtime.WcfClient`2.GetChannel[TChannel](IBaseMessage bizTalkMessage, ChannelFactory`1& cachedFactory)
at Microsoft.BizTalk.Adapter.Wcf.Runtime.WcfClient`2.SendMessage(IBaseMessage bizTalkMessage)". .
On the service side I have the set maxReceivedMessageSize="2147483647" in the endpoint and in the behavior section I have set
<serviceThrottling
maxConcurrentCalls="16"
maxConcurrentInstances="2147483647"
maxConcurrentSessions="10"/>
These two settings did not help.
When I turned on the tracing on wcf service I see these type of errors
Activity Name Process action 'http://schemas.xmlsoap.org/ws/2005/02/trust/RST/SCT/Cancel'.
Time 2011-11-22 15:03:12.5301
Level Error
Source System.ServiceModel
Process w3wp
Thread 32
Computer FRA1BSHR01S
Trace Identifier/Code http://msdn.microsoft.com/en-US/library/System.ServiceModel.Diagnostics.ThrowingException.aspx
System.ServiceModel.EndpointNotFoundException, System.ServiceModel, Version=3.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089
There was no channel that could accept the message with action 'http://schemas.xmlsoap.org/ws/2005/02/trust/RST/SCT/Cancel'.
System.ServiceModel.Dispatcher.ErrorBehavior.ThrowAndCatch(Exception e, Message message)
System.ServiceModel.Channels.DatagramChannelDemuxer`2.ProcessItem(TInnerItem item)
System.ServiceModel.Channels.DatagramChannelDemuxer`2.HandleReceiveResult(IAsyncResult result)
System.ServiceModel.Channels.DatagramChannelDemuxer`2.OnReceiveComplete(IAsyncResult result)
System.ServiceModel.Channels.DatagramChannelDemuxer`2.OnReceiveCompleteStatic(IAsyncResult result)
System.ServiceModel.Diagnostics.Utility.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
System.ServiceModel.AsyncResult.Complete(Boolean completedSynchronously)
System.ServiceModel.Channels.ReplyChannel.HelpReceiveRequestAsyncResult.OnReceiveRequest(IAsyncResult result)
System.ServiceModel.Diagnostics.Utility.AsyncThunk.UnhandledExceptionFrame(IAsyncResult result)
System.ServiceModel.AsyncResult.Complete(Boolean completedSynchronously)
System.ServiceModel.Channels.InputQueue`1.AsyncQueueReader.Set(Item item)
System.ServiceModel.Channels.InputQueue`1.EnqueueAndDispatch(Item item, Boolean canDispatchOnThisThread)
System.ServiceModel.Channels.InputQueue`1.EnqueueAndDispatch(T item, ItemDequeuedCallback dequeuedCallback, Boolean canDispatchOnThisThread)
System.ServiceModel.Channels.InputQueueChannel`1.EnqueueAndDispatch(TDisposable item, ItemDequeuedCallback dequeuedCallback, Boolean canDispatchOnThisThread)
System.ServiceModel.Channels.SingletonChannelAcceptor`3.Enqueue(QueueItemType item, ItemDequeuedCallback dequeuedCallback, Boolean canDispatchOnThisThread)
System.ServiceModel.Channels.SingletonChannelAcceptor`3.Enqueue(QueueItemType item, ItemDequeuedCallback dequeuedCallback)
System.ServiceModel.Channels.HttpChannelListener.HttpContextReceived(HttpRequestContext context, ItemDequeuedCallback callback)
System.ServiceModel.Activation.HostedHttpTransportManager.HttpContextReceived(HostedHttpRequestAsyncResult result)
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.BeginRequest()
System.ServiceModel.Activation.HostedHttpRequestAsyncResult.OnBeginRequest(Object state)
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke2()
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.WorkItem.Invoke()
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ProcessCallbacks()
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.CompletionCallback(Object state)
System.ServiceModel.Channels.IOThreadScheduler.CriticalHelper.ScheduledOverlapped.IOCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* nativeOverlapped)
System.ServiceModel.Diagnostics.Utility.IOCompletionThunk.UnhandledExceptionFrame(UInt32 error, UInt32 bytesRead, NativeOverlapped* nativeOverlapped)
System.Threading._IOCompletionCallback.PerformIOCompletionCallback(UInt32 errorCode, UInt32 numBytes, NativeOverlapped* pOVERLAP)
[TraceRecord] Severity Error
TraceIdentifier http://msdn.microsoft.com/en-US/library/System.ServiceModel.Diagnostics.ThrowingException.aspx
Description Throwing an exception.
AppDomain /LM/W3SVC/1373337114/Root-4-129664654928269938
Answer
Although increasing the timeout on both ends of the wire (BTS and WCF Service) may help avoid the error in some instances, you might just be kicking the can further down the road and you probably need to get to the root cause (does this specific web service call NORMALLY take over 20 seconds to complete?).
It is likely that under high load, or low capacity conditions, that your WCF Web Service cannot keep up with the rate of messages that BizTalk is able to send to it.
Depending on what your WCF Service does, you might look at optimising:
Database
- SQL blocking while waiting for locks
- DB performance may reduced during admin tasks such as Reindexing Jobs, Backups etc
IIS / ASP.NET
- See if requests are being queued
- Look at any throttling on the WCF Service side (e.g. MaxConcurrentCalls)
If there is no chance of further optimisation (or scale up / out) on the WCF Service side, you may need to look at throttling the number of concurrent orchestrations (using a variant of a Singleton Orch) or limiting the number of threads on your WCF Send Port Adapter (unfortunately, this will affect all messages, so you might need to split out separate SendHost
Be wary when simply 'maxing out' all of the WCF knobs - settings like maxReceivedMessageSize (or maxBufferSize) ="2147483647" will often result in OutOfMemoryExceptions and / or increase the threat surface area.