91 xxl-job executor 还存在并且 job 正在执行, 但是 job 被标记为 “任务结果丢失，标记失败“

前言

最近出现了一个这样的问题

我们生产环境中的一个 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], 我们大致可以判断的是

第一次任务执行成功, 第二次任务执行成功, 第三次任务执行失败 "任务结果丢失，标记失败"

第四次任务执行失败 "任务结果丢失，标记失败", 第五次任务执行失败 "任务结果丢失，标记失败"

以及后面的都应该会失败

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

然后启动 xxl-admin, 创建一个 jobGroup localExecutor, 创建一个调度任务关联在 localExecutor 上面

然后来尝试复现这个问题, 果然和我们期望的差不多, 启动任务 stackingJobHandler, 执行日志如下

我们注意观察一下这个 handle_time 基本上都是 trigger_time + 7s, 这是由 monitorThread 来处理标记的

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

问题的调试

首先我们要观察的是 moniitorThread 中是怎么将我们这里还在执行的 executor 对应的任务找到的

下面第一张图片是 monitorThread 的核心的业务逻辑, 主要是找到丢失的任务, 并且更新处理状态

下面第二张图片是具体的查找丢失的任务的方式, 查询的是已经正常触发的, 还未被 admin 正常/异常收尾处理的, 期望触发时间在 7s 之前的, 并且 job 对应的 executor 关联不到的 job

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

我们来查询一下 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 丢失的情况

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

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 一个任务执行完成之后, 会立即取下一个任务来执行

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

我们再来看一下任务拥塞的情况

可以看到的是 stackingJobHandler 的 jobThread 中已经拥塞了三个任务了, 分别是 94， 95， 96, 可以根据这个 id 去 xxl_job_log 中查询

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

日志中的细节

我们回到最问题出现的开始的情况, 我们来查看一下这一部分 job 执行记录对应的日志信息

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

抽样前面的几个来看一下

可以看到的是这些日志中任务开始之前, 任务结束之后, xxljob 都打印了相关的日志, 我们可以从日志中可以大致的判断出任务的执行时间, 这里的执行时间规则大概是 3, 5, 10, 3, 我们从前面的结果中可以看到的是 34, 35 应该是正常执行成功

36, 37 应该是被标记为了 "任务结果丢失，标记失败"

但是我们看具体的日志中 callback 的情况, 我去居然还是 callback finished ? 按照 jobThread 这边的处理, 我们正常理解期望应该是输出一些异常信息才对

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

我们在抽样一下后面的几个执行记录

可以看到任务执行的时间规则大概也还是 3, 5, 10, 3

并且 callback 这里都是 finished, 呵呵我们来看一下这里的 callback 的具体的情况

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

我们来看一下 xxl-admin 这边的处理, 实际的 callback 的处理是放到了异步任务里面

然后这里不管处理情况怎么样, 返回给 executor 的都是 SUCCESS, 所以 executor 这边拿到的总是 callback finished

然后我们再来看一下我们这里这种被标记为了 "任务结果丢失，标记失败" 的任务, 在 callback 里面实际又是怎么处理的? watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

因为 jobLog 的 handleCode 已经不为0了[表示已经被 admin 正常/异常处理过了], 这里标记为重复的 callback 的请求, 直接丢弃了请求

具体的错误信息, 会在上面的 callback 的外层会有日志体现

watermark,type_ZHJvaWRzYW5zZmFsbGJhY2s,shadow_50,text_Q1NETiBA6JOd6aOOOQ==,size_20,color_FFFFFF,t_70,g_se,x_16

所以如果我们想要感知到这部分拥塞的任务的执行情况, 我们一般来说有几种方式

1. 从 xxl-admin 的日志中查找这个 jobId 的相关的信息, 可以查询到具体的任务调用 callback 的一个大致的时间

2. jobHandler 中基于 XxlJobContext 输出 job 的相关信息, 这样就可以通过日志来查询

3. 等待能够找到这个 jobLog 对应的日志文件, 也就说明这个任务开始执行了

回溯一下问题

1. 通过 xxl-job 点击查看任务的执行记录的日志, 日志为空, 另外根据配置的日志的路径来查找, 查找不到给定的 job 的日志文件

这是因为这部分 jobLog 是期望调用了, 但是由于任务拥塞还没有调用, 因此还没有执行, 因此找不到对应的 jobLog 的日志文件

我们 jstack 查看到的任务的执行, 是所有的拥塞的任务再之前的一个 jobLog, 但是后面还有一系列拥塞的任务还未执行

这是由于任务的业务代码决定的, jobHandler 中查询的是 now 附近的业务数据, 那么当然是什么时候执行, 获取的就是那个时候的时间

jobLog 对应的 jobInfo 对应的 jobGroup 的 executor_address 和 executor 启动的时候向 admin 注册的 jobRegistry 的 registry_value 不一致, 导致 xxl-job 认为这个 job 对应的 executor 已经不在了, 这两者需要完全的字符串匹配

完