诡异至极的SQL Server推送数据到MQ日期早48小时的生产问题排查

背景

1. 应用迁移，即旧版应用下线，新版应用上线，停掉旧版应用里面的quartz任务，开启新版的xxl-job调度任务。
2. 数据推送源头是SQL Server，目的地是MQ。

问题爆出

今天iview的自动导出任务从老系统迁移到新系统，下午2点40~近5点。导出到MQ的消息内容与预期不符，造成这段时间数据缺失。
具体来说，本来今天要导出update_time 是2022-03-02的数据，但是切新系统之后，导出的数据，update_time 是2022-02-28。
4点40之后，把导出MQ任务切换到老系统。下游任务恢复正常。

消息查询平台截图如下，从2022-03-02 14:52:00到2022-03-02 16:52:35，造成生产事故的数据有65104条。另外搜索条件支持指定业务Id，即1000004004，指的是新的应用appId。

还没有考虑另外一个消息发送节点：

随便取一条数据，看其中的两个日期字段：

使用​​时间戳在线转换​​，日期确实有问题：

完整的消息体，JSON格式化之后的数据如下：

{
  "t_dial": 34,
  "lastevent_type": "EventReleased",
  "dn": "32350",
  "cnt_hold": 0,
  "employeeid_from": "32350",
  "id": 549270452,
  "dnis": "6017365591305",
  "create_time": 1646037503096,
  "t_handle": 20,
  "is_acw": 0,
  "ud_6": "",
  "ud_7": "",
  "ud_4": "3c4bcfbc92887c2e4484bff77c633e82",
  "dial_time": 1646037451176,
  "ud_5": "",
  "is_queued": 0,
  "ud_2": "75571446",
  "ud_3": "3",
  "ud_1": "124716316",
  "lastevent_time": 1646037505487,
  "transferconnid": "",
  "ed_5": "",
  "ed_4": "0",
  "ed_3": "",
  "deleted_time": 1646037505487,
  "ed_2": "",
  "ud_8": "",
  "ed_1": "",
  "ud_9": "",
  "answer_time": 1646037485842,
  "abandon_type": "100",
  "maincalluuid": "0014MEHGOS8O19GAPC1O22LAES23RIEQ",
  "t_acw": 0,
  "release_action": "",
  "ud_19": "",
  "ud_18": "",
  "ud_17": "",
  "ud_16": "",
  "ud_15": "",
  "ud_14": "",
  "employeeid": "",
  "cnt_mute": 0,
  "ud_13": "",
  "ud_12": "",
  "ud_11": "",
  "ud_10": "",
  "update_time": 1646037503096,
  "t_conf": 0,
  "calluuid": "0014MEHGOS8O19GAPC1O22LAES23RIEQ",
  "ani": "32350",
  "call_type": 3,
  "release_time": 1646037505487,
  "cnt_conf": 0,
  "call_state": 0,
  "ud_20": "",
  "t_queued": 0,
  "is_handle": 30,
  "release_code": "2 Remote",
  "t_hold": 0,
  "connid": "00790327a1802ee1",
  "t_ring": 0,
  "transfer_type": "",
  "arrived_time": 1646037451176,
  "cnt_transfer": 0,
  "is_diverted": 0
}

可以发现几个时间都是1646037开头。
从数据源头Sql Server获取数据的查询SQL语句如下：

select 
id,
maincalluuid,
calluuid,
connid,
transferconnid,
employeeid_from,
employeeid,
dn,
ani,
dnis,
arrived_time,
queued_time,
diverted_time,
ring_time,
dial_time,
answer_time,
release_time,
deleted_time,
acw_time,
hold_time,
conf_time,
cnt_hold,
cnt_conf,
cnt_transfer,
cnt_mute,
t_queued,
t_ring,
t_dial,
t_handle,
t_acw,
t_hold,
t_conf,
call_type,
call_state,
is_queued,
is_diverted,
is_handle,
is_acw,
transfer_type,
abandon_type,
release_code,
release_action,
lastevent_time,
lastevent_type,
create_time,
update_time,
ud_1,
ud_2,
ud_3,
ud_4,
ud_5,
ud_6,
ud_7,
ud_8,
ud_9,
ud_10,
ud_11,
ud_12,
ud_13,
ud_14,
ud_15,
ud_16,
ud_17,
ud_18,
ud_19,
ud_20,
ed_1,
ed_2,
ed_3,
ed_4,
ed_5
from sip_record
where update_time >= CONVERT(varchar(10),DATEADD(MINUTE,-10,GETDATE()),120)+' '+
                cast(DATEPART(HOUR,DATEADD(MINUTE,-10,GETDATE())) as varchar(10))+':'+
                right('0'+cast((DATEPART(MINUTE,DATEADD(MINUTE,-10,GETDATE()))/10)*10 as varchar(10)),2)+':00'
and update_time < CONVERT(varchar(10),GETDATE(),120)+' '+cast(DATEPART(HOUR,GETDATE()) as varchar(10)) + ':'+ right('0'+cast(DATEPART(MINUTE,GETDATE())- DATEPART(MINUTE,GETDATE())%10 as varchar(10)),2)+':00'

将此SQL拿到DataGrip执行，没有任何问题：

查询出来的时间就是系统当前时间往前15分钟左右。

至于上面的时间跨度，第二天继续排查此问题。。

排查

这是什么鬼问题？？？

没了主见，无头苍蝇。

甚至莫名其妙，修改系统的时间，然后执行此SQL，结果还是正常的时间。

能不能在本地调试程序？

本地使用原有的测试Sql Server数据源，推送数据到MQ，问题没有复现。

发现本地居然可以连接这个生产环境的Sql Server数据源，开搞。

在连接SQL Server，获取到的数据就不正常。为啥DataGrip连接数据源获取数据是OK的？？一开始没有往这方面想，折腾很久。MQ消息体看到的是时间戳，可以理解为一个大整数？调试代码修改如下，结果报错：

datetime2，这是什么数据类型？以这个关键词和48小时在Google搜索。

好家伙，网络搜到如下类似问题：
​​​how-is-sql-servers-timestamp2-supposed-to-work-in-jdbc​​

The datetime2 is always 2 days (48 hours) before the expected time.

The test is the same for both datetime and datetime2, but the datetime2 test fails with a date that is 2 days prior.

但是这里面没有给出可行的解决方案。除了建议使用jTDS驱动。

这是BUG？？

没有找到sqljdbc4的官方GitHub仓库？

然后发现microsoft不再维护sqljdbc4驱动，而是在维护新的驱动版本：

<<dependency>
    <groupId>com.microsoft.sqlserver</groupId>
    <artifactId>mssql-jdbc</artifactId>
    <version>10.2.0.jre8</version>
</dependency>

去sqljdbc4的升级版驱动​​GitHub仓库​​，即mssql-jdbc里面搜issue。

也提到类似的​​问题​​

但是我使用此驱动时，报错信息：

java.lang.Exception: com.microsoft.sqlserver.jdbc.SQLServerException: 驱动程序无法通过使用安全套接字层(SSL)加密与 SQL Server 建立安全连接。错误:“sun.security.validator.ValidatorException: PKIX path building failed: sun.security.provider.certpath.SunCertPathBuilderException: unable to find valid certification path to requested target”。 ClientConnectionId:e914fd2b-51f2-4939-bda2-9ffdb8b03207

参考​​文档​​​，将之前可以连接成功的URL：​​jdbc:sqlserver://10.121.31.116:2433;databaseName=gene_cdr;​​​改成​​jdbc:sqlserver://10.121.31.116:2433;databaseName=gene_cdr;integratedSecurity=true;encrypt=true;trustServerCertificate=true​​​，结果报错：
​​​java.lang.Exception: com.microsoft.sqlserver.jdbc.SQLServerException: 没有为集成身份验证配置驱动程序​​

而且假使真的使用这个驱动，还有乱七八糟的​​版本适配矩阵​​以及可能带来的各种问题

此时才再考虑使用jTDS。DataGrip使用的驱动是jTDS：

<dependency>
    <groupId>net.sourceforge.jtds</groupId>
    <artifactId>jtds</artifactId>
    <version>1.3.1</version>
</dependency>

而程序目前使用的驱动是：

<dependency>
    <groupId>com.microsoft.sqlserver</groupId>
    <artifactId>sqljdbc4</artifactId>
    <version>4.0</version>
</dependency>

修改驱动。还是不行？？

实际上是可以的：

如上图，需要注意的点：

1. 修改连接SQL Server数据源的URL地址，因为sqljdbc4驱动和jTDS连接同一个数据源，URL不一样；
2. 修改驱动的完整包路径，sqljdbc4是​​com.microsoft.sqlserver.jdbc.SQLServerDriver​​​，jTDS是​​net.sourceforge.jtds.jdbc.Driver​​。

断点调试发现，此时可以获取到正取的时间。

日期格式数据调整；

灵魂拷问

旧版工程和新版工程代码有何区别？

旧版代码不贴出来，写得一坨屎。

贴一张断点调试截图：

可以发现时间也是提前48小时。

MQ消息查询平台，发送IP，172.20.10.46是我的本机IP，业务ID是旧版应用工程的appId。调试时忘记​​select top 1 *​​，一下子发送几千条数据。可见测试环境，时间也是不对的。

旧版应用生产环境，没有问题，要不然早炸锅。消息查询平台截图如下，确实没有问题：

该数据源版本信息：
​​​select @@version​​ 执行结果：

Microsoft SQL Server 2012 (SP1) - 11.0.3000.0 (X64)
Oct 19 2012 13:38:57
Copyright (c) Microsoft Corporation
Enterprise Edition (64-bit) on Windows NT 6.2 <X64> (Build 9200: ) (Hypervisor)