现象描述与复现

线上环境签署合同时发现某一员工生日为1988-04-15,但合同上显示的是1988-04-14缺少一天

初步怀疑是夏令时问题,所以一开始排查方向重点放在数据存储和读取时的时区转换,走了不少弯路

Tip: 夏令时是什么

1986年4月，中国中央有关部门发出“在全国范围内实行夏时制的通知”，具体做法是：每年从四月中旬第一个星期日的凌晨2时整（北京时间），将时钟拨快一小时，即将表针由2时拨至3时，夏令时开始；到九月中旬第一个星期日的凌晨2时整（北京夏令时），再将时钟拨回一小时，即将表针由2时拨至1时，夏令时结束。

1986年至1991年，中华人民共和国在全国范围实行了六年夏令时，每年从4月中旬的第一个星期日2时整（北京时间）到9月中旬第一个星期日的凌晨2时整（北京夏令时）。除1986年因是实行夏令时的第一年，从5月4日开始到9月14日结束外，其它年份均按规定的时段施行。夏令时实施期间，将时间调快一小时。1992年4月5日后不再实行。

问题排查

第一步: 日期的来源

日期从数据库读取而来,类型为DATE类型,在数据库中保存的日期是1988-4-15,所以写入日期功能应该没有问题的

第二步: 线下环境确认

测试环境发现改问题能复现,并且在页面显示上也能看出问题,代码如下所示:

1

entryBasicInfo.setBirthday(new DateTime(entryInfoDetail.getBirthday(), DateTimeZone.forID("Asia/Shanghai")).plusHours(8).toDate());

可以看到页面展示的地方有+8小时的逻辑,也就是说读取到数据库时间为数据库中读取到的时间+8小时,代码如下所示:

1
2
3
4
5
6

/**
* 出生日期
*/
@NotNull(message = "出生日期不能为空", groups = EntryInfoV1.Group_EntryInfo.class)
@JsonFormat(pattern="yyyy-MM-dd HH:mm:ss",timezone = "GMT+8")
private Date birthday;

可以看到json序列化指定为GMT+8时区,如果是夏令时时间会转为为不执行夏令时的时间(-1hour), 返回值如下:

1
2
3
4
5

{
  	entryBasicInfo: {
    birthday: "1988-04-15 07:00:00"
  }
}

结合页面的返回值和阅读页面展示生日的代码,可以推断从数据库读取到的时间为夏令时时间1988-04-15 0:00:00(CDT)

再详细解释下为啥:

1988-04-15 07:00:00(GMT+8) = 1988-04-15 00:00:00(CDT) + 8 hours

为啥要从页面接口看?

因为生成合同逻辑在测试环境不好调试,所以借助页面展示接口推测从数据库读取到的Date数据

第三步 调试验证判断

如何验证我们前面推断出来的结论呢?肯定是依靠调试啦!造好数据,打上断点:

如我所料, 读取到的时间正是 1988-04-15 00:00:00(CDT) 下面继续追查,看在什么地方格式化为1988-04-14

第四步 本地与线上JDK版本不同引起的一段插曲

实际上在本人本地执行的结果如下,相同的输入下,本地的时间戳和远程调试的并不一样,很是困惑

对比发现zoneOffsets信息不同

经过光闪闪提醒,jdk会更新时区和夏令时信息,于是打开jdk更新公告查询,地址:https://www.oracle.com/java/technologies/tzdata-versions.html

8u202版本后,1988年夏令时开始于1988-04-17此前版本开始于1988-04-10,而1988-04-15正好落在此区间,因此本地与线上读取到的时间不同

再深究下不同JDK返回不同时间的原因:

找到mysql-connect-driver中解析DATE类型的代码:

1 2 3 4 5 6 7 8 9 10 11 12

>public <T> T decodeDate(byte[] bytes, int offset, int length, ValueFactory<T> vf) { if (length == 0) { return vf.createFromDate(0, 0, 0); } else if (length != MysqlaConstants.BIN_LEN_DATE) { throw new DataReadException(Messages.getString("ResultSet.InvalidLengthForType", new Object[] { length, "DATE" })); } int year = (bytes[offset] & 0xff) | ((bytes[offset + 1] & 0xff) << 8); int month = bytes[offset + 2]; int day = bytes[offset + 3]; return vf.createFromDate(year, month, day); }

可以发现DATE类型 不包含时区信息,因此构建出来的是日期是本地时间+默认时区,因此在8u202版本后返回为1988-04-15 00:00:00(GMT+8) ,在此版本前返回为1988-04-15 00:00:00(CDT) 这两个时间相差1小时

关于JDK中存放时区信息的位置:

位于TzdbZoneRulesProvider类型,在我本地的位置为:/Library/Java/JavaVirtualMachines/jdk1.8.0_241.jdk/Contents/Home/jre/lib/tzdb.dat

1 2 3 4 5 6 7 8 9 10 11 12

>public TzdbZoneRulesProvider() { try { String libDir = System.getProperty("java.home") + File.separator + "lib"; try (DataInputStream dis = new DataInputStream( new BufferedInputStream(new FileInputStream( new File(libDir, "tzdb.dat"))))) { load(dis); } } catch (Exception ex) { throw new ZoneRulesException("Unable to load TZDB time-zone rules", ex); } >}

在本地可以替换该文件为旧版本从而可以在本地复现该问题

第四步 定位问题代码

一路搜索代码,找到合同中设置生日的地方:

1
2

//  出生日期
template.setPbBirthDate(new DateTime(eu.getBirthday()).toString("yyyy-MM-dd"));

需要注意的是DateTime属于第三方库joda time,基于上一段“小插曲”,我们大胆猜测下joda time是使用自己的时区信息还是读取jdk的时区信息?

铛铛铛揭晓下答案:

joda time使用自己的时区信息,不难推测,如果joda time的时区信息较新,在8u202版本前的jdk运行就会发生诡异的问题:

至此,我们已经完全查明少一天的前因后果

1. 由于jdk版本较旧,时区信息较老, DATE类型数据1988-04-15被解析为 1988-04-15 0:00:00(CDT)
2. 由于joda time时区信息较新,1988-04-15 0:00:00(CDT) 被解析为1988-04-14 23:00:00(GMT+8)

总结和收获

1. Mysql DATE 类型不包含时区信息,使用配置的时区解析为java.sql.Date
2. 不同JDK版本的时区信息和夏令时信息可能会发生变化,信息存储在$JAVA_HOME/lib/tzdb.dat文件中
3. 8u201 以前版本认为中国时区在1988年时于04-10开始夏令时,8u201 后认为于04-17开始夏令时, 1988-04-10~1988-04-17期间的日期会因jdk不同而返回不同数据
4. joda time的时区信息使用自己独立的数据, 在和jdk Date类型转换时有转换错误的隐患
5. 升级jdk8版本到8u201以上,同时使用新版本joda time (其实就是为了保证两者时区最新且一致) 能避免上述隐患

Eureka服务发现机制

注册: 服务提供者启动后发送注册请求到Eureka-Server，默认注册信息生效时长为30秒。

续约: 服务提供者定时发送心跳给Eureka-Service，默认30秒一次，以刷新注册信息过期时间。若服务提供方不能续约，eureka-server将会注销该微服务节点（默认三个心跳周期90s)

注销: 服务提供者停机时发送注销请求到Eureka-Server。

调用: 服务消费者定时从Eureka-Server拉取服务注册表，并刷新本地缓存，默认30秒一次。服务消费者的负载均衡器(如Ribbon)向Eureka-Client获取服务提供者信息后，即可向服务提供者发送HTTP请求。

Eureka缓存机制

读写缓存定时刷新信息到只读缓存。刷新间隔：eureka.responseCacheUpdateIntervalMs，默认为30秒。

是否启用只读缓存可配：eureka.shouldUseReadOnlyResponseCache，默认开启。

Client定时从Eureka-Server拉取注册表，刷新本地缓存。拉取频率：eureka.client.registry-fetch-interval-seconds，默认为30秒。

LoadBalancer定时同步Client里的服务列表。同步间隔：ribbon.ServerListRefreshInterval，默认为30秒。可优化为实时刷新

服务下线不主动通知，则依赖剔除任务清除过期数据的机制。相关参数：续约间隔：eureka.instance.lease-renewal-interval-in-seconds，默认为30秒；节点有效期：eureka.instance.lease-expiration-duration-in-seconds，默认为90秒；清理时间间隔：eureka.server.eviction-interval-timer-in-ms，默认为60秒。

Eureka缓存机制造成的问题

在Client未同步到服务提供方下线信息前,流量仍会请求到下线节点上,导致Client报错,影响上游服务稳定性

多级缓存造成的同步延迟:

eureka.responseCacheUpdateIntervalMs+eureka.client.registry-fetch-interval-seconds+ribbon.ServerListRefreshInterval

默认为90s

解决方案

1. Server端 关闭eureka.shouldUseReadOnlyResponseCache 或 缩短eureka.responseCacheUpdateIntervalMs
2. Client端 缩短eureka.client.registry-fetch-interval-seconds
3. ribbon配置 优化为实时从Client获取
4. 延迟关闭服务,等待未同步的Client同步完成

问题接口流程梳理

根据报错信息,可以看出调用PersonnelSpi.getEmployeeInfo超时,且调用时长超过5s

1

com.netflix.hystrix.exception.HystrixRuntimeException: PersonnelSpi.getEmployeeInfo timed-out and fallback disabled

先梳理出PersonnelSpi.getEmployeeInfo执行流程

1. 先从网关获取oauthToken
2. 通过网关调用人事cr/employee/info接口

目前可以得出结论是这两步耗时大于5s

排除人事接口问题

通过报警的data_trace字段,可以在fast7层中查询Proxy的access日志:

查询结果类似这样:

可以看到Proxy的accesslog中 Proxy返回cr/employee/info耗时5ms

排除oauth/token接口问题

通过时间+clientIP 筛选方式,找到fast7层日志中 oauth/token的日志

比如13:20:15 调用了cr/employee/info接口

通过时间+clientIP+接口筛选,找到oauth/token的日志

从中可以得出两个结论:

1. o auth/token接口耗时6ms
2. o auth/tocken 和 cr/employee/info接口访问延迟在1s以内

如图,绿色部分是有日志证明没有问题的部分

检查DNS问题

从上图可以看到,出现问题的部分只可能出现在sm-ps-server解析域名过程中

查看jk上DNS监控发现:idc-aroute.ke.com解析存在5s超时情况,但是发生超时时间和报错时间不一致

查看代码发现,jk的dns监控并不是调用接口解析域名耗时,而是定时任务去检查域名解析耗时,所以报错时DNS监控数据正常并不说明当时DNS解析没有超时

通过DNS监控可以得出结论: DNS解析超时5s的情况存在,并且会影响oauth client真实请求延迟5s,并导致接口超时

结论

1. 优化oauthclient, 减少调用auth/token接口次数可以减少超时情况发生
2. 解决在容器环境中DNS解析超时问题

更新

networkaddress.cache.ttl (default: -1)
Specified in java.security to indicate the caching policy for successful
name lookups from the name service. The value is specified as as integer
to indicate the number of seconds to cache the successful lookup.
A value of -1 indicates “cache forever”.

networkaddress.cache.negative.ttl (default: 10)
Specified in java.security to indicate the caching policy for un-successful
name lookups from the name service. The value is specified as as integer to
indicate the number of seconds to cache the failure for un-successful lookups.
A value of 0 indicates “never cache”. A value of -1 indicates “cache forever”.

若DNS解析失败，会放入Negative Cache，默认缓存10秒(可调整/禁用)，后续DNS解析直接返回UnknownHostException。也就是说，极端情况下，DNS解析失败会导致10秒不可用。所以建议禁用Negative Cache。