案例研究：Web應用間歇性SqlException

最近有客戶找到我，說他們生產環境的事件日志中有下面的報錯。要我幫忙找找原因。

Event Type:    Warning
Event Source:    ASP.NET 2.0.50727.0
Event Category:    Web Event 
Event ID:    1309
Description:
..
Event code: 3005  Event message: An unhandled exception has occurred.  
 Exception information:      Exception type: SqlException      Exception message: A network-related or instance-specific error occurred while establishing a connection to SQL Server. The server was not found or was not accessible. Verify that the instance name is correct and that SQL Server is configured to allow remote connections. (provider: Named Pipes Provider, error: 40 - Could not open a connection to SQL Server) 
…

這是一個典型的asp.net unhandled exception記錄。如果asp.net web應用運行的過程中出現異常，並且這個異常沒有被web應用的代碼捕捉到，asp.net運行時就會捕捉這個未處理的異常，並在應用程序事件日志中記錄類似的記錄。記錄的ID總是1309。

這次的異常消息非常明確：web應用無法連接到數據庫。從經驗來看，出現這個錯誤時，往往連最基本的TCP三次握手都沒有成功完成。也就是說TCP連接都還沒有建立起來就失敗了。 

客戶說這個問題並不總是發生，而是間歇性的會有幾個出現在事件日志里面。 

好醫生從來不掐指算。沒有數據支持的結論都是臆想。用Network Monitor工具收個網絡包吧。我們從網絡包中可以看到web前端和后端數據庫之間的網絡交互，有了它，我們就可以分析當時它們之間到底為什么不能建立連接。

一般情況下Network Monitor只能連續運行幾分鍾，否則記錄的網絡日志會非常大，拖累系統性能，並且難於分析。為了限制生成的日志文件的大小，我需要用命令行的nmcap.exe 工具，並且用/File參數來限制文件的大小。具體請參考nmcap.exe 。 

另外一個使用的工具是DebugDiag。形象的說，它作用是在SqlException發生時，給IIS進程拍個快照（memory dump）。這樣當問題發生時，所用內存中的信息都會被保存下來。這樣事后我再看當時正在執行的代碼，局部變量的值，函數的參數，連接字符串等等都不是問題。有關DebugDiag 的使用詳解，請參考How to Use the Debug Diagnostic Tool v1.1 (DebugDiag) to Debug User Mode Processes 

就這樣客戶連續運行了nmcap.exe和DebugDiag幾天，問題終於又發生了。 

用network monitor看TCP 3次握手，可以通過設置filter為tcp.Flags.Syn來過濾網絡包。同時我假設SQL連接用的是默認的1433端口，所以同時使用filter: tcp.Port==1433。結果如下:

Time Delta	Source	Destination	Description
0.0000000	Web	SQL	TCP:Flags=......S.,
2.8593750	Web	SQL	TCP:[SynReTransmit]Flags=......S.,
6.0162010	Web	SQL	TCP:[SynReTransmit]Flags=......S.,

果然握手就出了問題。所要連接的SQL服務器一直沒有響應，最后導致連接超時。 

通過使用psscor2，可以從dump中解出當時的連接字符串如下：

data source=test1;persist security info=True;initial catalog=…

數據庫的名字是test1，一看就是台測試服務器。一定是部署到生產環境后，忘了改連接字符串。但是為什么這個問題只是在處理有些請求時才發生？大多數請求還是好的？為什么出問題后，什么也不用做，后續的請求可能就自動恢復了？ 

Psscor2有個sam(save all modules)命令可以從dump中，把當時加載的所有.net assembly DLL都保存到別的目錄。然后我就可以用像ILSpy 這樣的工具來反編譯DLL中的代碼。

反編譯結果如下：

public static string getConnectionString(string name)
{
                string str = "T";
                if (!isTesting())
                {
                                str = "P";
                }
                return ConfigurationManager.ConnectionStrings[str + name].ConnectionString;
}

連接字符串是由getConnectionString ()函數返回的。這個函數根據isTesting ()的結果來返回生產或者測試環境中對應的連接字符串。繼續往下看：

public static bool isTesting()
{
                string a = HttpContext.Current.Request.Url.Host.ToLower();
                return !(a == “www.contoso-production.com”);
}

看起來，邏輯還比較簡單：如果請求的主機名不是生產環境的主機名，那就返回true。看起來挺合理，那為什么對於當時這個請求就出錯了呢？

可惜當時那個請求的URL如下：

http://www.contoso-production.com.:80/default.aspx

請注意:80前面的那個點。根據RFC http://www.ietf.org/rfc/rfc1034.txt ，這個點是合理的，但是當時的判斷邏輯不能很好的處理這種情況。 

The most common interpretation uses the root "." as either the single origin or as one of the members of the search list, so a multi-label relative name is often one where the trailing dot has been omitted to save typing.

修改代碼后，問題就不再出現了。如果你的應用里面也用到了類似的代碼，那么也請注意了。

 

Juntao