MySQL Authentication Failed的问题分析与解决对策

数据库 MySQL
在应用端,偶尔看到有如下报错:Authentication to host 'xxxx' for user 'yyyy' using method 'mysql_native_password' failed with message: Reading from the stream has 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是比较新的版本。

问题分析

我们在应用服务器端和数据库端抓包。两边抓到的包是一致的。可以排除网络包丢失问题。下面是抓到的包,以及时间点:

从上述网络包的交互来看, 前面三个包是TCP的三次握手协议。问题出在第六个包,数据库服务器向应用服务器发送了一个Finish包,来终止数据库的连接。数据库发送Finish包,是由于数据库端发现连接超时而发送的。 这是由服务器端的Connect_timeout这个变量来控制。原因在于应用端超过10秒未向数据库服务器端发送网络包。从网络包交互的情况来看,第五个包和第六个包的时间间隔刚好是10秒。

对比正常的数据库连接和上面异常的数据库连接。 应用服务器发送第5个包到数据库端后, 应该紧接着发送下面的网络包到数据库端的。这个包主要是发送账号,驱动版本,操作系统信息等到数据库服务器端。【下面是部分的正常的网络包截图】。在出现异常报错的场景,客户端是延迟发送这个包的。在Frame 8才发送的。而此时连接已经被Finish了,在Frame 9,数据库端发送了一个Reset包到应用服务器,彻底中断连接。

我们现在具体分析,为何客户端发送账号,驱动版本,操作系统信息到数据库端这么慢。这部分的代码在Connector/NET的MySQLAuthenticationPlugin.cs文件中。 我们修改这部分代码,进行时间埋点,来进一步定位问题。下面是根据时间埋点,打印出来的跟踪信息。

从跟踪的Trace来看,有30秒左右的操作延时,全部时间集中在获取Mysqldefs:: OSDetails的属性。这部分代码如下:

这段代码是通过WMI查询,来获得Caption信息。也就是操作系统的版本信息。由于是WMI调用,所以依赖的关系比较多且与操作系统的状态相关。

问题验证

为了验证是否为WMI偶发且频繁的延时导致生产环境的某些机器出现通讯异常,我们把这段代码抽出来。下面是一段简短的重现代码:

 

在有问题的应用服务器上,我们运行上述代码,确实可以发现WMI查询有超时。下面这些日志信息是我们抓到的查询超过30秒的WMI信息查询操作。由此完全确认是该操作导致MySQL authentication failed错误。

  1. 2017-11-21 17:19:30.208,       33638 
  2.  
  3. 2017-11-21 17:20:09.193,       33199 
  4.  
  5. 2017-11-21 17:20:53.086,       33201 
  6.  
  7. 2017-11-21 17:27:05.114,       32976 
  8.  
  9. 2017-11-21 17:28:19.178,       33635 
  10.  
  11. 2017-11-21 17:30:07.130,       65977 
  12.  
  13. 2017-11-21 17:30:49.051,       40478 
  14.  
  15. 2017-11-21 17:31:15.126,       26072 
  16.  
  17. 2017-11-21 17:38:16.048,       66671 
  18.  
  19. 2017-11-21 17:38:49.204,       33152 
  20.  
  21. 2017-11-21 17:39:53.161,       33828 
  22.  
  23. 2017-11-21 17:40:38.121,       33549 
  24.  
  25. 2017-11-21 17:47:09.179,       33775 
  26.  
  27. 2017-11-21 17:47:57.174,       33164 

解决思路

WMI查询慢,可能是由于多种原因所致。如操作系统CPU高,或者查询本身有死锁。这个问题有待于进一步分析。但看代码,我们知道做这个WMI查询,只是为了获得操作系统的信息。这个信息完全可以缓存起来。而不必要每次连接的时候,去进行WMI查询。

此处确定该错误的根本原因在于MySQL的C# connector中对操作系统信息的获取时间过久,导致触发服务器的连接超时。注释掉该部分可能导致长时间的操作,在问题机器上进行进一步的验证,再无任何的超时错误出现。

 

由于应用端的系统信息相对来说是静态信息,因此Connector/Net可以通过环境变量获取这些信息,绕过WMI调用查询。这样每次进行连接时,可避免出现查询超时的问题,并且能够提高Connector/Net的效率。 

责任编辑:庞桂玉 来源: DBAplus社群
相关推荐

2015-03-17 21:01:12

2023-10-18 14:14:59

数字化转型

2013-06-19 10:03:42

2010-06-30 14:15:08

SQL Server死

2009-06-16 14:08:10

JBoss JDBC驱

2024-07-29 00:01:00

RabbitMQ消息堆积

2021-03-26 10:40:16

MySQL锁等待死锁

2010-05-28 18:05:22

jsp MySQL

2012-11-28 13:37:27

.NET.NET社区

2011-06-16 11:04:09

光纤损耗

2011-08-24 17:41:16

MySQL死锁

2017-05-15 12:05:33

2021-09-07 18:23:37

数据清理对策

2010-09-01 17:30:38

2010-09-08 12:58:20

2017-06-14 22:11:57

数据库MySQL死锁

2011-07-19 12:53:37

MySQLNPTL

2010-11-25 11:15:11

MySQL查询超时

2011-03-22 16:09:33

MySQL 5.0.1乱码

2021-06-08 08:38:36

MySQL数据库死锁问题
点赞
收藏

51CTO技术栈公众号