關於MySQL連線丟擲Authentication Failed錯誤分析
【問題描述】
在應用端,偶爾看到有如下報錯:
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;
}
}