WCF之诡异通讯超时

一、诡异现象

1、 在对一个项目的现场实施调试中,应用软件系统在获取服务端数据时报“操作失败”,经日志反馈为:WCF通讯超时!

2、 经过反复测试发现:并不是所有操作都会失败,像登录、增、删、改、查等简单操作能正常运行,只是在获取某种数据量比较大的数据时会出现操作失败的情况。

3、现场环境为:Dell R710(服务器)+Dell商用机(客户端)+光纤网.

4、我们的系统是C/S和B/S统一的行业应用软件,采用WCF进行分布式通讯,并提供统一的应用服务。

二、问题分析

1、  电话对现场进行指导,把超时时间设置为10分钟后照样有问题。

这让我很纳闷,就算是压力测试我们也要求即使是大数据也要在2分钟这内返回,何况是10分钟!

系统日志信息为:

请求通道在等待 00:10:00 以后答复时超时。增加传递给请求调用的超时值,或者增加绑定上的 SendTimeout 值。分配给此操作的时间可能是更长超时的一部分。

 

Server stack trace:

   在 System.ServiceModel.Channels.RequestChannel.Request(Message message, TimeSpan timeout)

   在 System.ServiceModel.Dispatcher.RequestChannelBinder.Request(Message message, TimeSpan timeout)

   在 System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs, TimeSpan timeout)

   在 System.ServiceModel.Channels.ServiceChannel.Call(String action, Boolean oneway, ProxyOperationRuntime operation, Object[] ins, Object[] outs)

   在 System.ServiceModel.Channels.ServiceChannelProxy.InvokeService(IMethodCallMessage methodCall, ProxyOperationRuntime operation)

   在 System.ServiceModel.Channels.ServiceChannelProxy.Invoke(IMessage message)

 

Exception rethrown at [0]:

   在 System.Runtime.Remoting.Proxies.RealProxy.HandleReturnMessage(IMessage reqMsg, IMessage retMsg)

   在 System.Runtime.Remoting.Proxies.RealProxy.PrivateInvoke(MessageData& msgData, Int32 type)

   在 ……

2、  同样的数据、同样的程序,在调试人员的笔记本上进行单机操作进能正常运行。

怀疑是不是光网运行不稳定?但经过测试网络运行稳定,光网速度应该也有保障,由此初步排除此想法。

3、  当我们无意中使用在服务器上的客户端,访问调试人员自带的笔记本上的服务时一切工作正常,时间在2秒之内!也就是说客户端和服务器端互换后即能工作正常。

难道服务器处理能力还不如一笔记本?这是什么道理!莫非是操作系统出问题了?这个结论可不敢乱下,必竟在此服务器上还运行了公司的其它产品,人家一点问题都没有(虽说他们都没有较大数据的传输)!

4、没有办法,也只能让实施人员偷偷的重装一下系统试试,死马当活马医了。结果重装后一切工作正常,医好了,返回时间在2秒以内!

10分钟又做何解呢?

三、现场模拟

问题虽然可以解决了,但是却给不了定论,也出不了报告!所以必须亲自搭建环境,找找原凶。

1、从库房借出同一型号的机器。

2、从相关部门找到操作系统原盘(注:我们一般用的都是5元版的,我认错!正版的只买了少数几个),并在服务器上安装。

3、光网未能搭建。

4、安装应用软件,还原数据。

结论:

问题重现!

四、不解

1、小数据的服务可以正常,一些增、删、改等大部分操作都能正常工作,说明WCF服务工作正常。

2、只在当超过某一级别的数据级的操作会失败。

我对WCF的配置文件进行更改,使期支持超大数据传输及10分钟的超时限制。

 <binding name="WSHttpBinding_Default" closeTimeout="00:01:00"

        openTimeout="00:01:00" receiveTimeout="00:10:00" sendTimeout="00:10:00"

        bypassProxyOnLocal="false" transactionFlow="false" hostNameComparisonMode="StrongWildcard"

        maxBufferPoolSize="2147483647" maxReceivedMessageSize="2147483647"

        messageEncoding="Text" textEncoding="utf-8" useDefaultWebProxy="true"

        allowCookies="false">

      <readerQuotas maxDepth="32" maxStringContentLength="2147483647" maxArrayLength="2147483647"

          maxBytesPerRead="2147483647" maxNameTableCharCount="2147483647" />

但最终还是失败!(图)

3、经过对详细的工作日志分析发现“服务已调用且成功返回”。也就是说问题出在了应用程序可控制的范围之处的WCF模块!(但有与1的观点相左)

五、抓包分析

没办法了,只能抓包

1、分析工具:

Wireshark 网络封包分析软件。

2、小数据请求分析:

①:正常情况下报文

请求方:192.100.0.14

服务方:192.100.0.13

结论:

应答一致,通讯通畅。

②:Dell R710出厂环境下的报文情况

请求方:192.100.0.14

服务方:192.100.0.13

结论:

请求方数据(含发送的和接收的)正常,但服务方未捕获任何请求方的TCP数,但最终数据转发成功所采用的方式不明。

3、大数据请求:

 ①:正常报文与小数据请求类似,应答一致,通讯通畅。

 ②:Dell R710出厂环境下的报文情况(Win7客户端)

请求方:192.100.0.14

服务方:192.100.0.13

结论:

请求方与服务方协调不一致,服务方频繁广播ARP信息“who has 192.100.1.15? Tell 192.100.0.14”直得怀疑。据Wireshark说明:“who has 192.100.1.15?Tell 192.100.0.14…”表示:主机192.100.15想发送数据给192.100.0.14,但它不知到192.100.0.14的MAC地址,从而向ARP询问。而本次通讯本质是发生在“192.100.1.13”和“192.100.1.14”之间,所以直接造成通讯无法正常进行。

 ③:Dell R710出厂环境的报文情况(WinXP客户端)

请求方:192.100.0.212

服务方:192.100.0.30

(服务方抓包迟缓,不能正确反映通讯情况)

结论:

请求方与服务方协调不一致,服务方发送的数据并不是正常的[ACK]报文,而是 [TCP segment of a reassembled PDU],而后请求方也会多次发送[TCP segment of a reassembled PDU]。查阅资料说明,该信息是指TCP层收到上层大块报文后分解成段后发出去。于是有个疑问,正常情况下TCP层可以把大段报文丢给IP层,让IP层完成分段,这就是一般我们能看到[ACK]报文,但现在TCP层分了段,抓包分析不了,也明显造成了通讯双方无法正常识别对方的信息。

六、清空ARP列表

怀疑:ARP攻击

arp –d

该环境下可能存在ARP异常,于是在大数据包通讯进行时,由命令窗口中输入“arp -d”清空当前arp列表,立即数据传输正常进行,但稍后的数据传输会再次受到影响,不能根本解除问题。

七、开启ARP保护,正常!

1、用杀毒软件进行全盘扫描,并未报出病毒和木马。也只能使第三方工具来进行防护。我这里使用了一款免费的工具(360)。

2、我只是个菜鸟对病毒和木马不了解。有兴趣的朋友可就此分析一下WCF的通讯细节,但目前已基本证实问题主要是服务主机受到了ARP攻击知成了通讯的异常。

3、 希望本能给碰到同样问题的朋友一些启发。

原文地址:https://www.cnblogs.com/showjan/p/2726040.html