定时任务分布式锁bug——@scheduled单线程 & jedis线程不安全

2019-10-24 发布
2022-2-7 修改
1.
第一个坑，生产环境上2台服务器，9点整跑A、B2个定时任务。每个任务都检查redis锁，任务内容会发邮件。结果每天都会收到A、B任务的重复邮件，说明任务在A、B服务器上都被执行了。
观察日志得出：

	第一台服务器	第二台服务器
9:00-9:02	获得锁A，执行任务A，释放锁A	获得锁B，执行任务B
9:03-9:05	获取锁B失败	释放锁B 获取锁A，执行任务A，释放锁A

推理结论：每台服务器上定时任务都在排队，不是并行执行，而是串行执行。所以可能一台服务器执行完任务，释放了锁之后，另一台服务器才请求锁，也获取锁成功。
原因：@shcheduled 默认单线程
解决：springboot下需要添加配置类，重写方法，增加线程池

import lombok.extern.slf4j.Slf4j;
import org.springframework.context.annotation.Configuration;
import org.springframework.scheduling.annotation.EnableScheduling;
import org.springframework.scheduling.annotation.SchedulingConfigurer;
import org.springframework.scheduling.concurrent.ThreadPoolTaskScheduler;
import org.springframework.scheduling.config.ScheduledTaskRegistrar;

/**
 * @author xinjie_guo
 * @version 1.0.0 createTime:  2019/10/23 11:18
 * @description
 */
@Slf4j
@Configuration
@EnableScheduling
public class ScheduleConfig implements SchedulingConfigurer {
    @Override
    public void configureTasks(ScheduledTaskRegistrar taskRegistrar) {
        ThreadPoolTaskScheduler taskScheduler = new ThreadPoolTaskScheduler();
        taskScheduler.setPoolSize(5);
        taskScheduler.initialize();
        taskRegistrar.setTaskScheduler(taskScheduler);
    }
}

坑2，更加隐蔽。
当天12点更新了项目。定时任务能并发执行。
当天13点，定时任务C能顺利执行，没有发出重复邮件。
当天17点，定时任务D能顺利执行，没有发出重复邮件。
次日9点，定时任务A、B，只有A发出一封邮件，B在两台服务器上均获取锁失败。
观察日志：
锁B在当天9点正常上锁，解锁。锁B再次日9点只有获取锁失败的日志，在此之前找不到上锁日志。
经过探索，发现锁B已被锁上，且没有被设置过期时间（用默认过期时间），且两台服务器均未能获取到锁B。

locked = redisStringCacheHelper.setNX(lockKey, "locked");
if (locked) {
    redisStringCacheHelper.expire(lockKey,timeOut);
     log.info("method:{}获取锁:{},开始运行！",cacheMethod,lockKey);
     pjp.proceed();
     return;
 }
在这里插入代码片

观察代码：锁B未设置超时时间，locked必然为false，锁B被锁上，setNX必定成功的设置redisKey了。
推理猜想：jedis多线程产生bug，setNX上锁成功，但返回了false。
理论依据：1. 虽然setNX和expire操作没有满足原子性，但是日志中没有捕获异常。我们知道如果在setNX和expire之间如果抛出异常，会导致资源死锁。这是个风险点，后续要修复掉，但应该不是错误原因。
2. jedis本身线程不安全，jedis靠jedis pool多个连接保证线程安全。网上查到，如果并发请求过多，2个请求使用了同一个连接，会产生异常或获得混乱的结果。
事实依据：昨天13点、17点各只跑一个定时任务，并发量小，今天早上9点跑2个定时任务，并发量高。昨天没出错，今天出错，变化的变量只有jedis的并发量。
错开了9点定时任务的时间解决了问题，猜想未有直接证据证实。下个版本修复了redis锁原子性问题。