什么130秒超时导致我的WCF流服务调用失败?

18

最近我开始调查一个关于WCF流的棘手问题,其中如果客户端在发送消息之间等待超过130秒钟,则会产生CommunicationException异常。

以下是完整的异常信息:

System.ServiceModel.CommunicationException was unhandled by user code
  HResult=-2146233087
  Message=The socket connection was aborted. This could be caused by an error processing your message or a receive timeout being exceeded by the remote host, or an underlying network resource issue. Local socket timeout was '23:59:59.9110000'.
  Source=mscorlib
  StackTrace:
    Server stack trace: 
       at System.ServiceModel.Channels.HttpOutput.WebRequestHttpOutput.WebRequestOutputStream.Write(Byte[] buffer, Int32 offset, Int32 count)
       at System.IO.BufferedStream.Write(Byte[] array, Int32 offset, Int32 count)
       at System.Xml.XmlStreamNodeWriter.FlushBuffer()
       at System.Xml.XmlStreamNodeWriter.GetBuffer(Int32 count, Int32& offset)
       at System.Xml.XmlUTF8NodeWriter.InternalWriteBase64Text(Byte[] buffer, Int32 offset, Int32 count)
       at System.Xml.XmlBaseWriter.WriteBase64(Byte[] buffer, Int32 offset, Int32 count)
       at System.Xml.XmlDictionaryWriter.WriteValue(IStreamProvider value)
       at System.ServiceModel.Dispatcher.StreamFormatter.Serialize(XmlDictionaryWriter writer, Object[] parameters, Object returnValue)
       at System.ServiceModel.Dispatcher.OperationFormatter.OperationFormatterMessage.OperationFormatterBodyWriter.OnWriteBodyContents(XmlDictionaryWriter writer)
       at System.ServiceModel.Channels.Message.OnWriteMessage(XmlDictionaryWriter writer)
       at System.ServiceModel.Channels.TextMessageEncoderFactory.TextMessageEncoder.WriteMessage(Message message, Stream stream)
       at System.ServiceModel.Channels.HttpOutput.WriteStreamedMessage(TimeSpan timeout)
       at System.ServiceModel.Channels.HttpOutput.Send(TimeSpan timeout)
       at System.ServiceModel.Channels.HttpChannelFactory`1.HttpRequestChannel.HttpChannelRequest.SendRequest(Message message, TimeSpan timeout)
       at System.ServiceModel.Channels.RequestChannel.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)
    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 WcfService.IStreamingService.SendStream(MyStreamUpRequest request)
       at Client.Program.<Main>b__0() in c:\Users\jpierson\Documents\Visual Studio 2012\Projects\WcfStreamingTest\Client\Program.cs:line 44
       at System.Threading.Tasks.Task.Execute()
  InnerException: System.IO.IOException
       HResult=-2146232800
       Message=Unable to write data to the transport connection: An existing connection was forcibly closed by the remote host.
       Source=System
       StackTrace:
            at System.Net.Sockets.NetworkStream.MultipleWrite(BufferOffsetSize[] buffers)
            at System.Net.ConnectStream.InternalWrite(Boolean async, Byte[] buffer, Int32 offset, Int32 size, AsyncCallback callback, Object state)
            at System.Net.ConnectStream.Write(Byte[] buffer, Int32 offset, Int32 size)
            at System.ServiceModel.Channels.BytesReadPositionStream.Write(Byte[] buffer, Int32 offset, Int32 count)
            at System.ServiceModel.Channels.HttpOutput.WebRequestHttpOutput.WebRequestOutputStream.Write(Byte[] buffer, Int32 offset, Int32 count)
       InnerException: System.Net.Sockets.SocketException
            HResult=-2147467259
            Message=An existing connection was forcibly closed by the remote host
            Source=System
            ErrorCode=10054
            NativeErrorCode=10054
            StackTrace:
                 at System.Net.Sockets.Socket.MultipleSend(BufferOffsetSize[] buffers, SocketFlags socketFlags)
                 at System.Net.Sockets.NetworkStream.MultipleWrite(BufferOffsetSize[] buffers)
            InnerException: 

似乎服务器由于连接处于不活动状态而过早关闭了连接。如果我改为向服务器发送脉冲,即使是一个字节,我就永远不会遇到这个异常,并且我可以继续无限期地传输数据。我构建了一个非常简单的示例应用程序来演示这一点,它使用基本的basicHttpBinding,带有Streamed transferMode,并在客户端的自定义流实现中插入了人为延迟,延迟130秒。这模拟了类似于缓冲区不足的情况,在该情况下,从客户端调用中提供的流没有快速将数据馈送到WCF基础结构,以满足某种不可识别的超时值,该超时值似乎约为130秒左右。

使用WCF服务跟踪工具,我能够找到一条HttpException消息,其中消息读取“客户端已断开连接,因为底层请求已完成。不再有HttpContext可用。”

从IIS Express跟踪日志文件中,我看到一条条目,上面写着“IO操作已被中止,因为线程退出或应用程序请求。(0x800703e3)”

我已经配置了服务器和客户端超时,以使用远高于130秒标记的值,只是为了排除它们。我已经尝试了IIS Express中的idleTimeout和一系列与ASP.NET相关的超时值,以便发现问题来自哪里,但到目前为止还没有运气。到目前为止我能找到的最好信息是火狐问题跟踪器中开发人员的一个评论,描述了在WCF架构之外工作时遇到的类似问题。因此,我猜测问题可能更具体地与IIS7或可能是Windows Server有关。

服务器Web.config上的自定义绑定

<binding name="myHttpBindingConfiguration"
         closeTimeout="02:00:00"
         openTimeout="02:00:00"
         receiveTimeout="02:00:00"
         sendTimeout="02:00:00">
  <textMessageEncoding messageVersion="Soap11" />
  <httpTransport maxBufferSize="65536"                        
                 maxReceivedMessageSize="2147483647"
                 maxBufferPoolSize="2147483647"
                 transferMode="Streamed" />
</binding>

代码中的客户端配置:

    var binding = new BasicHttpBinding();
    binding.MaxReceivedMessageSize = _maxReceivedMessageSize;
    binding.MaxBufferSize = 65536;
    binding.ReaderQuotas.MaxStringContentLength = int.MaxValue;
    binding.ReaderQuotas.MaxArrayLength = int.MaxValue;
    binding.TransferMode = TransferMode.Streamed;
    binding.ReceiveTimeout = TimeSpan.FromDays(1);
    binding.OpenTimeout = TimeSpan.FromDays(1);
    binding.SendTimeout = TimeSpan.FromDays(1);
    binding.CloseTimeout = TimeSpan.FromDays(1);

针对wals的建议,尝试自托管服务以查看是否会得到不同的结果,并发现自托管与IIS托管相同。这意味着什么?我的猜测是问题要么在WCF中,要么在Windows底层网络基础设施中。我使用的是64位Windows 7,我们是通过在各种客户端上运行服务部分并在Windows 2008 Server上运行服务部分来发现此问题的。

更新2013-01-15

感谢DarkWanderer,我发现了一些新线索,一旦意识到WCF在Windows 7的自托管场景中使用HTTP.sys。这使我开始调查我可以为HTTP.sys配置什么以及人们报告的与我遇到的类似的HTTP.sys问题类型。这将我引导到一个日志文件,位于 C:\Windows\System32\LogFiles\HTTPERR\httperr1.log,它似乎记录了HTTP.sys的特定类型的HTTP问题。每次运行测试时,我都会在此日志中看到以下类型的日志条目。

2013-01-15 17:17:12 127.0.0.1 59111 127.0.0.1 52733 HTTP/1.1 POST /StreamingService.svc - - Timer_EntityBody -

因此,我们需要找到可能会导致 Timer_EntityBody 错误的条件,以及IIS7或其他地方的哪些设置可能会影响该错误发生的时间和条件。

官方IIS网站上得知:

请求实体主体到达之前连接已过期。当明确请求具有实体主体时,HTTP API将打开 Timer_EntityBody 计时器。最初,此计时器的限制设置为 connectionTimeout 值。每次在此请求上收到另一个数据指示时, HTTP API 将计时器重置为给予连接更多分钟,如 connectionTimeout 属性中所指定的那样。

尝试修改连接超时属性,就像上面引用的那样,对于IIS Express的 applicationhost.config 文件似乎没有任何影响。也许IIS Express忽略此配置并在内部使用硬编码值?我尝试了自己的方法,发现 netsh http 命令添加了显示和添加超时值的新命令,因此我尝试了以下命令,但很遗憾,这样做似乎对此错误没有任何影响。

netsh http add timeout timeouttype=IdleConnectionTimeout value=300


我们需要您的app.config文件(两个方面)。 - wal
@wal - 目前配置文件并不重要。我正在一个简单的测试应用程序中复现这个问题,但为了满足请求,我会更新我的帖子。 - jpierson
接收超时是2分钟还是2小时? :) - wal
2:00:00 是2小时,增加它也没有任何差异。 - jpierson
1
可以试着在客户端和服务器端删除绑定的分配值,看看是否有任何差异(可能无法解决问题,但可以缩小范围)。此外,您可以将WCF服务运行在隔离环境中(自己的进程),以排除一些可能性。 - wal
显示剩余3条评论
5个回答

16
这个问题实际上是由HTTP.sys使用的连接超时值引起的,可以通过IIS管理器中单个站点的高级设置指定。默认情况下,当头部和正文都未在120秒内接收到时,该值被配置为超时连接。如果从正文接收到数据脉冲,则服务器会重新启动一个计时器(Timer_EntityBody)以在超时值内等待其他数据。请注意,保留HTML标签。

Connection Time-out setting in IIS

这与Timer_EntityBodyconnectionTimeout相关的文档一样,但很难确定,因为似乎IIS Express忽略了在applicationhost.config中指定的限制元素中的connectionTimeout值,无论文档如何说明。为了确定这一点,我不得不在开发机器上安装完整版的IIS,并在托管我的站点后修改上述设置。

由于我们将真实服务托管在Windows 2008上的IIS下,上述解决方案对我有效,但仍然存在一个问题,即在自托管情况下如何正确修改连接超时值。


是的,我起初尝试了140,然后测试了133和160的延迟,只是为了确保它能够通过前者并失败于后者,而它确实做到了。我还进行了400秒和600秒的进一步测试,以确认该设置确实影响了这种行为。 - jpierson
有人知道微软是否打算修复IIS Express,以遵守applicationhost.config中限制的connectionTimeout值吗? - petrsnd
@jpierson,你有没有想过如何增加自托管服务的空闲超时时间? - petrsnd
我在我的情况下没有进行自助托管,所以我没有遇到过这个问题。但是,如果我们需要自助托管并遇到类似的问题,我会非常欢迎任何关于这个问题的见解。 - jpierson

2

从错误信息来看:

套接字连接被中止。这可能是由于处理您的消息或远程主机超时接收,或底层网络资源问题引起的。本地套接字超时为“23:59:59.9110000”

看起来像是一个简单的TCP超时。

您可以通过将应用程序作为自托管运行,然后在控制台中运行此命令来验证它:

netstat -no |find "xxxxx"

这里的xxxxx是你的服务器进程的PID。此命令将显示您的服务器已建立的连接并每秒刷新一次。

尝试使用客户端连接并观察发生了什么。很可能在约100-120秒后,您的连接将显示“CLOSE_WAIT”或“TIME_WAIT”,这意味着由于超时而被中止。

通过将以下内容添加到配置文件中,可以解决此问题:

<httpTransport maxBufferSize="65536"                        
             maxReceivedMessageSize="2147483647"
             maxBufferPoolSize="2147483647"
             transferMode="Streamed"
             keepAliveEnabled="true" /> <!-- Here -->

该参数在此处有详细解释。


此时我也假设问题可能与底层超时有关,例如基础套接字中的超时。但此时还不确定超时值是服务器端还是客户端端。另外,keepAliveEnabled 值似乎没有任何效果。 - jpierson
仍在努力理解netstat的输出,因为它显示了一个意外的PID作为拥有测试中打开端口的进程。它显示PID 4,这与“System”ntoskrnl.exe相关联,而不是我的自托管命令行应用程序。 - jpierson
无论PID调查显示什么结果,结果都将是相同的...我猜,由于流式套接字的性质,keepAliveEnabled="true"在transferMode="Streamed"下没有效果。如果您确认上述原因,请按照您在问题中描述的方式解决自己的“保持活动状态”。 - DarkWanderer
结果显示PID 4是内核。据我所知,这是Vista和更高版本上自托管的正常方式,因为所有内容都在HTTP.sys下面托管。我尝试通过运行“netsh http add timeout timeouttype=IdleConnectionTimeout value=300”来更改HTTP.sys模块的idleConnectionTimeout值,但似乎没有任何区别。 - jpierson

1

可能有点冒险,但是...请检查您的IIS应用程序池是否启用了Ping。它在高级设置中,进程模型分组中。


我研究了一下,不幸的是,我现在正在IIS Express上重现这个问题,并且在applicationhost.config中设置pingFrequency值只会导致IIS Express在启动时崩溃。在我看来,可能是因为IIS Express没有与完整版IIS相同的进程模型或进程模型配置?也许这也表明,无论我是在IIS7还是IIS Express中运行服务,我都能够重现这个问题,因此这不是问题的根源? - jpierson
<processModel>元素的文档可能已经过时了。我尝试使用了pingingEnabled、pingInterval和pingResponseTime属性,但不幸的是,我还没有找到可行的组合。 - jpierson
2
嗯,可能无关。我想设置piningEnabled为false或增加pingResponseTime会有帮助。 - YuryP
在思考同样的方向时,这些是你提醒我后我尝试的第一件事情。感谢你的建议。 - jpierson

0
尝试这个,这对我解决了问题。问题在于底层内核http.sys有自己的超时,它会断开连接。
http://mmmreddy.wordpress.com/2013/07/11/wcf-use-of-http-transport-sharing-persistent-tcp-sessions/

netsh http add timeout timeouttype=idleconnectiontimeout value=120

1
请看我的问题结束附近,我实际上尝试了这个设置,但在我的情况下并没有成功。 - jpierson

0

你考虑过http://support.microsoft.com/kb/946086吗?

我在我的ISAPI扩展中观察到了这样的流中断。按照这个支持说明,在IIS 7中关闭缓冲后,一切都正常工作。


不,我之前没有看到过这篇 KB 文章,但在我看来它似乎与我的问题没有太大关系。我遇到的问题非常明确,是超时问题,而不是缓冲区达到容量限制的问题。我肯定是因为采纳了改变 IIS 中的超时设置的答案才解决了这个问题。 - jpierson

网页内容由stack overflow 提供, 点击上面的
可以查看英文原文,
原文链接