# 故障

业务线测试同学反馈压测时，有以下报错日志：

1
2
3

java.lang.IllegalMonitorStateException: attempt to unlock lock, 
not locked by current thread by node id: def1bd2c-1f49-4802-b635-5ea78543c033 thread-id: 109
	at org.redisson.RedissonLock.unlock(RedissonLock.java:366)

# 先抛结论

建议遇到类似问题的人先检查项目中是否确保了 redissonClient 的单例。（单线程当然也是必须的，不过排查起来很简单，估计看到文章的人首先已经排查过单线程的问题了）

本次报错是因为:

1. redissonClient 虽然是单例的静态成员变量，但初始化时未加锁，而是简单使用

   1 2 3 4 5 6 7 8

   private static RedissonClient redisson = null; public static RedissonClient getRedisson(){ if(redisson == null){ RedissonManager.init(); //初始化 } return redisson; }

2. 加锁解锁没有同一个 lock，而是每次都使用getRedisson().getLock(key) 。导致解锁时从另一个 redissonClient 并没有获取到锁。 换言之，报错里的not locked by current thread by node id: def1bd2c-1f49-4802-b635-5ea78543c033 thread-id: 109 其实关键问题在于by node id ，而不是线程id。

# 定位问题依据

不需要改代码、加日志甚至debug，只需要搜索日志里是否有两行

13:58:07.972 [main] INFO org.redisson.Version - Redisson 2.8.2

打印两次版本信息说明肯定初始化了两次 Redisson。

是的，定位和结论就这么简单，如果能早点知道，我就能省下这十几个小时和一大把头发了。

# 排查过程

# 一、搜索解决方案

把报错信息复制出去很容易就搜到了一些文章遇到类似的报错，解决方式就是解锁前判断是否自己持有的这个锁。

1
2
3

            if(lock.isHeldByCurrentThread()){
                lock.unlock();
            }

并且从“源码”级别解释了lock方法catch了InterruptedException等概念。

# 二、质疑解决方案

很显然加上这一行代码，不会再报错了，但是这给我带来的问题更多了。

1. 自己手写demo里将线程interrupt复现这个问题可以理解，但是我们实际项目中线程被谁interrupt了？

2. 加了if(lock.isHeldByCurrentThread())的确不报错了，但这个线程本质上就没拿到这个分布式锁，在else中还是应该手动抛个异常出去的。轻度压测都出现这种情况，那项目岂不是毫无并发度可言？

3. Redisson 应该也是个成熟的框架了，为什么特地暴露个 lock 接口出来，实际功能只是隐藏掉InterruptedException? 如果我们实际项目中线程被 interrupt 是常态，那暴露这种接口岂不是挖坑？

   1 2 3 4 5 6 7

   public void lock(long leaseTime, TimeUnit unit) { try { lockInterruptibly(leaseTime, unit); } catch (InterruptedException e) { Thread.currentThread().interrupt(); } }

看来问题并非一行代码就能掩盖过去的，事情开始变得有意思了。

# 三、排查线程问题

既然网上文章都说源码里catch 了 InterruptedException，那就研究下源码看是不是有地方会interrupt。

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34

    @Override
    public void lockInterruptibly(long leaseTime, TimeUnit unit) throws InterruptedException {
        long threadId = Thread.currentThread().getId();
      //先获取一次锁试试看
        Long ttl = tryAcquire(leaseTime, unit, threadId);
        // lock acquired
        if (ttl == null) {
            return;
        }
			//拿不到锁就订阅channel
        RFuture<RedissonLockEntry> future = subscribe(threadId);
        commandExecutor.syncSubscription(future);

        try {
          //循环获取锁
            while (true) {
                ttl = tryAcquire(leaseTime, unit, threadId);
                // lock acquired
                if (ttl == null) {
                    break;
                }

                // waiting for message
                if (ttl >= 0) {
                  //事实上通常等锁都会走到这，内部是semaphore在等资源。而发生InterruptedException也是在这里面。
                    getEntry(threadId).getLatch().tryAcquire(ttl, TimeUnit.MILLISECONDS);
                } else {
                    getEntry(threadId).getLatch().acquire();
                }
            }
        } finally {
            unsubscribe(future, threadId);
        }
    }

而这边用到的Semaphore其实是0个permmit的，作用就是用来阻塞线程。

1

this.latch = new Semaphore(0);

再继续深入无非就只有Semaphore和AQS的基础知识了。有处理interrupted的地方，但是没有手动interrupt()的地方。

unlock() 方法则更为简单，就是用脚本去redis查这个锁，解锁。失败的话会报我们遇到的错误。

源码再加上一些手动实验，都无法知道何时被interrupt，此时线程中断的排查似乎走到了死胡同。

# 四、排查client问题

经过一番沟通和折腾，终于测试同学可以压测我的电脑上部署的项目。

前后压了5、6遍，几十万次请求，流量近10倍于压测环境。

然而只有第一次和第三次压复现了异常，而第一次压时发现原项目日志用的还是System.out.println，打印的信息也不完善，无法帮助排查。第三次压刚启动进了异常断点，以为是项目启动有问题，放掉断点跑了十几万次请求都OK。

全部压测结束，最后几次也无法复现问题，到了收工时间，无法再压测。

再回过头看唯一一次有记录的异常日志信息，发现日志里显示的是 “interrupted:false,hold:true”。表明线程没被中断过，但是并不是这个锁的持有者。

只能继续带着更多的问题去做推测&验证。

Q1:会不会是加锁和解锁用到的两个方法各自去获取的lock对象不一致导致的问题？

A1:自己试验了很多遍，两个对象不一致并不影响结果。

Q2:会不会是项目启动的初始化redissonClient没加锁导致了异常？

A2:翻了下日志，项目打印日志多，请求量又特别大，几十万行的日志中找到报错位置和项目启动位置似乎时间间隔有点长，应该不是这个原因。（就是这里第一次错过了正确的答案。。。）

Q3:会不会是因为加锁解锁间隔过短，两个lock对象分别连接了master和slave，主从延迟导致的？(半夜刷牙想到这个，似乎非常有可能，高兴坏了)

A3:第二天来公司用demo验证，用了半天时间，各自改代码，几百上千个线程跑了很多遍都没复现这个问题，redis都打得有节点连接不上了，跑得我都要怀疑人生了。

Q4:试验中发现解锁用到的lock2对象如果是通过redissonClient2获取的，能稳定复现这个问题，是否与我们的项目遇到的异常有关联呢？

A4:再去看了下项目代码，除了初始化redissonClient没加锁之外，运行过程中用的都是静态变量指向的redissonClient，应该是同一个，与这个试验场景不一样。（第二次错过正确答案。。。）

没有了思路，只能逐行debug，走一行看一眼Redisson打的长串日志。

观察发现调用 lock.isHeldByCurrentThread() 等方法其实都是在请求redis，并非像普通的java对象一样读取成员变量。

仔细看每个lock的每次查询是否用了相同的connection，搜索每个connection的id发现，每次并不相同，且应该都是从初始化连接池中拿的。

排除了各种情况的答案后，我发现了请求redis的脚本中元素的key其实有规律，是id+key，而id就是这个client初始化时生成的uuid，稍加验证，很轻松解释了之前的Q4中能稳定复现这个异常的原因。就是多个client就相当于分布式的多个jvm，即使同一个线程，使用的锁id肯定也是不一样的。

因此我又把目光转回了多个client的这个问题，光看代码的确是有这个可能性，现在还需要在错误日志里找到相应的依据去证实自己的猜测。

回到Q2位忽略掉的日志，在vscode中打开庞大的日志文件，CTRL+F搜索异常的时间点等信息，发现了自己之前的一个误解，其实 项目启动!=client初始化， client是等到请求打过来才初始化的。

再稍加搜索，虽然日志中没有打印client的id，但是两个不同的线程打印了两次Redission的版本信息便足以佐证我的猜测了。

# 反思

十几个小时的排查过程虽然学到了很多，但是自己的几个失误其实大大拉长了这痛苦的时间。

1. 没有第一时间去加日志，压测，复现问题。

   如果在原项目中加上日志看下锁的 isInterrupted() 和 isHeldByCurrentThread()状态，其实很快就能发现线程根本没有被 interrupt，不用往那个方向排查。

   1 2	log.info("lock:" + lock.toString() + ",interrupted:" + Thread.currentThread().isInterrupted() + ",hold:" + lock.isHeldByCurrentThread() + ",threadId:" + Thread.currentThread().getId());

2. 多次错过了正确答案。

其实也主要是因为不是自己的项目，在改代码、发布、压测、日志、监控这些方面都缺乏掌控，因此难免走了一些弯路。