关于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;
    }
}