记一次 ElasticJob 从节点循环等待分片导致部分分片未执行的问题排查

本人水平及经验有限，内容如有错误或表述不当，请各位大佬批评指正！

分布式调度解决方案 https://github.com/apache/shardingsphere-elasticjob

本文基于 ElasticJob-Lite 3.0.0-beta-SNAPSHOT，撰写时 master 分支最新的 commit 为：
Trigger one-off job via Zookeeper (#1457)

背景描述

这段时间本人使用 ElasticJob 的 OneOffJobBootstrap 实现一个纯外置的 DAG 调度。
在调度时，DAG 中的每个节点都对应了一个 OneOffJobBootstrap 的实例，DAG 调度器通过 OneOffJobBootstrap 的 execute() 方法调度节点。

其中，每个 DAG 中的 OneOffJobBootstrap 实例是首次进行该 DAG 调度时才会初始化，后续 DAG 调度都将直接基于该实例调用 execute() 方法。

用伪代码描述：

private OneOffJobBootstrap aNodeOfDag;

public void scheduleNode() {
	if (null == aNodeOfDag) {
		aNodeOfDag = new OneOffJobBootstrap(...);
	}
	aNodeOfDag.execute();
}

DAG 模块、DAG 作业执行器模块写好后，在本地环境进行自测。

• 在单进程情况下，DAG 作业调度正常；
• 同时启动两个进程，DAG 作业调度正常，DAG 中每个节点的分片正常；
• 先启动单个进程，该进程运行一段时间（至少完成过一次 DAG 作业）后，再启动新的进程加入集群。此时预期是 DAG 中的每个节点会被重新分片以分配给多个进程。但实际情况是， DAG 中某个节点的作业只有该作业的 Leader 进程执行了，非 Leader 进程的 Debug 日志循环打印等待分片，且直到下一次 DAG 调度，非 Leader 进程的分片仍然没有运行。

---

初步分析与判断

验证是否与 OneOffJobBootstrap 的触发方式有关

看起来像是 OneOffJobBootstrap 出了问题，只有该作业的 Leader 节点所在进程执行成功，立即联想到有没有可能和前段时间修复的 OneOffJobBootstrap 无法分布式执行的问题 有关系？

于是编写了两段使用 OneOffJobBootstrap 调度作业的代码进行验证，用伪代码描述逻辑：

private static OneOffJobBootstrap bootstrap;

public static void initializeAndExecuteInLoop() {
	bootstrap = new OneOffJobBootstrap(...);
	while (true) {
		bootstrap.execute();
		TimeUnit.SECONDS.sleep(10L);
	}
}

public static void initializeOnly() {
	bootstrap = new OneOffJobBootstrap(...);
}

先启动一个进程执行 initializeAndExecuteInLoop() 方法；
然后再启动执行 initializeOnly() 的进程，且在整个过程中频繁增加或减少执行该方法的进程。

经过几轮测试发现，每一次调度都能完成分片且所有分片都能正常执行。也许不是这个问题？

分析 DAG 作业执行器的逻辑特点，猜测与节点初始化有关

根据本人 DAG 作业执行器的实现逻辑，其中有一个关键点：

DAG 中每个节点的 OneOffJobBootstrap 将在首次调度时初始化

回顾场景：

先启动单个进程，该进程运行一段时间（至少完成过一次 DAG 作业）后，再启动新的进程加入集群。

此时集群中，已有进程的 DAG 的节点都已经经过初始化且时刻准备着，新加入的节点需要经过一个初始化的过程（OneOffJobBootstrap 的初始化），初始化完成后就可以监听触发作业的 ZNode。

新的节点在加入过程中会创建实例、分片标记等相关 ZNode，也许在这过程中老节点和新节点发生了什么摩擦？

口说无凭，开始验证。

---

问题排查过程

环境说明

基本信息：

➜  ~ uname -a
Linux local-wwj-icu 5.4.0-47-generic #51-Ubuntu SMP Fri Sep 4 19:50:52 UTC 2020 x86_64 x86_64 x86_64 GNU/Linux
➜  ~ java -version
java version "1.8.0_261"
Java(TM) SE Runtime Environment (build 1.8.0_261-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.261-b12, mixed mode)
➜  ~ docker images zookeeper
REPOSITORY          TAG                 IMAGE ID            CREATED             SIZE
zookeeper           3.6.1               6ad6cb039dfa        6 weeks ago         252MB

其中，zookeeper 直接在 K8S 上部署单节点。

➜  ~ kubectl get po -n zk zk36-0 -owide 
NAME     READY   STATUS    RESTARTS   AGE   IP             NODE            NOMINATED NODE   READINESS GATES
zk36-0   1/1     Running   10         16d   10.240.0.150   local.wwj.icu   <none>           <none>

以尽量简洁的方式复现问题

复现问题的关键点

1. 集群中已有就绪的作业实例；
2. 作业调度的同时有新实例加入。

构造复现代码

由于直接使用 DAG 复现问题在排查上会增加一些麻烦，经过一段时间分析后，本人构造了尽量简单的问题复现代码。

完整代码可以在 TeslaCN/reproduce-blocking 找到。

关于 OneOffJobBootstrap，只要任意一个实例的 execute() 被调用，集群中有相应作业的 OneOffJobBootstrap 实例的节点就会分布式地执行作业。

定义作业执行逻辑。
该作业执行逻辑定义了 OneOffJobBootstrap 实例的初始化逻辑，并且只由分片 0 执行 execute() 方法。

import lombok.RequiredArgsConstructor;
import lombok.SneakyThrows;
import lombok.extern.slf4j.Slf4j;
import org.apache.shardingsphere.elasticjob.api.JobConfiguration;
import org.apache.shardingsphere.elasticjob.api.ShardingContext;
import org.apache.shardingsphere.elasticjob.lite.api.bootstrap.impl.OneOffJobBootstrap;
import org.apache.shardingsphere.elasticjob.reg.base.CoordinatorRegistryCenter;
import org.apache.shardingsphere.elasticjob.simple.job.SimpleJob;

import java.util.concurrent.ConcurrentHashMap;
import java.util.concurrent.ConcurrentMap;
import java.util.concurrent.TimeUnit;

@Slf4j
@RequiredArgsConstructor
public final class ScheduleSimpleJob implements SimpleJob {
    
    private static final ConcurrentMap<String, OneOffJobBootstrap> JOBS = new ConcurrentHashMap<>();
    
    private final String scheduleJobName;
    
    private final CoordinatorRegistryCenter registryCenter;
    
    @Override
    public void execute(final ShardingContext shardingContext) {
        JOBS.computeIfAbsent(scheduleJobName, unused -> {
            JobConfiguration jobConfiguration = JobConfiguration.newBuilder(scheduleJobName, 3).build();
            return new OneOffJobBootstrap(registryCenter, new SomeSimpleJob(), jobConfiguration);
        });
        if (0 != shardingContext.getShardingItem()) {
            return;
        }
        log.info("Execute job {} on 0", scheduleJobName);
        executeOneOffJob();
    }
    
    private void executeOneOffJob() {
        JOBS.get(scheduleJobName).execute();
    }
    
    @Slf4j
    public static final class SomeSimpleJob implements SimpleJob {
        
        @SneakyThrows
        @Override
        public void execute(final ShardingContext shardingContext) {
            long since = System.currentTimeMillis();
            log.info("{} [{}] started.", shardingContext.getJobName(), shardingContext.getShardingItem());
            double took = Math.random() * 5000;
            TimeUnit.MILLISECONDS.sleep((long) took);
            log.info("{} [{}] finished. Took {}", shardingContext.getJobName(), shardingContext.getShardingItem(), System.currentTimeMillis() - since);
        }
    }
}

启动类：

import org.apache.shardingsphere.elasticjob.api.JobConfiguration;
import org.apache.shardingsphere.elasticjob.lite.api.bootstrap.impl.ScheduleJobBootstrap;
import org.apache.shardingsphere.elasticjob.reg.base.CoordinatorRegistryCenter;
import org.apache.shardingsphere.elasticjob.reg.zookeeper.ZookeeperConfiguration;
import org.apache.shardingsphere.elasticjob.reg.zookeeper.ZookeeperRegistryCenter;

import java.util.Optional;

public final class ReproduceMain {
    
    public static void main(String[] args) {
        CoordinatorRegistryCenter registryCenter = setupRegCenterFromProperties();
        JobConfiguration jobConfiguration = JobConfiguration.newBuilder("schedule-job", 3).cron("0/30 * * * * ?").build();
        new ScheduleJobBootstrap(registryCenter, new ScheduleSimpleJob("foo",registryCenter), jobConfiguration).schedule();
    }
    
    public static CoordinatorRegistryCenter setupRegCenterFromProperties() {
        String servers = Optional.ofNullable(System.getProperty("zk.servers")).orElseThrow(() -> new IllegalArgumentException("Missing -Dzk.servers"));
        String namespace = Optional.ofNullable(System.getProperty("zk.namespace")).orElseThrow(() -> new IllegalArgumentException("Missing -Dzk.namespace"));
        ZookeeperConfiguration zookeeperConfiguration = new ZookeeperConfiguration(servers, namespace);
        ZookeeperRegistryCenter zookeeperRegistryCenter = new ZookeeperRegistryCenter(zookeeperConfiguration);
        zookeeperRegistryCenter.init();
        return zookeeperRegistryCenter;
    }
}

执行复现代码并分析

执行方法：

1. 启动一个新进程 A，并等待 A 完成一次作业执行；
2. 启动一个新进程 B，等待至下一次作业执行时间，问题复现。

可能因本地环境比较稳定，涉及 Zookeeper 通讯的时间基本是恒定的，硬件资源充足，按照以上方法执行复现代码，问题 几乎必现 。

此时，进程 A 为 Leader 节点，分片为 [1]；进程 B 非 Leader 节点，分片为 [0, 2]。

进程 A 的日志：

进程 B 的日志：

此时进程 A 的分片已经运行完了，但是进程 B 一直处于等待分片的状态。

本次调度最终只有分片 [1] 被执行，分片 [0, 2] 没有被执行。

后续存在两种情况：

1. 如果调用 OneOffJobBootstrap#execute() 的逻辑后续不需要等待作业执行完毕（OneOffJobBootstrap#execute() 是异步方法，不会阻塞），持续等待分片的情况会在下一次作业调度解除，作业分片的执行恢复正常。（即存在 1 次部分分片未执行的情况）
2. 如果 OneOffJobBootstrap#execute() 被调用后阻塞了线程等待执行结果（阻塞 OneOffJobBootstrap#execute() 后面的逻辑，通过监听 Zookeeper ZNode 的运行状态判断执行完毕），则等待分片的状态将会持续下去，影响作业调度。

由于涉及多进程及客户端连接，本人暂时想不到如何 Debug 代码，只能通过日志排查。

通过 Zookeeper CLI 增加 Watches 排查

从 Zookeeper 的 ZNodes 变化可以看出，Leader 已经完成了重新分片并开始执行自己的分片了，但是这时候突然又插入了一个 sharding/necessary 的标记。当非 Leader 实例执行到分片相关的逻辑后，开始循环等待 Leader 完成分片，但是它并不知道 Leader 已经完成分片并开始执行自己的分片了。

通过程序日志排查

在源码中各个分片相关的位置添加了日志输出后，按照前文的问题复现步骤执行复现代码。截取关键部分的日志，将两个进程的日志对比分析。

时间轴

此处先启动的进程称为“老进程”，后启动的进程称为”新进程“。

• [22:31:30,002] 两个节点同步开始调度 OneOffJobBootstrap，其中老进程的 OneOffJobBootstrap 已经有实例存在，新进程的 OneOffJobBootstrap 需要进行实例化。
• [22:31:30,240] 老进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,243] 老进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,246] OneOffJobBootstrap#execute() 方法被其中一个进程调用完毕，TRIGGER 标志都已经写入所有作业实例。
• [22:31:30,248] 老进程的 JobTriggerStatusJobListener 监听到 TRIGGER 标志，调用 JobScheduleController#triggerJob() 方法执行作业。
• [22:31:30,254] 新进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,276] Leader 节点（老进程）开始分片。
• [22:31:30,258] 新进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,276] Leader 节点（老进程）完成分片。
• [22:31:30,287] 新进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,292] 新进程的 ListenServersChangedJobListener 设置 sharding/necessary 标志。
• [22:31:30,295] 新进程的 JobTriggerStatusJobListener 监听到 TRIGGER 标志，调用 JobScheduleController#triggerJob() 方法执行作业。
• [22:31:30,302] 新进程的 Quartz 开始调度 LiteJob#execute() 方法执行作业。
• [22:31:30,305~] 新进程循环等待 Leader 分片完成。从此循环阻塞开始

流程图

PlantUML

原始日志（部分，仅供参考）

• Zookeeper CLI 日志
• 老进程日志
• 新进程日志

初步结论

由于所有节点的 Listener 在监听到 servers 和 instances 变化后都可以写入 sharding/necessary 标志，由于写入次数较多且写入请求来自集群所有节点，写入的时间与 Leader 开始分片的顺序便出现不可控的情况。一旦有 Listener 的 sharding/necessary 标志的写入操作比 Leader 分片慢一拍，就会出现从节点等待分片的死锁情况。

---

总结

问题出现概率

其实一开始我在考虑，现在遇到的这个情况到底是不是 Bug？还是说这是一个特别极端、触发概率特别小或用户使用方式不恰当造成问题？

考虑到以下几点，我还是将这个问题当作 Bug 来看待：

1. 作为 SDK，我们难以考虑到用户所有的场景和所有的使用方式，而且会了解甚至研究源码的用户应该只有很小一部分，我们不能指望用户如何去使用我们的 SDK；
2. 本文所提到的问题有稳定复现的方式，问题复现代码使用的都是向用户提供的 API，属于正常使用方式；
3. 对于一个分布式调度解决方案，出现某一次作业部分分片未执行的不可靠情况应该是不允许的。

问题直接原因

新进程的 ListenServersChangedJobListener 监听到数据变化设置 sharding/necessary 标志时，Leader 节点已经完成了分片。非 Leader 节点只能循环等待直到 Leader 节点分片完成，因此出现循环阻塞等待分片的死锁情况。

解决思路

限制 ListenServersChangedJobListener 仅主节点可设置分片标志

当作业的 server 或 instance 发生变化时，该作业所有节点都会监听到相关变化并设置 sharding/necessary 标志。多个节点同时进行多次写入，如果此时 Leader 节点恰好要进行重新分片，便存在分片完毕后仍然有 sharding/necessary 标志写入的风险。
由 Leader 节点完成 sharding/necessray 的设置，如果不存在 Leader 则对可用实例进行选举，在保证需要重新分片的情况不会被遗漏以外，也让 sharding/necessary 标志的写入更可控。

当作业实例初始化时，无须再次写入 sharding/necessary 标志

以下代码为作业实例初始化过程中的设置过程：

    /**
     * Register start up info.
     * 
     * @param enabled enable job on startup
     */
    public void registerStartUpInfo(final boolean enabled) {
        listenerManager.startAllListeners();
        leaderService.electLeader();
        serverService.persistOnline(enabled);
        instanceService.persistOnline();
        shardingService.setReshardingFlag();
        if (!reconcileService.isRunning()) {
            reconcileService.startAsync();
        }
    }

注册启动信息时，先启动了所有 Listeners，其中就包括了 ListenServersChangedJobListener。此处注册实例即会触发 ListenServersChangedJobListener，无须再调用 shardingService.setReshardingFlag() 设置 sharding/necessary 标志。

https://github.com/apache/shardingsphere-elasticjob/pull/1472

问题延伸

其他会调用 ShardingService#setReshardingFlag() 的地方是否也会存在这个问题？

ListenServersChangedJobListener 所在的外部类下还有另一个 Listener

    class ShardingTotalCountChangedJobListener extends AbstractJobListener {
        
        @Override
        protected void dataChanged(final String path, final Type eventType, final String data) {
            if (configNode.isConfigPath(path) && 0 != JobRegistry.getInstance().getCurrentShardingTotalCount(jobName)) {
                int newShardingTotalCount = YamlEngine.unmarshal(data, JobConfigurationPOJO.class).toJobConfiguration().getShardingTotalCount();
                if (newShardingTotalCount != JobRegistry.getInstance().getCurrentShardingTotalCount(jobName)) {
                    shardingService.setReshardingFlag();
                    JobRegistry.getInstance().setCurrentShardingTotalCount(jobName, newShardingTotalCount);
                }
            }
        }
    }

这个 Listener 会在作业总分片数量发生变化时，写入 sharding/necessary 标志以在下一次作业调度时重新分片。

基于上面的问题复现代码，使用同样的启动步骤，只不过每次启动前修改以下代码中的作业分片数，暂时没有测出问题。