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、 希望本能给碰到同样问题的朋友一些启发。
