關於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;
    }
}