前言
最近出现了一个这样的问题
我们生产环境中的一个 xxl-job 任务, 很大一部分执行记录被标记为 "任务结果丢失，标记失败", 几乎是 98% 吧
然后 调试的时候 存在几个令人疑惑的地方
1. 通过 xxl-job 点击查看任务的执行记录的日志, 日志为空, 另外根据配置的日志的路径来查找, 查找不到给定的 job 的日志文件
2. jstack 查看该程序, 可以看到该 job 是正在执行中, 为什么找不到日志的问题? 根据 jobThread 的代码来看, 只要进入了业务代码, 那么至少应该会有一些 框架打印的日志信息到日志文件才对
3. 查询该 job 产生的业务数据, 我们可以查询到 "当前时间附近" 的一些相关业务数据[这一点是可以被 jstack 查询可以找到 job 正在执行解释, 业务代码中使用的是 now(), you业务代码执行, 就会有 "当前时间附近" 的业务数据]
4. 根据 monitorThread 的业务代码来看, 扫描的是正在运行的 已经超过了十分钟 并且找不到关联的 executor 的任务执行记录, 而我们的这个 job 的 executor 还存在, 怎么就被标记为 "任务结果丢失，标记失败" 了?
然后 后面当我查看到了 当前 job 对应的 jobThread 中的 triggerQueue 中还有 76 个任务的时候, 我突然明白了
本文的代码, 调试图片基于 jdk8 + xxl-job 2.3.0
测试用例
新建测试用例如下 StackingJob
可以看到的是这个 stackingJobHandler 是以 三次任务执行为一个循环
第一次执行 sleep 3s, 第二次执行 sleep 5s, 第三次执行 sleep 10s, 然后 循环
/**
* StackingJob
*
* @author Jerry.X.He <970655147@qq.com>
* @version 1.0
* @date 2021-10-02 16:20
*/
public class StackingJob {
int counter = 0;
@XxlJob("stackingJobHandler")
public void stackingJobHandler() throws Exception {
if (counter % 3 == 0) {
Thread.sleep(3000);
} else if (counter % 3 == 1) {
Thread.sleep(5000);
} else {
Thread.sleep(10_000);
}
counter++;
}
}
然后为了测试, 调整一下 monitorThread 的过期时间, 更新为 7s
结合上面的 stackingJobHandler, 以及 jobThread 顺序执行 job 的情况, 以及 monitorThread 查询丢失的任务的判断标准是以 任务 的期望执行时间来判断的[trigger_time], 我们大致可以判断的是
第一次任务执行 成功, 第二次任务执行 成功, 第三次任务执行 失败 "任务结果丢失，标记失败"
第四次任务执行 失败 "任务结果丢失，标记失败", 第五次任务执行 失败 "任务结果丢失，标记失败"
以及 后面的都应该会失败
然后启动 xxl-admin, 创建一个 jobGroup localExecutor, 创建一个 调度任务 关联在 localExecutor 上面
然后 来尝试复现这个问题, 果然 和我们期望的差不多, 启动任务 stackingJobHandler, 执行日志如下
我们注意观察一下 这个 handle_time 基本上都是 trigger_time + 7s, 这是由 monitorThread 来处理标记的
问题的调试
首先我们要观察的是 moniitorThread 中是怎么将我们这里还在执行的 executor 对应的任务找到的
下面第一张图片是 monitorThread 的核心的业务逻辑, 主要是找到 丢失的任务, 并且更新处理状态
下面第二张图片是 具体的查找 丢失的任务 的方式, 查询的是已经正常触发的, 还未被 admin 正常/异常 收尾处理的, 期望触发时间在 7s 之前的, 并且 job 对应的 executor 关联不到的 job
我们来查询一下 job_log 和 job_registry 的相关数据, 我们查看一下对应的 executor_address 和 registry_value
可以看到这里 job_log 中的 executor_address 为 http://localhost:9998 , 但是 job_registry 中的 registry_value 为 http://192.168.43.14:9998/
根据 "=" 关联 匹配, 没有匹配上, 所以 xxl-admin 将该 job 视为了 executor 丢失的情况
job_log 中的 executor_address 来自于 job 对应的 jobGroup 中的 executor_address, 也就是我们上面手动录入的这个 localExecutor 里面的 executor 暴露的 tcp 地址信息
然后 job_registry 的这个 registry_value 是来自于, executor 这边向 admin 注册的时候, 传递过来的地址信息, 优先取的是 xxl.job.executor.address 的配置信息, 以 IpUtil.getIpPort 来进行兜底, 也就是我们上面得到的 http://192.168.43.14:9998/
所以说我们配置 xxl.job.executor.address 和 jobGroup 的 address 的时候一定要注意, 如果是同一个逻辑 executor 一定要配置成一样, 即使是一个是 http://192.168.43.14:9998/ , 一个是 http://192.168.43.14:9998 这样也是不行的
如果是 xxl.job.executor.address 没有配置, 那么配置 jobGroup 的 address 的时候要按照它的默认规则配置, 务必需要一模一样, 因为关联是通过 字符串 "="匹配 来进行关联的
假设我们 jobGroup 的 address 和 jobRegistry 的 registryValue 配置一致
那么这里的 job 执行不会出现这里的 "任务结果丢失，标记失败" 的情况了
但是 依然会出现任务 拥塞 的情况, 那么我们就需要合理调整任务的用时 或者 说调度的周期了
我们观察一下 这一组的任务执行情况, 都是 执行成功, 并且 在任务拥塞了之后, 都是任务的执行间隔都是 3, 5, 10, 因为任务已经拥塞在队列里面了, jobThread 一个任务执行完成之后, 会立即取下一个任务来执行
我们再来看一下任务 拥塞 的情况
可以看到的是 stackingJobHandler 的 jobThread 中已经拥塞了 三个任务了, 分别是 94， 95， 96, 可以根据这个 id 去 xxl_job_log 中查询
日志中的细节
我们回到最问题出现的开始的情况, 我们来查看一下 这一部分 job 执行记录对应的日志信息
抽样前面的几个来看一下
可以看到的是 这些日志中任务开始之前, 任务结束之后, xxljob 都打印了相关的日志, 我们可以从日志中可以大致的判断出任务的执行时间, 这里的执行时间规则大概是 3, 5, 10, 3, 我们从前面的结果中可以看到的是 34, 35 应该是正常执行成功
36, 37 应该是被标记为了 "任务结果丢失，标记失败"
但是我们看具体的日志中 callback 的情况, 我去 居然还是 callback finished ? 按照 jobThread 这边的处理, 我们正常理解期望应该是输出一些 异常信息才对
我们在抽样一下 后面的几个执行记录
可以看到任务执行的时间规则大概也还是 3, 5, 10, 3
并且 callback 这里都是 finished, 呵呵 我们来看一下 这里的 callback 的具体的情况
我们来看一下 xxl-admin 这边的处理, 实际的 callback 的处理是放到了异步任务里面
然后这里不管处理情况怎么样, 返回给 executor 的都是 SUCCESS, 所以 executor 这边拿到的总是 callback finished
然后我们再来看一下 我们这里这种被标记为了 "任务结果丢失，标记失败" 的任务, 在 callback 里面实际又是怎么处理的? 
因为 jobLog 的 handleCode 已经不为0了[表示已经被 admin 正常/异常 处理过了], 这里标记为重复的 callback 的请求, 直接丢弃了请求
具体的错误信息, 会在上面的 callback 的外层会有日志体现
所以 如果我们想要感知到这部分 拥塞 的任务的执行情况, 我们一般来说有几种方式
1. 从 xxl-admin 的日志中查找这个 jobId 的相关的信息, 可以查询到具体的 任务调用 callback 的一个大致的时间
2. jobHandler 中基于 XxlJobContext 输出 job 的相关信息, 这样就可以通过 日志来查询
3. 等待能够找到这个 jobLog 对应的日志文件, 也就说明这个任务 开始执行了
回溯一下问题
1. 通过 xxl-job 点击查看任务的执行记录的日志, 日志为空, 另外根据配置的日志的路径来查找, 查找不到给定的 job 的日志文件
这是因为这部分 jobLog 是期望调用了, 但是由于任务拥塞 还没有调用, 因此还没有执行, 因此找不到对应的 jobLog 的日志文件
2. jstack 查看该程序, 可以看到该 job 是正在执行中, 为什么找不到日志的问题? 根据 jobThread 的代码来看, 只要进入了业务代码, 那么至少应该会有一些 框架打印的日志信息到日志文件才对
我们 jstack 查看到的任务的执行, 是所有的拥塞的任务再之前的一个 jobLog, 但是后面还有一系列拥塞的 任务 还未执行
3. 查询该 job 产生的业务数据, 我们可以查询到 "当前时间附近" 的一些相关业务数据[这一点是可以被 jstack 查询可以找到 job 正在执行解释, 业务代码中使用的是 now(), you业务代码执行, 就会有 "当前时间附近" 的业务数据]
这是由于任务的业务代码决定的, jobHandler 中查询的是 now 附近的业务数据, 那么当然是什么时候执行, 获取的就是那个时候的时间
4. 根据 monitorThread 的业务代码来看, 扫描的是正在运行的 已经超过了十分钟 并且找不到关联的 executor 的任务执行记录, 而我们的这个 job 的 executor 还存在, 怎么就被标记为 "任务结果丢失，标记失败" 了?
jobLog 对应的 jobInfo 对应的 jobGroup 的 executor_address 和 executor 启动的时候向 admin 注册的 jobRegistry 的 registry_value 不一致, 导致 xxl-job 认为这个 job 对应的 executor 已经不在了, 这两者需要完全的字符串匹配
完
