记一次排查了两个小时的简单bug

开始

近期有一个需求，需要不断重复刷新数据库中存储的运维表的时间，符合便执行。想偷懒，就使用了spring自带的定时任务，对，就那个@Scheduled，因为之前使用过多次了，感觉得心应手就没多想。设定cron表达式每秒一次刷新 ， cron="*/1 * * * * ?" 反正不在乎服务器资源占用，有钱就是豪横。 后面需要比较准时的一秒，就把cron表达式改成如下形式 fixRate = 1000 写写代码逻辑本以为任务就此完成，没想到恶果就此种下。

起因

写完代码随后一跑服务，想找前端拉一下代码，前端说还没写完，也罢，自己服务启动数据库改一下数据也是可以的，就在我准备拿起咖啡开始下午的摸鱼时间时，看到控制台日志打印了一点儿不寻常的东西

• [2024-05-27 16:48:21,124] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:21,124] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:21,124] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:21,124] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:21,533] [INFO] - run(dispatchAdapter.java:28) - 开始调度任务计划
• [2024-05-27 16:48:22,262] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:22,262] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:22,262] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功
• [2024-05-27 16:48:22,262] [ERROR] - sendCommand(taskRunner.java:41) - 控制命令发送成功 ?????? 从队列中读取的任务，过一秒以后竟然又执行了一遍。因为还没有和命令下发模块对接，所以下发的命令我都是写死的成功，这要是到了生产环境，重复下发命令。我估计我的小工作就不保了。随后我写了一行代码，在执行任务的时候实时打印一下任务队列的长度。竟然两次都是惊人的从4到0。这个操作迷惑了我，让我认为自己向任务队列添加任务的代码是没有错误的，可能是@Scheduled的导致的重复执行。就此步入的和空气斗智斗勇的深渊。

激情四射的百度环节

首当其冲的便是xml配置重复读取问题，文章在这。我回到项目，却有点傻眼，xml配置方式都是多老的东西了。项目几乎全是注解开发，并没有相关的问题。后面我又审查了@EnableScheduling和@Scheduled的添加位置，也都没有问题。好吧，继续看看有没有其他的方法。随后文章作者便找到了命中注定的那个它，cron表达式的书写问题。我也兴致冲冲，认为罪魁祸首不过是自己对cron表达式认识不够深刻。简单的修改之后，重启服务，就在认为万事大吉的时候。同样的问题再次出现。我微微一皱眉，意识到事情可能并不简单。

没那么激情四射的百度环节

随后查找百度，大多也都是类似的解决方案，xml扫描两次导致的两个实例，注解扫描导致的两个实例，cron表达式。就在此时，一个显眼的文章映入眼帘。就是它。执行时间间隔过短？天呐，这简直就是我，我设定的任务间隔只有一秒。我的命中注定的那个它，来了吗？我又兴致冲冲的找到配置，1秒太短，一万年太长，那就10秒吧。随后重启服务，铛铛！完美的日志，服务日志只打印了一遍。我微笑，默叹，以为秒绝。随后端起象征着胜利和摸鱼的咖啡。

一切，都结束了，吗？

喝下一口绝绝子好喝到翘脚脚的咖啡。却差点一口喷了出来，该死的重复执行又出现了，甚至还是就像我配置的任务执行间隔一样，完完整整的是10秒之后把4个任务又利利索索来了一遍。天呐！！！！！！老天爷。为什么这样对我。我心如死灰，万籁俱寂。可能，这就是我的命吧，我要死在这个bug手里了。

任何bug豆浆被绳之以法，和蔼！

虽然前面的努力，全部木大，但是我也是加把劲打工人，不要停下来啊。终于，在排除了其他的可能因素，我把视线对焦到了我给任务队列添加任务的代码。它的逻辑很简单。也是一秒执行一次，对比从数据库取出的计划执行时间和现在时间是否一样，一样就放入任务执行队列。这能有什么错？我不屑一顾，随手打了个断点。一次、二次、三次、四次。就像数据约定好的那样，向待执行队列放入4个任务，他却并没有停下来。我一下就从椅子上坐直了。然后五次、六次、七次、八次。结结实实的又放了4个任务。一旦错误的地方找对了，那解决问题就简单多了。我看向时间的比对代码。被我的愚蠢逗笑了。 代码逻辑如下 Command.getStartTime().until(LocalTime.now(), ChronoUnit.SECONDS) == 0 把从任务取出的时间和当前时间，在秒的尺度上进行判断，until是取二者的差值，==0就证明任务到了执行的时间。用这个来判断，有错吗？错的一塌糊涂， LocalTime是包含纳秒的，比如16:40:20和16:40:19.890和16:40:20.890两者相差的时间都是小于1秒的，都会等于0。所以，当这段代码设定是每秒执行一次的时候，它会在这个任务的执行时间附近两秒都是true，就会向队列添加两次任务。正确的做法是 Command.getStartTime().compareTo(LocalTime.now().withNano(0)) == 0 compare当两者相等的时候就返回0，把当前时间只取到秒不要纳秒，再比对，就不会有问题了。

coding有风险，测试需谨慎

再简单的任务也不能小看，一个小小的判断，浪费我两个小时的时间。谨以为记。