【問題描述】
在應用端，偶爾看到有如下報錯：
Authentication to host 'xxxx' for user 'yyyy' using method 'mysql_native_password' failed with message: Reading from the stream has failed. 表現特征：
1.只有用Connector/NET 出現這個問題， 用JDBC驅動沒有類似問題。
2.多台應用服務器，只有一台報這個錯，因此可以排除服務器端的問題。
3.問題非常隨機，重啟一下服務器/IIS，就能臨時解決問題。
4.有一些場景應用服務器CPU並不是很高，也會偶爾拋出這個錯來。
客戶端是Windows機器， 驅動是MySQL Connector ADO.NET Driver for MySQL (Connector/NET) ，使用的版本是6.9.9，是比較新的版本。
【問題分析】
我們在應用服務器端和數據庫端抓包。兩邊抓到的包是一致的。可以排除網絡問題。下面是抓到的包，以及時間點：
| 編號 | 絕對時間 | 相對時間(秒) | 源頭 | 目的 | 網絡包內容 |
|---|---|---|---|---|---|
| 1 | 12:58:47 | 9.07 | 應用服務器 | 數據庫服務器 | ......S. |
| 2 | 12:58:47 | 9.07 | 數據庫服務器 | 應用服務器 | …A..S. |
| 3 | 12:58:47 | 9:07 | 應用服務器 | 數據庫服務器 | …A…. |
| 4 | 12:58:47 | 9:07 | 數據庫服務器 | 應用服務器 | …AP… |
| 5 | 12:58:47 | 9.27 | 應用服務器 | 數據庫服務器 | …A…. |
| 6 | 12:58:57 | 19.12 | 數據庫服務器 | 應用服務器 | …A…F |
| 7 | 12:58:57 | 19.12 | 應用服務器 | 數據庫服務器 | …A…. |
| 8 | 12:59:10 | 32.00 | 應用服務器 | 數據庫服務器 | …AP… |
| 9 | 12:59:10 | 32.00 | 數據庫服務器 | 應用服務器 | …..R.. |
從上述網絡包的交互來看， 前面三個包是TCP的三次握手協議。問題出在第六個包，數據庫服務器向應用服務器發送了一個Finish包，來終止數據庫的連接。數據庫發送Finish包，是由於數據庫端發現連接超時而發送的。 這是由服務器端的Connect_timeout這個變量來控制。原因在於應用端超過10秒未向數據庫服務器端發送網絡包。從網絡包交互的情況來看，第五個包和第六個包的時間間隔剛好是10秒。
對比正常的數據庫連接和上面異常的數據庫連接。 應用服務器發送第5個包到數據庫端后， 應該緊接着發送下面的網絡包到數據庫端的。這個包主要是發送賬號，驅動版本，操作系統信息等到數據庫服務器端。【下面是部分的正常的網絡包截圖】。在出現異常報錯的場景，客戶端是延遲發送這個包的。在Frame 8才發送的。而此時連接已經被Finish了，在Frame 9，數據庫端發送了一個Reset包到應用服務器，徹底中斷連接。
我們現在具體分析，為何客戶端發送賬號，驅動版本，操作系統信息到數據庫端這么慢。這部分的代碼在Connector/NET MySQLAuthenticationPlugin.cs文件中。 我們修改這部分代碼，進行時間埋點，來進一步定位問題。下面是根據時間埋點，打印出來的跟蹤信息。
從跟蹤的Trace來看，有30秒左右的操作延時。返回MySQLDefs::OSDetails的時候。這部分代碼如下：
[DisplayName("_os_details")]
public string OSDetails
{
get
{
string os = string.Empty;
try
{
var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
var collection = searcher.Get();
foreach (var mgtObj in collection)
{
os = mgtObj.GetPropertyValue("Caption").ToString();
break;
}
}
catch (Exception ex) { System.Diagnostics.Debug.WriteLine(ex.ToString()); }
return os;
}
}
這段代碼是通過WMI查詢，來獲得Caption信息。也就是操作系統的版本信息。由於是WMI調用，所以依賴的關系比較多。
【問題驗證】
我們把這段代碼抽出來。下面是一段簡短的Repro代碼：
static void Main(string[] args)
{
Stopwatch watch = new Stopwatch();
while (true)
{
watch.Restart();
var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
var collection = searcher.Get();
foreach (var mgtObj in collection)
{
string os = mgtObj.GetPropertyValue("Caption").ToString();
}
watch.Stop();
Console.WriteLine(watch.ElapsedMilliseconds);
if (watch.ElapsedMilliseconds >= 1000)
{
Console.WriteLine("-------------");
File.AppendAllText("abc.txt", DateTime.Now.ToString("yyyy-MM-dd HH:mm:ss.fff") +","+ watch.ElapsedMilliseconds + "\r\n");
}
}
}在有問題的應用服務器上，我們運行上述代碼，確實可以發現WMI查詢有超時：下面這些點是我們抓到的超過30秒的點：
2017-11-21 17:19:30.208， 33638
2017-11-21 17:20:09.193， 33199
2017-11-21 17:20:53.086， 33201
2017-11-21 17:27:05.114， 32976
2017-11-21 17:28:19.178， 33635
2017-11-21 17:30:07.130， 65977
2017-11-21 17:30:49.051， 40478
2017-11-21 17:31:15.126， 26072
2017-11-21 17:38:16.048， 66671
2017-11-21 17:38:49.204， 33152
2017-11-21 17:39:53.161， 33828
2017-11-21 17:40:38.121， 33549
2017-11-21 17:47:09.179， 33775
2017-11-21 17:47:57.174， 33164
【解決思路】
WMI查詢慢，可能是由於多種原因所致。如操作系統CPU高，或者查詢本身有死鎖。這個問題有待於進一步分析。但看代碼，我們知道做這個WMI查詢，只是為了獲得操作系統的信息。這個信息完全可以緩存起來。而不必要每次連接的時候，去進行WMI查詢。
此處確定該錯誤的根本原因在於MySQL的C# connector中對操作系統信息的獲取時間過久，導致觸發服務器的連接超時。注釋掉該部分（可能導致長時間的操作），進行進一步的驗證，再無任何的超時錯誤出現。
public string OSDetails
{
get
{
dbglog.dolog("MysqlDefs::OSDetails1");
string os = string.Empty;
/*try
{
var searcher = new System.Management.ManagementObjectSearcher("SELECT * FROM Win32_OperatingSystem");
var collection = searcher.Get();
foreach (var mgtObj in collection)
{
os = mgtObj.GetPropertyValue("Caption").ToString();
dbglog.dolog(String.Format("MysqlDefs::OSDetails::foreach{0}", os.ToString()));
break;
}
}
catch (Exception ex) { System.Diagnostics.Debug.WriteLine(ex.ToString()); }*/
dbglog.dolog("MysqlDefs::OSDetails2");
return os;
}
}