记因系统对时导致打点缺失
一、背景
某天收到通知需要重启一台服务器。于是在业务低峰期时(14:48)对这台机器进行了重启操作。重启之后发现服务的业务打点居然消失了，只剩下CPU、内存、GC这些系统打点。震惊！遂将机器从注册中心摘除后开始Debug
二、排障和破案
第一天
1. 首先分析一下现象，业务打点确实而系统打点正常。于是开始查找这两种打点之间有什么差异。通过扒源码发现业务打点是本地消费队列并将点发到Trace服务器进行打点，而系统打点是将打点发到MQ由其他业务进行打点。所以问题还是出在我本地上。
2. 进入服务器检查与Trace服务器的连通性，确认与Trace服务器之间是否能正常进行通信
与Trace网络联通正常
TCP通信也正常
目前看来，服务与Trace服务的网络也是正常的，现在只能猜测是服务中打点的某个代码卡住了。
3. 分析服务。我们将服务当前的dump文件拷贝下来简单看了一下确实有东西在等待，根据dump中的trace进入代码看了一下，是ReentrantLock的一个Condition在await()，看样子是一直等待某个东西唤醒它，但就是不知道它在等啥。
dump中看到有东西在等待
代码中正在等待的地方
于是我们决定用arthas进机器看一下各方法的watch和参数，但是查了一晚上都没发现有什么比较可疑的异常，用四个字形容就是 无事发生。(当时忘记截图了，结果通过watch看到请求打点请求是一直有的，业务打点和TraceSDK消费打点也都是正常的)。时间已经到晚上十点半左右，我们就这么鸣金收兵了。
第二天
第二天一到公司查看监控发现一件差点让我喷早餐的事，昨天晚上快到23点的时候打点又出现了。也就是说昨晚我要是晚走半小时可能就能看到这个现象(不过这也的话可能我要通宵)。
惊现打点
到现在，我们的服务正常得不能再正常了，如果将这台机器重新上线应该也是没什么问题的，因为虽然我们的服务从注册中心摘除，但是每半小时还有几k的自检流量。但是这样的话这个问题就成了一个未解之谜，本着“反正线上有没有这台机器一个样”的想法，决定重启一下这台机器看看问题能不能复现(之前一直没有重启是因为害怕破坏现场)。我在14：12的时候重启的服务器，结果服务重启以后问题再次发生，打点又消失了！
在我看来，现在的处境和昨天比起来要稍微乐观一些，因为我们是刚刚启动服务，有新鲜的日志可以看，而昨天我们发现打点缺失的时候，启动日志早就被无数的业务日志淹没了。于是我决定从头看一下日志。
看第一行日志的时候，我就感觉破案了，因为有一个明显而又不明显的错误(当时没有截图，不过我可以自己打出来让大伙看看)
2020-12-01 22:13:57.044 ERROR SQLLogFilter[worker-31]: [xxxx..xxx.xxxx.xxx.xxx] ## Failure ! sql context is quit, clientConnId=593119546 cRecv0,sSend0,sRecv0,cSend0, CLIENT_FAKE_AUTH unknown_user transId=q0 , quitTrace type=conn.das.send2client.broken
可以看到这个日志的时间明显不对，跟我重启的时间大概差了8小时，且从上一张图看，打点消失到打点出现之间的间隔也是8小时。为什么是8小时呢？其实对于程序员来说，时间上的8小时应该是很敏感的，毕竟CST + 8 = GMT。
继续往下看日志，大概几秒后时间变成了正常的时间(这个截图了，很关键)
我就象征性地打点码吧
这下应该比较清晰了，服务器重启之后系统对时和服务启动是并行的，也就是说服务在启动时拿到的系统时间是GMT 22:xx:xx，在服务启动之后对时成功，此时拿到的系统时间就变成了CST 14:xx:xx，服务中应该有根据时间判断是否打点的逻辑才导致打点丢失的！
经过又一次扒别人的代码终于发现在打点消费者初始化的时候用系统时间设置了成员变量。
此时拿到的是22:xx:xx
而在消费的时候会用这个时间来做逻辑判断
此时的endTime是14:xx:xx
可以看出这种情况会导致代码永远无法执行进入if代码块中执行逻辑(后面两个条件不会成立)，因此也就发生打点缺失了，而8个小时之后，endTime终于可以超过start，打点恢复。
于是把这个发现发给了群里管服务器的大佬，得到证实服务器重启之后对时是和其他进程并行进行的。还得到了下面的评语。
中二了
三、后记
随手画了个图总结一下，错误就是因为
到此为止，服务器重启打点丢失案件算是破案了。我们在重启SOP中加入一条，在启动脚本的开头强制进行系统对时再重启服务来解决燃眉之急，并将这个需求提到服务器管理员那边让他们帮忙解决，因为这种问题影响面会比较大。目前只有我们提出这个问题的原因可能是服务器重启这种需求特别少，因为正常操作只是重启服务，像重启服务器这种需求是极少的；系统对时会慢到这种程度可能只有我们的机器遇到；且不是所有人都很关心业务打点。
最后随便提一下，打点是开发的眼睛，关注打点，遵守SOP，从我们做起！
