一、詭異現象
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、 希望本能給碰到同樣問題的朋友一些啟發。