IIS Apppool dropping connection to WCF service

Question

I'm encountering an app pool timing out on one request and it always times out around 5 minutes. I've enabled tracing, but no Warning, Error, Critical events are being logged. There are also no events in the EventViewer. I enabled FailedReqLogging and set it to log any requests over 4 minutes 30 sec. I've found the following in the C:\inetpub\logs\FailedReqLogFiles\W3SVC2 directory:

What IIS setting do I change to accomidate this request? By the Failure Reason it's listed as TIME_TAKEN so I'm guessing the AppPool exceeded some time limit. What is that limit?

I also notice that the Final Status is listed at 200. That would mean I wouldn't see anything in the logs for Warning, Critical, or Fatal because it was logged as OK. Am I right on that assumption?

Below is a stack trace of the exception found in the client trace logs. Note there is no error shown in the servers trace log. What's odd is that there is multiple nested exceptions within, but none hold real value.

...
...
<Exception>
<ExceptionType>System.ServiceModel.CommunicationException, System.ServiceModel, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089</ExceptionType>
<Message>The underlying connection was closed: A connection that was expected to be kept alive was closed by the server.</Message>
<StackTrace>
at System.ServiceModel.Channels.HttpChannelUtilities.ProcessGetResponseWebException(WebException webException, HttpWebRequest request, HttpAbortReason abortReason)
at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
at System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Dispatcher.RequestChannelBinder.Request(Message message, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)
at System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)
at System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)
at System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData&amp; msgData, Int32 type)
at OSI.Framework.ServiceContracts.IWCFObjectDirectorWebService.Fetch(Byte[] serializedObjectRequest)
at OSI.Framework.WCF.Director.WCFWebObjectDirectorProxy.Fetch(Byte[] serializedObjectRequest)
at OSI.Framework.WCF.Director.WCFWebObjectDirector.Fetch(Object criteria)
at ActvMonitorSystemBusiness.Views.ActvView.GetActvDetails(DateTime fromDate, DateTime thruDate, String userGrpCd, String userCatCd, String userMajorCd, String userStatusCd, Nullable`1 userMemberNbr, Nullable`1 subjNbr, String searchBy, String dispActivity, Boolean showUncategorizedActv, Object[] fetchOptions)
at ActvMonitorSystemScreen.frmActvMonitor.Populate(Object sender, EventArgs e)
at ActvMonitorSystemScreen.frmActvMonitor.InitializeExtension(Object sender, EventArgs e)
at OpenSolutions.Sys.DnaExtensions.Client.SecureCoreBaseForm.Initialize(Object sender, EventArgs e)
at OSI.Base.Windows.Forms.BaseForm.OnShown(EventArgs e)
at OSI.Core.Windows.Forms.CoreBaseForm.OnShown(EventArgs e)
at ActvMonitorSystemScreen.SecureCoreBaseFormShim.OnShown(EventArgs e)
at System.Windows.Forms.Form.CallShownEvent()
at System.Windows.Forms.Control.InvokeMarshaledCallbackDo(ThreadMethodEntry tme)
at System.Windows.Forms.Control.InvokeMarshaledCallbackHelper(Object obj)
at System.Threading.ExecutionContext.RunInternal(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state, Boolean preserveSyncCtx)
at System.Threading.ExecutionContext.Run(ExecutionContext executionContext, ContextCallback callback, Object state)
at System.Windows.Forms.Control.InvokeMarshaledCallback(ThreadMethodEntry tme)
at System.Windows.Forms.Control.InvokeMarshaledCallbacks()
at System.Windows.Forms.Control.WndProc(Message&amp; m)
at System.Windows.Forms.ScrollableControl.WndProc(Message&amp; m)
at System.Windows.Forms.Form.WndProc(Message&amp; m)
at System.Windows.Forms.Control.ControlNativeWindow.OnMessage(Message&amp; m)
at System.Windows.Forms.Control.ControlNativeWindow.WndProc(Message&amp; m)
at System.Windows.Forms.NativeWindow.Callback(IntPtr hWnd, Int32 msg, IntPtr wparam, IntPtr lparam)
at System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG&amp; msg)
at System.Windows.Forms.Application.ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(IntPtr dwComponentID, Int32 reason, Int32 pvLoopData)
at System.Windows.Forms.Application.ThreadContext.RunMessageLoopInner(Int32 reason, ApplicationContext context)
at System.Windows.Forms.Application.ThreadContext.RunMessageLoop(Int32 reason, ApplicationContext context)
at System.Windows.Forms.Application.Run(Form mainForm)
at OSI.Runtime.Program.Main(String[] args)
</StackTrace>
<ExceptionString>System.ServiceModel.CommunicationException: The underlying connection was closed: A connection that was expected to be kept alive was closed by the server. ---&gt; System.Net.WebException: The underlying connection was closed: A connection that was expected to be kept alive was closed by the server. ---&gt; System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---&gt; System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.FixedSizeReader.ReadPacket(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security._SslStream.StartFrameHeader(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.StartReading(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.ProcessRead(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.TlsStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.PooledStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.Connection.SyncRead(HttpWebRequest request, Boolean userRetrievedStream, Boolean probeRead)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.GetResponse()
   at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
   --- End of inner exception stack trace ---</ExceptionString>
<InnerException>
<ExceptionType>System.Net.WebException, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089</ExceptionType>
<Message>The underlying connection was closed: A connection that was expected to be kept alive was closed by the server.</Message>
<StackTrace>
at System.Net.HttpWebRequest.GetResponse()
at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)
</StackTrace>
<ExceptionString>System.Net.WebException: The underlying connection was closed: A connection that was expected to be kept alive was closed by the server. ---&gt; System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---&gt; System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.FixedSizeReader.ReadPacket(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security._SslStream.StartFrameHeader(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.StartReading(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.ProcessRead(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.TlsStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.PooledStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.Connection.SyncRead(HttpWebRequest request, Boolean userRetrievedStream, Boolean probeRead)
   --- End of inner exception stack trace ---
   at System.Net.HttpWebRequest.GetResponse()
   at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.WaitForReply(TimeSpan timeout)</ExceptionString>
<InnerException>
<ExceptionType>System.IO.IOException, mscorlib, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089</ExceptionType>
<Message>Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host.</Message>
<StackTrace>
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
at System.Net.FixedSizeReader.ReadPacket(Byte[] buffer, Int32 offset, Int32 count)
at System.Net.Security._SslStream.StartFrameHeader(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security._SslStream.StartReading(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.Security._SslStream.ProcessRead(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
at System.Net.TlsStream.Read(Byte[] buffer, Int32 offset, Int32 size)
at System.Net.PooledStream.Read(Byte[] buffer, Int32 offset, Int32 size)
at System.Net.Connection.SyncRead(HttpWebRequest request, Boolean userRetrievedStream, Boolean probeRead)
</StackTrace>
<ExceptionString>System.IO.IOException: Unable to read data from the transport connection: An existing connection was forcibly closed by the remote host. ---&gt; System.Net.Sockets.SocketException: An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   --- End of inner exception stack trace ---
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.FixedSizeReader.ReadPacket(Byte[] buffer, Int32 offset, Int32 count)
   at System.Net.Security._SslStream.StartFrameHeader(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.StartReading(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.Security._SslStream.ProcessRead(Byte[] buffer, Int32 offset, Int32 count, AsyncProtocolRequest asyncRequest)
   at System.Net.TlsStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.PooledStream.Read(Byte[] buffer, Int32 offset, Int32 size)
   at System.Net.Connection.SyncRead(HttpWebRequest request, Boolean userRetrievedStream, Boolean probeRead)</ExceptionString>
<InnerException>
<ExceptionType>System.Net.Sockets.SocketException, System, Version=4.0.0.0, Culture=neutral, PublicKeyToken=b77a5c561934e089</ExceptionType>
<Message>An existing connection was forcibly closed by the remote host</Message>
<StackTrace>
at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)
</StackTrace>
<ExceptionString>System.Net.Sockets.SocketException (0x80004005): An existing connection was forcibly closed by the remote host
   at System.Net.Sockets.Socket.Receive(Byte[] buffer, Int32 offset, Int32 size, SocketFlags socketFlags)
   at System.Net.Sockets.NetworkStream.Read(Byte[] buffer, Int32 offset, Int32 size)</ExceptionString>
<NativeErrorCode>2746</NativeErrorCode>

This service works for other clients just fine. It's just this client that's having an issue with requests over 5 minutes. Other clients on different web servers complete the request fine.

Answer 1

The five minute limit doesn't sound like any of the default timeouts

so I took a look at the Advanced settings for app pools and looked for settings that default to 5 minutes and look possibly problematic. I found a couple you might try. You might want to take this approach:

1. In IIS Manager, go to App Pools
2. Find your app pool, right click, select Advanced Settings
3. Scan the list of settings and look for the 5 minute settings and try selectively tuning by increasing the values (strongly suggest reading and learning what each does first)

A couple of 5 minute settings that jump out at me are Limit Interval (minutes) under CPU and Failure Interval (minutes) under Rapid-Fail Protection.

Can't guarantee this will be it but unless you are manually setting a default value to 5 minutes somewhere, this is a reasonable place to start looking for a 5 minute setting. Change one setting at a time, restart the app pool, and test. Note that if you have a problem like an infinite loop in your code, obviously no timeout value is going to help :-( Good luck.