XXL-JOB任务中执行带超时控制的纯串行LiteFlow流程导致的日志混乱问题

前言

组件版本

组件	版本
XXL-JOB	2.0.2
Lite Flow	2.12.4.1
Spring Boot	2.6.13
Java	11

业务场景

出于数仓管理需要，笔者使用XXL-JOB和LiteFlow开发了一个简单的物化视图刷新流程调度任务，由XXL-JOB发起调度，在SpringBoot中根据任务配置动态生成LiteFlow流程并执行，生成的流程均为串行执行（THEN），应用通过JDBC和StarRocks交互。

问题描述

功能部署上线后，将两个旧的刷新流程迁移到了基于LiteFlow的刷新流程，新流程执行后出现了任务日志缺失、出现其他任务日志的情况；旧流程任务日志如下：

旧流程执行使用的XXL-JOB的任务线程，可以观察到其线程名称全部为Thread-51，此时流程正常运行，日志正常打印；新流程任务日志如下：

可以观察到开头打印【----------- XXL-JOB job execute start -----------】日志的线程和打印流程执行信息的线程是不一致的，而且存在多个【when】开头的流程执行线程。

排查过程

基于上面的现象和日志信息，初步推测是不同线程的ThreadLocal传值问题导致，最初笔者以为是XXL-JOB存放日志文件路径的ThreadLocal没考虑到父子线程ThreadLocal传值的问题，但是观察发现有些任务日志中是能正常打印部分日志的，查看XXL-JOB源码，发现确实是考虑到了父子线程传值问题的：

package com.xxl.job.core.log;

public class XxlJobFileAppender {
	private static Logger logger = LoggerFactory.getLogger(XxlJobFileAppender.class);
	
	// for JobThread (support log for child thread of job handler)
	//public static ThreadLocal<String> contextHolder = new ThreadLocal<String>();
	public static final InheritableThreadLocal<String> contextHolder = new InheritableThreadLocal<String>();
}

基于InheritableThreadLocal的子线程会在创建时继承父线程的ThreadLocal变量值作为初始值。不是ThreadLocal传值的问题，观察发现流程执行过程中存在多个不同的when线程，推测LiteFLow执行串行流程时并没有直接使用原线程执行，而是提交到线程池中执行的，LiteFlow流程表达式为：

THEN(
	node("refreshMvHandleEventGroup").tag("0").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("1").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("2").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("3").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("4").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("5").maxWaitSeconds(900),
	node("refreshMvHandleEventGroup").tag("6").maxWaitSeconds(900),
	node("refreshMvHandleFlowSuccess").retry(3)
).maxWaitSeconds(1800);

配置有重试和超时，在本地DEBUG发现配置了超时的流程会被解析为com.yomahub.liteflow.flow.element.condition.TimeoutCondition，其底层调用的WhenCondition#executeAsyncCondition异步执行的：

package com.yomahub.liteflow.flow.element.condition;

public class WhenCondition extends Condition {
	@Override
	public void executeCondition(Integer slotIndex) throws Exception {
		executeAsyncCondition(slotIndex);
	}
}

查询LiteFlow官方文档发现，默认配置when表达式是全局共用一个线程池来执行的：

package com.yomahub.liteflow.thread;

public class LiteFlowDefaultWhenExecutorBuilder implements ExecutorBuilder {

	@Override
	public ExecutorService buildExecutor() {
		LiteflowConfig liteflowConfig = LiteflowConfigGetter.get();
		// 只有在非spring的场景下liteflowConfig才会为null
		if (ObjectUtil.isNull(liteflowConfig)) {
			liteflowConfig = new LiteflowConfig();
		}
		return buildDefaultExecutor(liteflowConfig.getWhenMaxWorkers(), liteflowConfig.getWhenMaxWorkers(),
				liteflowConfig.getWhenQueueLimit(), "when-thread-");
	}

}

继续往上面翻源码发现LiteFlow底层的when线程池采用了阿里的TTL进行包装，查看文档简单了解了下这个库，结合前面出现问题得出结论：线程池的线程复用，导致子线程的InheritableThreadLocal变量值只会保持在创建那一刻的状态。
这也能解释为什么前面会出现缺部分日志和串日志的问题：when线程池的XXL-JOB日志文件路径ThreadLocal变量值保持在第一次创建线程时的值，如果任务中使用的when线程为第一次创建，则能正常输出日志到正确文件；如果不是第一次创建，则会使用ThreadLocal中之前存在的日志文件路径进行日志输出，就出现了当前任务缺日志，其他任务多日志的情况。

解决方案

思考之后，在不动LiteFlow源码的情况下，有两个解决方案：

1. 在LiteFlow每个会调用XXL-JOB日志输出的节点中手动设置一下日志输出文件路径ThreadLocal的值（启动流程时需要将该值传入流程的上下文或流程数据中）
2. 反射Hook一下XXL-JOB保存日志输出文件ThreadLocal静态变量，修改为TTL的TransmittableThreadLocal

方案一需要在每个节点硬编码，既不优雅也不高效，不推荐使用：

XxlJobFileAppender.contextHolder.set("xxx");

方案二仅需在启动时反射修改一次，其他地方无需改动，推荐使用（注意，Hook操作需要在任意XXL-JOB任务执行前完成）：

public static void hookXxlJob() {
    try {
        Field contextHolderField = XxlJobFileAppender.class.getField("contextHolder");
        // 设置字段可访问
        contextHolderField.setAccessible(true);
        // 去除final修饰符的影响，将字段设为可修改的
        Field modifiersField = Field.class.getDeclaredField("modifiers");
        modifiersField.setAccessible(true);
        modifiersField.setInt(contextHolderField, contextHolderField.getModifiers() & ~Modifier.FINAL);
        // 设置ThreadLocal为TTL
        contextHolderField.set(null, new TransmittableThreadLocal<String>());
        log.info("反射修改XXL-JOB日志文件ThreadLocal为TransmittableThreadLocal完成: {}", XxlJobFileAppender.contextHolder.getClass());
    }catch (Throwable e) {
        log.error("反射修改XXL-JOB日志文件ThreadLocal失败", e);
    }
}

修改完成后XXL-JOB调度任务执行LiteFlow流程日志正常打印：

XXL-JOB的Thread线程和LiteFlow的when线程池打印的日志正常，没有缺失也没有串入其他任务日志。

总结

带超时控制的纯串行LiteFlow流程，在引擎执行时会走when线程池，导致了XXL-JOB日志混乱的问题；通过反射修改XXL-JOB存放日志文件路径的ThreadLocal为TTL解决了问题。