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