小言_互联网的博客

遇到一个特别“恶心”的问题,排查大半天

468人阅读  评论(0)

最近遇到一个特别恶心的问题,就是数据库里面的时间和实际时间差了 13 小时。

最后的解决方案很简单,就是问 DBA 咋回事,然后他扔给我一个配置,叫我改一下就完事了。

确实改完之后就好了,我也知道是时区的问题导致的了。

但是...

我想知道更细节的原因,细节到具体是哪一个环节、哪一步源码。

在探究的过程中,发现一个朋友也遇到了这个问题并整理成文,写的很细节,也解答了我的疑问,所以分享给大家看看。

相互学习,共同进步。

背景

我负责的一个后台服务,负责接收客户端请求,同时写库。比如,创建一个任务,在代码里创建时间是直接 new Date,然后写入数据库。然后,我用我的客户端软件去看那个创建时间的时候,是差了 13 个小时的。

当然了,客户端软件看着差了 13 个小时,但是我 web 界面上查看,是没啥问题的。

比如,我现在时间是 21:02 分,我在界面上创建了一个任务,然后我用的 MySQL 客户端 sqlyog 去查看任务的创建时间:


  
  1. Ftask_id Fcreate_time
  2. -------- ---------------------
  3. 4121 2021-06-19 08:02:36

咦,怎么是8点呢,和现在比,差了21 - 8 = 13个小时。

这个时区问题,一般还是和 MySQL 的一些 variable 相关的,比如,我们这么查了一下,

SHOW VARIABLES LIKE '%zone%'

结果如下:


  
  1. Variable_name Value
  2. ---------------- --------
  3. system_time_zone CST
  4. time_zone SYSTEM

这个 cst、system,虽然不懂,但感觉就是有点问题,这时候去某度某歌查一下,基本改改就解决了。

但是,这个 MySQL 实例上,不止我们一个数据库,上面有几十个库,我这也不敢直接改数据库配置,万一有人专门这么配置的呢?

然后我问了下同事,他在这个实例上也有一个其他的数据库,但是比较奇怪的是,他在程序里 new Date,写进来的时间,是对的。

大家都是一个组的,都是同样的 MyBatis 框架,不至于你可以,我不可以。

我决定,找找原因。

当然了,这么明显的 bug,之前没发现?那倒不是,因为我 web 界面上查出来,是对的。

虽然只是有点恶心人(MySQL 客户端看到的时间差了 13 小时,web 前端没问题),但还是不能继续忍了。

到底是谁错了?

是 MySQL server 错了还是 sqlyog 客户端错了呢?

sqlyog 在本机,MySQL server 在远端,我们可以 wireshark 抓包,看看 MySQL 返回的,是不是对的。

wireshark 上,选择正确的网卡,捕获表达式设为:tcp port 3306,开抓,然后跑去 sqlyog 上执行 select 语句。

SELECT Ftask_id,Fcreate_time FROM t_task ORDER BY Fcreate_time DESC  LIMIT 1;

然后,回到我们的 wireshark,抓到了很多包:

然后随便找一个右键-跟踪流-tcp 流,就会把对应的这个 tcp 连接上的包全部以 ascii 显示出来。

正常来说,一般 MySQL 的报文,都是明文的,可以直接看到 sql 语句,和返回的结果啥的。

但是,我本机这个 sqlyog,不知道是不是版本很高的原因,少量语句可以明文显示,其他的就不是明文。

不过吧,咱们暂时没时间和这个客户端耗着,我直接去应用所在的服务端上抓包吧,看看 MySQL server 返回的,是什么样的。

上图那个 tcpdump 语句,就是抓 3306 端口的包,不管 3306 是 src 端口,还是 dst 端口。

然后相关的包,写入到 3306.pcap 里面,然后我们 sz 传到 windows 上,用 wireshark 来分析。

大家注意看上图,MySQL 返回的就有问题,先把锅甩给 MySQL。

但是,MySQL 只是个存储,既然存的数据有问题,那是不是说明,可能我们写的有问题呢?

MySQL server:谁来领锅

站在 MySQL server 的角度来说就是:谁写了个错误的时间给我,来领锅。

但是很尴尬啊,这个时间,是我们的服务端写进去的,这样的话,我们只能继续像上图那样抓包了:

看吧,果然写入有问题,说明程序有问题,我们顺便看看 MyBatis logger 记录的 sql 日志。

但是,MyBatis 日志里,记录的时间是对的,就是晚上 9 点。

好,有点乱了,我们理一下。

首先我们程序里 new date,MyBatis 写入,记录的日志是晚上 9 点,没问题。

但是,最终发给 MySQL server 的包,是晚 13 小时的。

说明啥?

可能 MySQL 建立的连接有点问题。我这时候去看了下本地代码的配置文件。


  
  1. commondb:
  2. database:
  3. url: jdbc:mysql://xxxxxx:3306/xxxx?characterEncoding=utf8&zeroDateTimeBehavior=convertToNull&useTimezone= true&serverTimezone=GMT%2B8

大家看这个配置:

useTimezone=true&serverTimezone=GMT%2B8

一看就有点不对,什么时区,什么 GMT。

我本来以为就这个问题了,但是,我们这边,程序和配置是分开打包、分开部署的,大家可以理解为:配置中心。

我去看了下线上配置,结果好像没问题,即:


  
  1. commondb:
  2. database:
  3. url: jdbc:mysql://xxxxxx:3306/xxxx?characterEncoding=utf8&zeroDateTimeBehavior=convertToNull

本来就没有带后面那个时区的东西。

我很怀疑,现在线上那个运行的 java 程序,到底 commondb.database.url 有没有问题,我想了好几个办法:

  • 1、因为是 Spring Boot 的,所以一开始用 http://xx.xx.xx.xx:8080/actuator/env 之类的端口,去查看了一下,发现访问不通。后来发现,咱们的程序,没引入 Spring Boot 的 actuator 的 jar 包,作罢。

  • 2、本地使用 jconsole、jvisualvm 去连接这个运行着的 java 程序。

这个怎么玩呢,首先,这个运行着的程序,需要是开了这几个 jvm 参数:


  
  1. -Dcom.sun.management.jmxremote
  2. -Dcom.sun.management.jmxremote.port=9999
  3. -Dcom.sun.management.jmxremote.authenticate=false
  4. -Dcom.sun.management.jmxremote.ssl=false

然后,就可以去连接它了,用 jconsole/jvisualvm 都行。

当然,这个比较随机,有时可以连上,有时不行,我这次就不行,我还在本机 wireshark 抓了 jconsole 去连接这个远程 java 程序的包。

抓包的过滤语句:tcp port 9999。

抓到的包,是以 tcp 协议展示的,其实我们知道应用层的通信协议的话,可以手动右键 --decode as-- 然后选择 rmi,

没错,java 自带的那个 rmi,就可以看到多一些信息。

当然了,虽然多了些信息,我还是没明白为啥 jconsole 没连上。放弃。

jconsole 不行,最终我还是只能试试 arthas 了,阿里的那个,连上去那个 java 程序后,只能看看环境变量、System Property 之类的,好像对我们要看的东西,于事无补。

还记得吗,我们想看的是,commondb.database.url 的值,思考了一会,最终只能暴力解决了,这个属性,好像被注入到一个 bean 里去了,他就是 Datasource,但是想看到这个 bean 的值,没那么简单:


  
  1. @Bean(name = DATA_SOURCE)
  2. @ConfigurationProperties(prefix = DB_CONFIG_PREFIX)
  3. @Primary
  4. public DataSource omsDbDatabase () {
  5. DataSource build = DataSourceBuilder.create().build();
  6. return build;
  7. }

所以,最终只能 jmap,把堆内存 dump 下来了,然后使用 eclipse memoryAnalyzer 来分析。

oql,大家不了解的,可以了解下,反正就是根据 class 来搜索内存中的对象。

问题在哪里

配置没问题,那,问题在哪里

我这时候才想起来,既然服务器上这个 java 程序,配置没问题,也会出这个时区问题。

那我本地,是不是也会有这个问题(按理说,我早该这么想,但是就是后知后觉),然后本地试了下,和服务器上表现一样,这时候,其实就可以慢慢debug了。

但是,我还是很奇怪,同事那个程序,为啥发送给 MySQL server 的时间没问题,我这个就有问题,我于是,对比了一下双方的 mysql-connector-java 这个依赖,发现,咦,版本不一样啊。


  
  1. <dependency>
  2. <groupId>mysql </groupId>
  3. <artifactId>mysql-connector-java </artifactId>
  4. <version>8.0.16 </version>
  5. </dependency>

同事用的是 5.1.41,我这边怎么这么高,8.0。

于是,我试着改成了 5.1.41,这把,果然发给 MySQL server 的时间,就是对的了。

关于 mysql-connector-java

现在主流的版本,有两个,5.1.x 系列和 8.0.x 系列,5.1.x 系列最新的一个版本是5.1.49.

大家看下图,有红色字样的 "1 vulnerability",表示有漏洞,这也是为什么我们同事为啥要升级或者是被安全组逼着升级到 8.0.x 版本的原因。

8.0.x 的最新版本是 8.0.28,可以看到,没有漏洞字样:

这两个版本之间的差异有下面几处。

第一处,先给一份官方的:

其实可以看出来,5.1 和 8.0 的兼容性都不错,都支持 MySQL server 端:5.6/5.7/8/0,差异无非是对 jre 和 jdk 的版本不一样。

这里多说一句,mysql-connector-java 是 jdbc 规范的一个实现,jdbc 规范相关接口(java.sql和javax.sql里的就是,比如java.sql.Driver),跟随 jdk 一起发布。

可参考:

https://docs.oracle.com/en/java/javase/11/docs/api/java.sql/java/sql/package-summary.html

第二处,是 connection property 发生了变化,什么是 connection property,举例:

jdbc:mysql://1.1.1.1:3306/test?useSSL=false&serverTimezone=Asia/Shanghai

上面的 useSSL、serverTimezone 就是 connection property。

具体变化:

https://dev.mysql.com/doc/connector-j/8.0/en/connector-j-properties-changed.html

第三处,就是 MySQL driver 的类名也发生了变化.

5.1.x版本是叫 "com.mysql.jdbc.Driver"。

8.0.x里面是 "com.mysql.cj.jdbc.Driver",而且,8.0版本不需要我们自己再去写这种代码:


  
  1. // 注册 JDBC 驱动
  2. String JDBC_DRIVER = "com.mysql.jdbc.Driver";
  3. Class.forName(JDBC_DRIVER);

当然了,8.0 版本对 5.1 版本做了兼容,你即使加载 5.1 的 driver,也没影响。

另外还有些大家不用感知的,比如一些接口的包名发生变化,一些异常类被删除了,因为我们一般不会直接用 mysql-connector-java 去编程,我们都是用 jdbc 接口嘛,实现类再怎么变,也没什么影响。

https://dev.mysql.com/doc/connector-j/8.0/en/connector-j-exceptions-changes.html

探寻源码

现在我们定位到是版本的问题了,那么就基于这个版本进行调试就行。

首先我们要判断出来的一个事情是:

错误的时间,是客户端发送前就错了,还是服务端错了?

问一下自己这个问题,主要是界定问题发生的地方。

这个也容易界定,最理想的方式就是网络抓包,wireshark或者tcpdump自己选吧。

这里先看下我的测试程序要做的事:

数据库有下面这一条记录,我要做的,就是根据时间参数,把记录查出来。

程序如下:

我如果实际执行这个 demo,是查不出结果的,为啥呢,我网络抓包的截图给大家看看:

至于这个错误的时间,是怎么来的,就确实需要慢慢去 debug 了。

看看我们前面的代码,设置时间参数主要是下面这一行:


  
  1. Timestamp timestamp = new Timestamp(simpleDateFormat.parse("2022-02-17 22:49:27").getTime());
  2. preparedStatement.setTimestamp( 1, timestamp);

那我们直接一点,就在这行打上断点,开始调试:

这里看得出来,是给 this.query 这个对象,设置相关的绑定参数。

我们继续跟进:

此时,时间依然还是正确的。

我们传了 4 个参数到 setTimestamp 方法,注意,第三个参数 targetCalendar 为 null,这个参数会影响内部的分支。

看上图,这里因为 targetCalendar 为 null,所以会去获取当前这个  MySQL 会话中的时区字段。

这个时区是啥呢,就是 CST。

也就是说,2022-02-17 22:49:27 这个时间,在CST时区下,就是 2022-02-17 08:49:27。

这里 CST 说是有好几个时区都是这个缩写,比如:

  • Central Standard Time, North America's Central Time Zone: UTC−06:00,这个时间基本就是北美中部时间,北美中部包括了:美国、加拿大、墨西哥的中部地区

  • China Standard Time: UTC+08:00,这个就是中国的北京时间了,但感觉CST一般还是指:北美中部时间

  • Cuba Standard Time: UTC−04:00,这个其实点链接,会跳转进入美洲东部时间的wiki,因为古巴也是在北美东部位置,包括了:美国、加拿大、墨西哥东南、巴拿马、哥伦比亚、厄瓜多尔、秘鲁等(这里也有中美洲的一些地区)

可能国际上来说,看到CST,首先是任务是美国中部时区 Central Standard Time(USA)UTC-06:00。

一般不是是另外两个时区,中国那肯定就是 Asia/Shanghai。

这个时区,是零时区 - 6(美国冬令时,从 11 月 7 日到 3 月 11 日)或者是零时区 - 5(夏令时,从“ 3 月 11 日”至“ 11 月 7 日”),因为现在是美国的冬令时,所以这里差 14 小时(我们是东八区嘛,8 + 6)。

ok,言归正传,反正问题就是出现在: 会话的时区不对 。

那么为啥是 CST 啊,能不能改?

CST 怎么来的?

那么会话中的时区变量,怎么是 CST,什么时候设置的呢?

第一次设置

第一次设置(初始化)的代码是这样的:

targetCalendar != null ? null : this.session.getServerSession().getDefaultTimeZone()

这里面其实是获取了:


  
  1. com.mysql.cj.protocol.a.NativeServerSession #getDefaultTimeZone
  2. private TimeZone defaultTimeZone = TimeZone.getDefault();
  3. public TimeZone getDefaultTimeZone() {
  4. return this.defaultTimeZone;
  5. }

我们可以在这个字段上打个断点,看看这个值什么时候被设置:

然后重新 debug 整个程序,看看什么时候进入该 field 断点。我们会发现,第一次进入,就是在 new 这个类的对象时,

可以看看这个堆栈,基本就是获取 connection 的时候,相当于就是建立一个会话,所以这里会去 new 一个会话出来。

我看了下,在我机器上,初始化后,是东八区。

在第一次设置和第二次设置之间

这之间发生了一次重要的网络请求,

客户端向服务端请求各种服务端的 variable,也就是服务端的配置。

上面有两个时区相关的,system_time_zone 和 time_zone。

第二次设置

接下来,运行到了 com.mysql.cj.protocol.a.NativeProtocol#configureTimezone ,开始了第二次设置。

这个方法比较长,我分两三段来截图。

上图比较清楚:

首先获取服务端的"time_zone"配置,如果“time_zone”为“system”,则获取“system_time_zone”的配置

我这边数据库吧,反正默认装好就是这样的,正好就是 CST 和 system,也没动过,所以这也是为啥国内大家很多人遇到这个问题的原因。

接着获取客户端自身建立连接时候的配置,通俗来说,就是 dbUrl 里面那些 connection property。

最后如果客户端没配,则以服务端的为准。

再接下来,就是以 CST 来设置成本次会话的默认时区。

下面最后一行红框的,也就是这第二次设置:

至此,我们已经知道这个 CST 是怎么来的了。

解决问题

通过上面,我们知道了,如果客户端没设置时区,就会用服务端的。所以,两种改法:

  • 把服务端配置的 system_time_zone 和 time_zone 改成正确的,网上也有些教程,就是这样。但是我们这边,数据库很多业务在用,这么改,怕影响到别人

  • 客户端连接url中,指定时区。

第二种,也就是这样指定 serverTimezone:

jdbc:mysql://1.1.1.1:3306/test_ckl?useSSL=false&serverTimezone=Asia/Shanghai

我们改了客户端,再看看。

程序就没毛病了,问题得到解决。

扩展信息

这个整个交互中,一共有如下几次网络请求。

  • tcp 三次握手

  • 登录请求,带着用户名、密码去登录

  • 接下来,就是那次查询服务端各种配置参数的请求,包括 time_zone 等全局 variable

  • show warnings,这次请求应该就是看看服务端有没有什么警告信息

  • 客户端发起:SET names latin1

  • 客户端发起:SET character_set_results = NULL

  • 客户端发起:SET autocommit=1

  • 我们的业务查询请求

  • 结束会话

  • 四次挥手

具体可以看下面的红框部分:

最后说一句(求关注)

好了,看到了这里了, 转发、在看、点赞 随便安排一个吧,要是你都安排上我也不介意。写文章很累的,需要一点正反馈。

给各位读者朋友们磕一个了:


转载:https://blog.csdn.net/HongYu012/article/details/123423139
查看评论
* 以上用户言论只代表其个人观点,不代表本网站的观点或立场