天啦撸，甩锅不成，程序员只好含泪修复bug

1. 前言

最近项目有个需求：一个内部派单系统，同事反馈：来一个活儿系统就立马派给我，我的工作永无结束之日。程序员小哥们能不能在系统控制每日派单上限，每日派单超过这个上限就别分给我了，我想早点下班偶遇我未来的女朋友。嘤嘤嘤…
“年轻人，勇敢的去追求爱情吧，剩下的交给我”
望着同事心满意足下班的背影，我冷笑，“哼，年轻，丝毫不懂工作的乐趣。”

2. 开心的改造代码

咱先梳理下逻辑：

• 1.一天24小时随时都有可能来新订单。原本逻辑系统每分钟扫描未派出去的订单，并根据某些规则下发给用户。
• 2.不同订单会派给不同角色下的用户。

戴上我山寨的earPods Pro 闪瞎眼Max，“爱情买卖”调到最大声，音乐一放，我最闪亮，翘着二郎腿就开干， 在最终派单的代码中添加如下逻辑：

//是否强制分配
//是否有配置上限，有则判断：超上限不分配。没有配置则能直接通过
if (!force && dispatchOverLimitPerDay(orderType, userId)) {
     log.warn("经办人:{}，本日已超出类型：{}的分配上限，系统不分配orderId：{}", userId, orderType, orderId);
     return;
}

//派单逻辑
...
orderService.save(entity);

方法内查询用户当天已经派了多少单，当天还剩余可派多少：

 //当天开始时间和结束时间
Date date = new Date();
Date beginOfDate = DateUtil.getBeginOfDate(date);
Date endOfDate = DateUtil.getEndOfDate(date);

//当天某一角色下用户，当天已分配的数量
List<DispatchOrderNumLimitResDTO> dayDispatchedInfo = orderService.queryDispatchedOrderNumGroupByUserId(orderType, beginOfDate, endOfDate);
 
// 查找某一角色下用户配置的每日上限，无则默认无上限
List<DispatchCaseNumLimitInfo> dayLimitInfo = findLimitConfig();

//待分配的用户当天是否还有剩余
int remainNum = getRemainNum(userId,dayDispatchedInfo,dayLimitInfo);
...
...
return remainNum > 0; 

本地测试通过，测试验收通过，生产发版上线，需求标记为已解决。一套流程走下来，如德芙般丝滑。合上电脑，背包，打卡下班一气呵成。

3. 天呐，系统貌似出现了问题

先介绍下项目：

• springboot + mybatis-plus + dubbo
• 分布式定时任务采用quartz
• 预发布1台服务器，生产3台服务器
• MySQL 5.6.42

第二天上班收到测试反馈：系统超出了配置的用户派单上限，原本配置每日分配上限为12，实际分配了18。如下：

遇到bug不要慌，甩锅已经是基本操作了。看数据库的确是凌晨00:00系统自动派单的，看了系统日志，同事昨晚最迟操作系统是在20:54。排除人为因素，那就是系统层面的原因了。

4. 一个键盘一包烟，一个BUG找一天

接下来就是一天的排查，有以下几个怀疑的点：

1. 每日上限数配置配置有误/被修改过
2. 系统查询条件有问题
3. 系统的定时任务由于并发导致查询出脏数据，也就导致系统超出当天的分配上限

4.1 每日上限数配置配置有误/被修改过

这个纯粹是想甩锅，去nacos查看配置确认：pre和prod上的nacos配置都是12。问了几个同事，他们都表示没有修改过nacos。
况且，上线当天（6/10 18:30上线，6/11早上发现问题）系统分配是刚好12条上限，且有剩余其他订单等待11号分配。此路不通。
疑点：上线当天正常，第二天却超上限分配，差别是时间。

4.2 系统查询条件有问题

查询逻辑为：查询一天的开始~结束时间段之内，每个人派了多少单。
SQL语句如下：

select order_id,user_id,count(1) as dispatchedNum
from wait_order
where 
is_deleted = false and orderType = #{orderType} 
and create_time >= #{beginOfDate}
and create_time <= #{endOfDate}
order by userId

是不是获取开始时间和结束时间有问题？
我在本地跑main方法输出这两个时间，发现也是正常的：
00:00:00 ~ 23:59:59，时间获取是正常的。我手动替换掉#{beginOfDate}等占位参数去生产环境跑此条SQL，能把当天分配的所有订单都查询出来（12条正常的 + 6条额外分配的）。那我判定SQL是没问题的。

4.3 系统的定时任务由于并发导致查询出脏数据

这个就能很好的解释分配超限问题了。由于同事小M写的分布式定时任务有问题，导致同时有俩线程A,B同时执行分配。

• 假设A线程在某一刻查询出某人当天分配了6条，准备分配剩余6条。
• B线程此时也查询出6条，并且把剩余6条给分配了。（B：“我就是比你快” A：“老哥，男人不能太快”）
• A继续分配6条订单，这样就导致了超限分配

科学~ 合理~
跑去同时小M位置上，反手甩给他一口锃光瓦亮的锅
你以为这就结束了？
小M反手就是程序员灵魂提问：“请先看下文档，请仔细看文档，请熟读并背诵文档”。
okok我错了，定时任务没有问题。（其实项目的定时任务一直没出过问题）

此外，还怀疑了数据库主从没同步的问题，但都否决了。
第一天排查无果，加上了几行log日志后下班回家。

5. 柳暗花明

第二天一早看数据库，超限派单问题依然存在——某账户设置一天派单8件，但实际派单12件。日志打印如下：

2020-06-12 00:00:00.175 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[]
2020-06-12 00:00:00.386 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=1, remainNum=7)]
2020-06-12 00:00:00.437 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=1, remainNum=7)]
2020-06-12 00:00:00.487 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=1, remainNum=7)]
2020-06-12 00:00:00.632 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=1, remainNum=7)]
2020-06-12 00:00:00.681 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=2, remainNum=6)]
2020-06-12 00:00:00.732 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=3, remainNum=5)]
2020-06-12 00:00:00.781 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=4, remainNum=4)]
2020-06-12 00:00:00.831 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=5, remainNum=3)]
2020-06-12 00:00:00.882 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=6, remainNum=2)]
2020-06-12 00:00:00.931 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=7, remainNum=1)]
2020-06-12 00:00:00.978 [pool-124-thread-1] INFO   - 每日分配上限剩余信息：[XXXDTO(userId='测试1', dispatchedNum=8, remainNum=0)]
2020-06-12 00:00:00.978 [pool-124-thread-1] WARN - 经办人:测试1，本日已超出类型：3的分配上限，系统不分配orderId：XXX

我从MySQL数据中抓住了元凶，当天插入数据如下：

疑问：

• 第3,4,5,6次派单dispatchedNum（已派单）数量仍为1？
• 系统实际多派了4单，从数据上看，有4单插入的时间均为00:00:00。我回头看昨天的派单，发现11号数据中，有6单插入时间也为00:00:00，数量恰好是多派的单！我们再看一下前一天的数据：
  
  我回头看看工具类源码：

    public static Date getBeginOfDate(Date date) {
        Calendar calendar = Calendar.getInstance();
        calendar.setTime(date);
        calendar.set(11, 0);
        calendar.set(12, 0);
        calendar.set(13, 0);
        return calendar.getTime();
    }

    public static Date getEndOfDate(Date date) {
        Calendar calendar = Calendar.getInstance();
        calendar.setTime(date);
        calendar.set(11, 23);
        calendar.set(12, 59);
        calendar.set(13, 59);
        return calendar.getTime();
    }

问题定位！
getBeginOfDate方法，只把时，分，秒设置为0，未把毫秒也设置为0。同理，getEndOfDate也未把毫秒设置为999，导致我的SQL查询语句实际为带了毫秒查询：
至此，看官们可能还有最后一个疑问：为什么中途会有条记录为00:00:01的数据呢？你听我给你 狡辩 解释。
定时任务调用service.save(entity)方法，有可能打在不同的svc上，而这三个svc系统时间可能有毫秒时间的差别，所以~~~

6. 解决BUG

//getBeginOfDate方法
calendar.set(Calendar.MILLISECOND,0);

//getEndOfDate方法
calendar.set(Calendar.MILLISECOND,999);

问题出在了工具类上，我的心情：完~
（开头的同事仍在努力寻找爱情ing~）