这个Jedis的坑你肯定没踩过!记一次深坑排查过程

背景

上周四晚上,月黑风高Coding夜,在公司的角落里,埋头研究研究webflux,组里的同事小D过来说碰到一个诡异的Redis的问题:

在UT(单元测试)中,通过Jedis的client执行lua脚本,每次都是lua脚本正常执行正常返回,但是Redis服务器挂了,执行其他的命令(非lua脚本)就没这个问题。client连接的是开发环境的Redis服务器,版本是2.8。但是连接本地启动的Redis服务器(5.x版本)就不会出现这个情况。

没有查到什么原因,找我帮忙一块看下。

作为一个有技术追求的人,碰到这种诡异的问题,果断不会错过研究的机会的。

这个问题花了好几个小时才查到,期间走了不少弯路,这篇文章记录下整个问题的排查过程。

复现

碰到诡异(神奇)的问题,首先就是要想办法复现。只要是能稳定复现的问题,肯定是能查到原因的,只是有些问题可能花的时间比较长而已。对于不能稳定复现的问题,那就只能通过log等方式记录案发现场了然后根据记录的现场进行排查了。

幸好这次这个问题是百分百复现的.

首先看UT的代码,如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
@SpringBootTest(classes = ApplicationStarter.class, properties = {"spring.profiles.active=test"})
public class LuaServiceTest extends AbstractTestNGSpringContextTests {

@Resource
private Jedis jedis;

@Test
public void testExecuteLuaScript() {
String skuId = "1234567";
String phone = "1234567";
String orderId = "123456";
String countKey = RedisHelper.key(skuId, phone, "count");
String orderKey = RedisHelper.key(skuId, phone, "order");
Object result = jedis.eval(LuaScript.DECREASE_COUNT, Arrays.asList(countKey, orderKey), Arrays.asList(orderId, "100"));
System.out.println("evel result is " + result.toString());
}
}

代码很简单,生成redis的key和参数,然后直接调用jedis.eval()方法执行预先写好的lua脚本,lua脚本如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
local countKey=KEYS[1];
local orderKey=KEYS[2];
local orderId=ARGV[1];
local count= tonumber(redis.call('get',countKey) or 0);
if (count<1) then
return -1;
end
local orderIds=tostring(redis.call('get',orderKey) or '');
local i,j=string.find(orderIds,orderId);
if(i==nil) then
return 0;
end
local newOrderIds=string.gsub(orderIds,'_'..orderId,'');
redis.call('set',orderKey,newOrderIds);
redis.call('decr',countKey);
return 1;

lua代码看过去也没啥问题,然后开始测试,测试结果输出如下:

ut.png

表明ut正常执行通过(先不管执行结果对不对,整个流程是通的就OK)。

再来看Redis服务器的日志:

redis.png

从Redis日志输出看Redis进程的确已经结束了。

好,已复现。

排查

既然已经复现了,那可以来排查了。

第一次排查

首先看下Redis服务器这边的输出日志,日志里面有一句很明显的线索:

redis2.png

1
[34238] 09 Mar 16:37:56.035 # User requested shutdown...

意思很明显,是用户自己请求关闭的。

难道是代码里面主动关闭的?

重新回去看下Jedis的源码,Jedis里面的确有个方法名叫shutdown的方法:

1
2
3
4
5
6
7
8
9
10
public String shutdown() {
client.shutdown();
String status = null;
try {
status = client.getStatusCodeReply();
} catch (JedisException ex) {
status = null;
}
return status;
}

client.shutdown()方法的底层实现是给Redis服务器发送shutdown命令(只有shutdown()这一个方法能够发送shutdown命令给服务器):

1
2
3
public void shutdown() {
sendCommand(SHUTDOWN);
}

这的确是会导致Redis服务器关闭,

回去重头重新看了下ut的代码,没有看到任何地方有jedis.shutdown()方法,且在项目里面全局搜了下,也没有搜到任何其他地方调用shutdown()方法,此时脑子里面就有了一个潜意识:

既然我代码里面没有显示调用shutdown(),jedis客户端也不可能莫名其妙的去给我调用shutdown()吧?那肯定不是不是client发送的。

要确认是不是client发送了shutdown命令,只需要去Redis服务器上看下到底有没有接收到shutdown命令吧,查了下,Redis提供了了monitor命令,可以查看服务器处理的每一个命令.重新启动Redis服务器,通过redis-cli连接服务器,并执行monitor命令,然后重新启动UT执行,monitor输出结果如下:

monitor.png

可以看到,并没有输出shutdown命令,所以更加坚信客户端并没有发送shutdown命令

此时已经认定了客户端没有什么问题,那么只有可能是Redis服务器的问题了,现在来服务端排查下:

服务端的信息很有限,目前获取到的有用的信息只有# User requested shutdown...这一句话了。那就根据这句话来排查吧。

首先在Redis的源码里面全局搜索User requested shutdown...这句话,在prepareForShutdown()方法中搜到了这句话:

1
2
3
4
5
6
7
int prepareForShutdown(int flags) {
int save = flags & SHUTDOWN_SAVE;
int nosave = flags & SHUTDOWN_NOSAVE;

serverLog(LL_WARNING,"User requested shutdown...");
// 其他省略代码
}

看方法名是在Redis服务器准备shutdown的时候调用的,接着查看下是在哪里调用了prepareForShutdown()这个方法,查找结果如下:

shutdown.png

Redis源码中有两处调用到了这个函数,第一次是在serverCron()研究过Redis源码的同学应该都知道这个方法是干嘛的`方法里面:

1
2
3
4
5
6
7
8
9
10
11
12
int serverCron(struct aeEventLoop *eventLoop, long long id, void *clientData) {
// 其他省略代码
/* We received a SIGTERM, shutting down here in a safe way, as it is
* not ok doing so inside the signal handler. */
if (server.shutdown_asap) {
if (prepareForShutdown(SHUTDOWN_NOFLAGS) == C_OK) exit(0);
serverLog(LL_WARNING,"SIGTERM received but errors trying to shut down the server, check the logs for more information");
server.shutdown_asap = 0;
}

// 其他省略代码
}

第二处是在restartServer()方法中:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
int restartServer(int flags, mstime_t delay) {

// 其他省略代码

/* Perform a proper shutdown. */
if (flags & RESTART_SERVER_GRACEFULLY &&
prepareForShutdown(SHUTDOWN_NOFLAGS) != C_OK)
{
serverLog(LL_WARNING,"Can't restart: error preparing for shutdown");
return C_ERR;
}

// 其他省略代码
}

既然只有这两个地方会调用到这个方法,那我就在这两处加断点,心想肯定会执行到吧。

好,加断点,启动UT,走你,见证奇迹的时候到了。

诶,什么情况, Redis日志都输出User requested shutdown...并且关闭了,断点都没进来!!

这不科学吧,见鬼了!!内心简直要抓狂!

接下来该怎么排查呢?

小D反馈的信息是连接开发机上的Redis服务器执行lua脚本就会出现这个问题,连接本地的Redis就不会有问题,且只有在执行lua脚本的情况下会出现这个问题。

这里有两个关键点:

  1. 版本不同。开发机上面运行的Redis的版本是2.8.11,本机的Redis版本是5.x。
  2. 只有在执行lua脚本的猜出出现这个问题。

突然灵光一闪(实际上是宇神提醒的):可以去Github上看Redis版本的Release Note,说不定能发现什么。

说干就干,找到Redis的RELEASE NOTE:
在页面上全局搜索lua关键字,还真搜出点东西来了

lua.png

在2.8.14版本中修复了一个lua脚本引起的Redis crash的问题:当lua脚本第一次分配的时候如果保存了argv的长度就会引起crash。这个bug是2.8、10引起来的。

跟这个问题情况很像啊:版本是2.8.11,应该存在这个bug,且lua脚本的确引用了argv参数,查了半天该不会是redis本身的bug吧。

(心里暗爽:要真是查出了redis的bug,虽然是老版本中且已经修复了的,那还是有的吹的:某年某月某时,在跟Antirez神交之后,指出了他曾经犯过的错~~ 而且Antirez太’卑鄙’了,明明是crash了,还非要说是用户自己关闭的!哼!)

然后我就跟小D说,有可能是redis本身的bug引起的,你升一哈版本再看下复现。

然后就下班了,第一次排查到此结束。

第二次排查

第二天下午的时候,小D来给我说,升了版本也不行,而且现在连接本启动的Redis 5.x的版本也不行,执行完之后服务器一样会被关闭。

额,这。。。这消息跟之前的不太一样啊,我心里这么想着。

这样啊,那咱们得继续排查了。先总结下当前的线索吧:

  1. 在ut里面使用Jedis客户端连接Redis服务器执行lua脚本,脚本正常执行,正常返回。然后Redis服务器会打印出User requested shutdown...并关闭。
  2. 1中描述的行为跟Redis版本没关系,最新的5.x版本也是会出现一样的情况。
  3. 已经排查到客户端不会给服务器发送shutdown命令。
  4. 只有在执行lua脚本的时候才会出现这个情况。

第一点和第二点是已经确定的现象,第三点是昨天排查得到的结论,第四点是从小D那得到的信息。

前面两点是确认的,后面两点还是在确认下。

首先是第三点:要确认客户端到底有没有发出shutdown命令。有两种方式可以确认:

  1. 在客户端机器上面通过tcpdump命令查看客户端发出去的报文中有没有shutdown数据。
  2. 排查Redis服务器到底有没有收到shutdown命令。可以在Redis服务器上在SHUTDOWN命令执行的地方断点,看断点能否进来。如果能进来,说明的确是客户端发送了shutdown命令。(第一次排查是通过monitor命令的,这样是有问题的,后面会提到)。

选择第二种方式:在shutdownCommand()函数入口加断点,重新执行ut:

进了!进了!国足进球了!(黄健翔附体)

不好意思,串场了!

shutdownCommand()方法的断点进来了!

shutdownCommand.png

说明客户端的确发送了shutdown命令

shutdownCommand()方法实现,里面明明有调用prepareForShutdown()方法,那为啥昨天第一次排查的时候查找哪些地方调用了prepareForShutdown()方法的时候没有搜到shutdownCommand()呢?

排查了一下Redis的源码发现:

  1. server.h文件中声明了方法int prepareForShutdown();。这个方法没有带参数。
  2. server.c中实现了方法int prepareForShutdown(int flags)。这个方法实际上是个重载的方法。
  3. shutdownCommand()方法是在db.c文件中实现的。db.c引入了db.h头文件,db.h中引入了server.h头文件。

IDE(CLion)看来,db.c中的shutdownCommand()实际上调用的是server.h中声明的不带参数的prepareForShutdown()方法。

sd.png

所以昨天搜多哪些地方调用了server.c中实现的shutdownCommand(flag)方法时没有搜到shutdownCommand()方法。

其实,这里我有个疑惑:根据我已经过期了的C/C++的知识判断,我觉得这里应该会报错吧,在头文件中声明了int prepareForShutdown()方法,但是从头到尾都都没有实现,难道不应该报错吗?为啥还能正常的运行?求大神解答!

到目前为止,已经确定了客户端的确是发送了shutdown命令,那么就跟Redis服务器没啥关系了,Redis服务器只是正常的执行客户端的请求(所以跟Redis的版本没有任何关系)。

那现在着重来看下客户端的代码了。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
@SpringBootTest(classes = ApplicationStarter.class, properties = {"spring.profiles.active=test"})
public class LuaServiceTest extends AbstractTestNGSpringContextTests {


@Resource
private Jedis jedis;

@Test
public void testExecuteLuaScript() {
String skuId = "1234567";
String phone = "1234567";
String orderId = "123456";
String countKey = RedisHelper.key(skuId, phone, "count");
String orderKey = RedisHelper.key(skuId, phone, "order");
System.out.println(">>>>>>>> begin eval");
Object result = jedis.eval(LuaScript.DECREASE_COUNT, Arrays.asList(countKey, orderKey), Arrays.asList(orderId, "100"));
System.out.println(">>>>>>>> evel result is " + result.toString());
}

}

排查问题的最高境界就是人肉debug:只要看代码就能看出问题所在。

在盯着这段代码苦思冥想几分钟后,我终于得出了一个结论:

恩,我还没这水平。-_-

既然肉眼不行,那就只有手动debug了。

当前确认且正确的线索是:

  1. 客户端的lua代码正常执行、正常返回。
  2. 服务器能正常接收lua脚本,正常执行,返回。
  3. 客户端不知道什么时候给服务器发送了shutdown命令。
  4. 服务器接收shutdown命令,持久化并关闭服务器。
  5. 客户端代码没有显示的给调用jedis.shutdown()给服务器发送SHUTDOWN命令。

根据上面的线索:既然自己没有调用jedis.shutdown(),那么肯定是其他地方调用了jedis.shutdown()方法。现在需要确认的就是在谁在什么时候在哪里调用的jedis.shutdown()

还有一点可已确认的是,jedis.shutdown()方法肯定是在jedis.eval()之后被调用的

现在可以debug了。首先在执行testExecuteLuaScript()方法的最后一行打断点(断点A),然后是在jedis.shutdown()(BinaryJedis.java文件中)打断点(断点B)。

启动程序, 首先执行到断点A,eval()正常返回,按照我的预期,这个时候单步调试(Command+F8)应该会调到调用jedis.shutdown()方法的地方,结果程序直接执行到了断点B。

没有调到执行jedis.shutdown()的地方。

突然灵光一闪:会不会是因为testExecuteLuaScript()程序执行结束,然后springboot框架释放Jedis资源的时候调用了shutdown()方法?

转念一想,应该不至于这么傻逼吧,程序结束顶多释放资源关闭连接而已,怎么可能会把服务器给关闭掉啊?

不管是不是,反正现在也没其他思路了,就先试试这种可能性吧,万一真的这么傻逼呢?

这个其实很好验证:当程序进入断点A之后,停留几分钟,看下这几分钟之内Redis服务器会不会被shutdown(接收到shutdown命令)。如果不会,取消断点,继续执行,看程序会不会进入断点B(执行jedis.shutdown()方法)。

作为行动派,立马做起来。

20:20分程序进入断点A,并在A出停留3分钟,此时Redis服务器一直正常运行,没有收到SHUTDOWN命令。继续执行,果然,程序进入断点B,继续执行,Redis服务器输入# User requested shutdown...并关闭。

redis3.png

天哪(小岳岳表情)!难道真的这么傻逼!程序运行结束就把服务器给关闭了!!??

为了验证我这个想法,我决定:不在ut里面执行,在controller里面写一个接口,接口里面执行一样的代码。看代码执行之后会不会发出shutdown命令Redis关闭服务器。停止项目,看会不会发出shutdown命令Redis关闭服务器。

controller.png

实验结果发现:每次调用api/jedis/test接口之后Redis服务器正常运行,但是

关闭项目(IDEA里面的停止按钮,kill pid)之后,程序都会进入到jedis.shutdown()方法中执行,发送SHUTDOWN命令给Redis服务器关闭Redis服务器

进行到这里,基本上已经有结论了:

每次程序结束的时候,spring会释放Jedis资源,继而会执行jedis.shutdown()方法。shutdown()方法会给Redis服务器发送SHUTDOWN命令,从而出现服务器输出# User requested shutdown...并保存关闭数据库了。(根据这个分析,可以推断出跟执行lua脚本没关系,后来验证了下,的确没啥关系,只要注入了Jedis对象,都会出现一样的情况。说明小D给的信息有误啊。😢)

那么问题又来了,根据上面的分析,只要使用Jedis的包并注入了Jedis对象,在程序结束的时候都会关闭服务器,这样太不合理了吧?简直丧心病狂啊!!Jedis不至于傻逼的这个程度吧?如果真这样的话,还会有人用Jedis吗?

我觉得Jedis不至于这么傻逼的,所以肯定还是有哪里有问题的。

继续排查!

我们都知道,Spring管理的bean都是有生命周期的,其中一个就是销毁阶段:在程序结束之后会销毁对象,释放资源,在销毁前会执行指定的方法。

在Spring里面指定销毁前的方法有以下几种方式:

  1. 指定destroy-method方法。
  2. 实现DisposableBean接口。
  3. 在类的方法上加上@PreDestroy注解。

除了Spring的方式外,Java7引入了AutoCloseable接口,所有实现了AutoCloseable接口的对象会自动调用close()方法。

从表象上来看,出现上面描述的情况,应该是Jedis把shutdown()方法指定为销毁的时候的destoryMethod了。

来看下Jedis的继承类图:

jedis.png

Jedis并没有实现DisposableBean接口,shutdown()方法也没有打上@PreDestroy注解

shutdown1.png

更没有指定destroy-method方法。同样的,Jedis也没有实现AutoCloseable接口。

那么为什么在程序执行结束释放资源的时候会调用jedis.shutdown()方法呢?

既然这个问题想不通,何不从入口出发:Jedis对象是由Spring进行管理并注入的,我们可以从Spring源码入口,看一哈生成Jedis对象的过程中到底发生了哪些事。

作为第一次看Spring IoC源码的人表示:Spring的源码真的超复杂,看起来太绕了!😢

从Main函数一步一步断点单步调试,跟踪到AbstractApplicationContext.refresh()方法中

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
public void refresh() throws BeansException, IllegalStateException {
synchronized (this.startupShutdownMonitor) {
// Prepare this context for refreshing.
prepareRefresh();

// Tell the subclass to refresh the internal bean factory.
ConfigurableListableBeanFactory beanFactory = obtainFreshBeanFactory();

// Prepare the bean factory for use in this context.
prepareBeanFactory(beanFactory);

try {

// 其他省略代码

// Instantiate all remaining (non-lazy-init) singletons.
// 初始化所有的非延迟加载的单例bean
finishBeanFactoryInitialization(beanFactory);

// Last step: publish corresponding event.
finishRefresh();
}

catch (BeansException ex) {
// 其他省略代码
}

finally {
// Reset common introspection caches in Spring's core, since we
// might not ever need metadata for singleton beans anymore...
resetCommonCaches();
}
}
}

refresh()方法里面会调用finishBeanFactoryInitialization(beanFactory);生成所有的非延迟加载的单例的对象,跟踪进去看:

1
2
3
4
5
6
7
8
protected void finishBeanFactoryInitialization(ConfigurableListableBeanFactory beanFactory) {

// 其他省略代码

// Instantiate all remaining (non-lazy-init) singletons.
// 初始化所有剩余的非延迟加载的单例bean
beanFactory.preInstantiateSingletons();
}

finishBeanFactoryInitialization()方法中会调用传入的beanfactory.preInstantiateSingletons()完成初始化单例对象的工作。

继续往下跟踪到DefaultListableBeanFactory.preInstantiateSingletons()方法中

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
@Override
public void preInstantiateSingletons() throws BeansException {
if (this.logger.isDebugEnabled()) {
this.logger.debug("Pre-instantiating singletons in " + this);
}

// Iterate over a copy to allow for init methods which in turn register new bean definitions.
// While this may not be part of the regular factory bootstrap, it does otherwise work fine.
List<String> beanNames = new ArrayList<String>(this.beanDefinitionNames);

// Trigger initialization of all non-lazy singleton beans...
for (String beanName : beanNames) {
RootBeanDefinition bd = getMergedLocalBeanDefinition(beanName);
if (!bd.isAbstract() && bd.isSingleton() && !bd.isLazyInit()) {
// 其他省略代码
}
else {
getBean(beanName);
}
}
}

// Trigger post-initialization callback for all applicable beans...
// 其他省略代码
}

这个方法中会调用getBean()方法生成具体的对象,继续往下看:

1
2
3
4
@Override
public Object getBean(String name) throws BeansException {
return doGetBean(name, null, null, false);
}

实际上调用的是doGetBean()方法:

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
protected <T> T doGetBean(
final String name, final Class<T> requiredType, final Object[] args, boolean typeCheckOnly)
throws BeansException {
// 其他省略代码
try {
// 生成rootBeandefinition
final RootBeanDefinition mbd = getMergedLocalBeanDefinition(beanName);
// Create bean instance.
// 如果是单例,则生成对象
if (mbd.isSingleton()) {
sharedInstance = getSingleton(beanName, new ObjectFactory<Object>() {
@Override
public Object getObject() throws BeansException {
try {
// 生成实际的bean
return createBean(beanName, mbd, args);
}
catch (BeansException ex) {
// 其他省略代码
}
}
});
// 其他省略代码
}
}
}
// 其他省略代码
return (T) bean;
}

doGetBean()方法是调用createBean()方法来生成Bean,

1
2
3
4
5
6
7
8
9
protected Object createBean(String beanName, RootBeanDefinition mbd, Object[] args) throws BeanCreationException {
// 其他省略代码
// 实例化beanInstance
Object beanInstance = doCreateBean(beanName, mbdToUse, args);
if (logger.isDebugEnabled()) {
logger.debug("Finished creating instance of bean '" + beanName + "'");
}
return beanInstance;
}

同样的,createBean()是委托doCreateBean()方法实例化对象,

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
35
36
37
38
39
40
41
42
43
protected Object doCreateBean(final String beanName, final RootBeanDefinition mbd, final Object[] args)
throws BeanCreationException {

// Instantiate the bean.
// 实例化bean
BeanWrapper instanceWrapper = null;
if (mbd.isSingleton()) {
instanceWrapper = this.factoryBeanInstanceCache.remove(beanName);
}
if (instanceWrapper == null) {
// 实例化对象
instanceWrapper = createBeanInstance(beanName, mbd, args);
}

// ... 其他省略代码

// Initialize the bean instance.
// 初始化bean
Object exposedObject = bean;
try {
populateBean(beanName, mbd, instanceWrapper);
if (exposedObject != null) {
exposedObject = initializeBean(beanName, exposedObject, mbd);
}
}
catch (Throwable ex) {
// ... 其他省略代码
}

// ... 其他省略代码

// Register bean as disposable.
// 如果有必要的话,把bean注册为disposable
try {
registerDisposableBeanIfNecessary(beanName, bean, mbd);
}
catch (BeanDefinitionValidationException ex) {
throw new BeanCreationException(
mbd.getResourceDescription(), beanName, "Invalid destruction signature", ex);
}

return exposedObject;
}

doCreateBean()方法中,首先会调用createBeanInstance()方法生成对象,接着会调用populateBean()方法初始化对象。

同志们,注意了,关键时候到了!!!

在初始化之后,doCreateBean()方法会调用registerDisposableBeanIfNecessary()方法判断是否有必要把新生成的Bean对象注册为DisposableBean

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
protected void registerDisposableBeanIfNecessary(String beanName, Object bean, RootBeanDefinition mbd) {
AccessControlContext acc = (System.getSecurityManager() != null ? getAccessControlContext() : null);
if (!mbd.isPrototype() && requiresDestruction(bean, mbd)) {
if (mbd.isSingleton()) {
// Register a DisposableBean implementation that performs all destruction
// work for the given bean: DestructionAwareBeanPostProcessors,
// DisposableBean interface, custom destroy method.
// 注册成为DisposableBean
registerDisposableBean(beanName,
new DisposableBeanAdapter(bean, beanName, mbd, getBeanPostProcessors(), acc));
}
else {
// ... 其他省略代码
}
}
}

registerDisposableBeanIfNecessary()方法中,会先调用requiresDestruction(bean, mbd)方法判断是否需要把Bean对象注册成为DisposableBean

1
2
3
4
5
protected boolean requiresDestruction(Object bean, RootBeanDefinition mbd) {
return (bean != null &&
(DisposableBeanAdapter.hasDestroyMethod(bean, mbd) || (hasDestructionAwareBeanPostProcessors() &&
DisposableBeanAdapter.hasApplicableProcessors(bean, getBeanPostProcessors()))));
}

首先调用DisposableBeanAdapter.hasDestroyMethod(bean, mbd)

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
public static boolean hasDestroyMethod(Object bean, RootBeanDefinition beanDefinition) {
// 如果bean实现了DisposableBean接口或者实现了java.lang.AutoCloseable接口,则直接返回true,表示要注册成为DisposableBean
if (bean instanceof DisposableBean || closeableInterface.isInstance(bean)) {
return true;
}
// 获取bean指定的destoryMethodName
String destroyMethodName = beanDefinition.getDestroyMethodName();

if (AbstractBeanDefinition.INFER_METHOD.equals(destroyMethodName)) {
// 如果指定的方法名是字符串 (inferred),则
// 首先判断Bean对象中方法中有没有名为close()的方法,如果没有的话,在判断有没有
// 名为shutdown的方法
return (ClassUtils.hasMethod(bean.getClass(), CLOSE_METHOD_NAME) ||
ClassUtils.hasMethod(bean.getClass(), SHUTDOWN_METHOD_NAME));
}
// 如果用户自己指定且不为空,则返回true,注册为DisposableBean,如果指定为空串则不注册
return StringUtils.hasLength(destroyMethodName);
}

hasDestroyMethod()方法中,会

  1. 判断bean对象有没有实现DisposableBean接口或者java.lang.AutoCloseable接口,如果有的话则返回true表示注册为DisposableBean
  2. 获取bean指定的destoryMethodName。如果没有指定的话,Spring会默认为(inferred),表示由Spring自己来推断。
  3. Spring会首先判断Bean对象有没有一个名字叫做close的方法,如果没有的话,则继续判断有没有名为shutdown的方法,有的话则返回true注册为DisposableBean
  4. 如果都没有,则判断指定的destoryMethodName是否为空串,如果不是则返回true注册成为DisposableBean,否则不注册。

继续回到registerDisposableBeanIfNecessary()方法中,

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
protected void registerDisposableBeanIfNecessary(String beanName, Object bean, RootBeanDefinition mbd) {
AccessControlContext acc = (System.getSecurityManager() != null ? getAccessControlContext() : null);
if (!mbd.isPrototype() && requiresDestruction(bean, mbd)) {
if (mbd.isSingleton()) {
// Register a DisposableBean implementation that performs all destruction
// work for the given bean: DestructionAwareBeanPostProcessors,
// DisposableBean interface, custom destroy method.
// 注册成为DisposableBean
registerDisposableBean(beanName,
new DisposableBeanAdapter(bean, beanName, mbd, getBeanPostProcessors(), acc));
}
else {
// ... 其他省略代码
}
}
}

在判断Bean需要注册成为DisposableBean之后,接着会生成一个DisposableBeanAdapter对象,进入到DisposableBeanAdapter的构造函数中看下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
public DisposableBeanAdapter(Object bean, String beanName, RootBeanDefinition beanDefinition,
List<BeanPostProcessor> postProcessors, AccessControlContext acc) {

// 推断destoryMethodName
String destroyMethodName = inferDestroyMethodIfNecessary(bean, beanDefinition);
if (destroyMethodName != null && !(this.invokeDisposableBean && "destroy".equals(destroyMethodName)) &&
!beanDefinition.isExternallyManagedDestroyMethod(destroyMethodName)) {
// 设置方法名
this.destroyMethodName = destroyMethodName;
// 生成对应的方法
this.destroyMethod = determineDestroyMethod();

// ... 其他省略代码
}
}
this.beanPostProcessors = filterPostProcessors(postProcessors, bean);
}

在构造函数中,首先会调用inferDestroyMethodIfNecessary()方法判断destoryMethodName是什么:

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
private String inferDestroyMethodIfNecessary(Object bean, RootBeanDefinition beanDefinition) {
String destroyMethodName = beanDefinition.getDestroyMethodName();
if (AbstractBeanDefinition.INFER_METHOD.equals(destroyMethodName) ||
(destroyMethodName == null && closeableInterface.isInstance(bean))) {
// Only perform destroy method inference or Closeable detection
// in case of the bean not explicitly implementing DisposableBean
if (!(bean instanceof DisposableBean)) {
try {
// 首先找到是否存在close()方法
return bean.getClass().getMethod(CLOSE_METHOD_NAME).getName();
}
catch (NoSuchMethodException ex) {
try {
// 如果不存在close(),则判断存不存在shutdown方法
return bean.getClass().getMethod(SHUTDOWN_METHOD_NAME).getName();
}
catch (NoSuchMethodException ex2) {
// no candidate destroy method found
}
}
}
return null;
}
// destroyMethodName是否为空窜,不是则返回自定义的方法名,否则返回null
return (StringUtils.hasLength(destroyMethodName) ? destroyMethodName : null);
}

inferDestroyMethodIfNecessary()的逻辑跟hasDestroyMethod()方法一样:如果destoryMethodName(inferred),则表示要Spring自动推断,推断的逻辑是:如果Bean存在close()方法,则把close设置为destoryMethodName,如果不存在则把shutdown设置为destoryMethodName,如果都不存在则为null。如果用户指定了特定的方法,且不为空,则返回用户指定的方法,否则返回null

接着会调用determineDestroyMethod()方法生成具体的destoryMethod

我想分析道这里,已经不用往下看了!!!问题的原因终于找到了!!!!

结论及反思

结论

在走了很多弯路,深入分析了Spring源码之后,终于查明了原因:

Jedis对象正好有一个名字叫做shutdown的方法,虽然Jedis对象没有指定destoryMethod,但是被Spring 自动推断注册成为了DisposableBean!!!并且把shutdown()方法注册为destoryMethod,在程序运行结束的时候会调用shutdown(),发送SHUTDOWN关闭了Redis服务器!!!

修复

从上面的分析中,已经可以得到修复这个问题的方法了。

  1. 在配置生成Jedis对象的时候注定destoryMethod方法为空串。

    1
    2
    3
    4
    5
    6
    7
    @Bean(value = "jedis",destroyMethod = "")
    public Jedis buildJedis() {
    JedisPoolConfig config = new JedisPoolConfig();
    JedisPool jedisPool = new JedisPool(config, "127.0.0.1", 6379);

    return jedisPool.getResource();
    }
  2. Jedis Client中实现close()方法,close()的实现可以为关闭连接。按照优先级,shutdown()方法就不会注册成为destoryMethod

    出现问题的Jedis版本为2.2.1,这个版本太老了,还是13年发布的,这个问题在2.4.x版本就已经修复了(采用的就是第二种方法,实现了close()方法,close()方法的实现就是关闭连接),

忍不住吐槽下,为啥公司还用这么老版本的客户端!!

反思

在这个问题的排查过程中,其实是走了不少弯路的。

  1. 最开始输入的信息不够准确,导致排查方向有误。

    最开始反馈的信息是:

    1. 服务端使用的Redis版本是2.8.11会出现问题,使用本地的5.x没问题。
    2. 只会在执行lua脚本的时候出现问题,执行其他的命令没问题。

      其实这些信息都是有误的,导致第一次排查的时候主要在服务端排查。

      后面跟小D聊的时候,才知道小D本地装5.x的时候,限制了shutdown命令,所以表现出来就是5.x的版本没有问题。

  2. 思维定势,先入为主。

    在确认客户端有没有发送shutdown命令给服务器的时候,一开始想当然的认为客户端不可能主动发送shutdown给服务器。导致后面花了很多时间在排查服务端的问题。

    后面证明:第一次的排查时间完全是浪费了的。

  3. 对Redis的命令以及实现不够熟悉,导致没有很快确定Redis没有问题。

    第一次排查的时候真不知道Redis还有shutdown命令(第二次排查的时候猜测应该有可能会有shutdownCommand()方法,一搜,还真有)。如果知道有这么个命令的话,就不至于傻逼的通过查找prepareForShutdown()方法来定位问题,肯定会直接在shutdownCommand()方法处加断点。这样很快就能定位问题出在哪里了!

    monitor命令的原理认知不够,导致判断错误。

    第一次通过monitor命令查看Redis服务器收到哪些命令的时候,并没有看到shutdown命令,导致自己更加坚定的认为客户端没问题。

  1. 对Spring不够熟悉。如果对Spring足够熟悉的话,就很容易知道是因为Jedis客户端存在shutdown()方法,导致被注册为destoryMethod(),从而在程序结束的时候被执行。

其他

关于monitorshutdown命令( 如果看到这里,最好往下看完 )

在第一次排查的时候使用monitor命令,发现Redis服务器收到了客户端发送的SHUTDOWN命令,但是monitor命令的结果并没有输出,导致误判。

为什么会这样呢?

要搞清楚这个问题,需要明白两点。

  1. monitor和shutdown的实现原理。
  2. Redis事件驱动模型。
  3. Redis如何给客户端返回数据。

现在来一个一个分析。

首先是monitor的实现原理

monitor命令执行过程为:

1
2
3
4
5
6
7
8
void monitorCommand(client *c) {
/* ignore MONITOR if already slave or in monitor mode */
if (c->flags & CLIENT_SLAVE) return;

c->flags |= (CLIENT_SLAVE|CLIENT_MONITOR);
listAddNodeTail(server.monitors,c);
addReply(c,shared.ok);
}

把自己添加到server.monitors链表的末尾。

当其他客户端在执行命令的时候,在call()方法中会把自己要执行的命令拷贝到server.monitors链表中的每个client的缓冲区中,

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
void call(client *c, int flags) {
long long dirty, start, duration;
int client_old_flags = c->flags;
struct redisCommand *real_cmd = c->cmd;

/* Sent the command to clients in MONITOR mode, only if the commands are
* not generated from reading an AOF. */
if (listLength(server.monitors) &&
!server.loading &&
!(c->cmd->flags & (CMD_SKIP_MONITOR|CMD_ADMIN)))
{
// 调用replicationFeedMonitors()方法把请求命令复制到monitors链表的每个元素的缓冲区上
replicationFeedMonitors(c,server.monitors,c->db->id,c->argv,c->argc);
}

// ... 其他省略代码

}

replicationFeedMonitors()方法中把数据复制到server.monitors链表上的每个元素的缓冲区上

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
35
36
37
38
39
40
void replicationFeedMonitors(client *c, list *monitors, int dictid, robj **argv, int argc) {
listNode *ln;
listIter li;
int j;
sds cmdrepr = sdsnew("+");
robj *cmdobj;
struct timeval tv;

gettimeofday(&tv,NULL);
cmdrepr = sdscatprintf(cmdrepr,"%ld.%06ld ",(long)tv.tv_sec,(long)tv.tv_usec);
if (c->flags & CLIENT_LUA) {
cmdrepr = sdscatprintf(cmdrepr,"[%d lua] ",dictid);
} else if (c->flags & CLIENT_UNIX_SOCKET) {
cmdrepr = sdscatprintf(cmdrepr,"[%d unix:%s] ",dictid,server.unixsocket);
} else {
cmdrepr = sdscatprintf(cmdrepr,"[%d %s] ",dictid,getClientPeerId(c));
}

for (j = 0; j < argc; j++) {
if (argv[j]->encoding == OBJ_ENCODING_INT) {
cmdrepr = sdscatprintf(cmdrepr, "\"%ld\"", (long)argv[j]->ptr);
} else {
cmdrepr = sdscatrepr(cmdrepr,(char*)argv[j]->ptr,
sdslen(argv[j]->ptr));
}
if (j != argc-1)
cmdrepr = sdscatlen(cmdrepr," ",1);
}
// 生成字符互传对象
cmdrepr = sdscatlen(cmdrepr,"\r\n",2);
cmdobj = createObject(OBJ_STRING,cmdrepr);

listRewind(monitors,&li);
while((ln = listNext(&li))) {
// 遍历链表上的每个元素,调用addReply()方法把数据写入buf缓冲区
client *monitor = ln->value;
addReply(monitor,cmdobj);
}
decrRefCount(cmdobj);
}

Redis的事件驱动模型

Redis的事件驱动模型(可以参考我之前写的一篇文章Redis源码学习之事件驱动)为

1
2
3
4
5
6
7
8
void aeMain(aeEventLoop *eventLoop) {
eventLoop->stop = 0;
while (!eventLoop->stop) {
if (eventLoop->beforesleep != NULL)
eventLoop->beforesleep(eventLoop);
aeProcessEvents(eventLoop, AE_ALL_EVENTS);
}
}

在每次进入事件循前会先调用eventLoop->beforesleep()方法。在beforesleep()方法中把数据返回给Client

Redis如何把数据返回给客户端

在Redis每次接收到命令并执行之后,Redis不是立马把返回结果写回给Client,而是通过调用addReply()方法首先把需要返回数据的Client对象添加到server.clients_pending_write对象的末尾,然后把需要返回的数据保存到Client对象的缓冲区c->buf中,代码如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
void addReply(client *c, robj *obj) {
// 把client对象添加到server.clients_pending_write链表的末尾
if (prepareClientToWrite(c) != C_OK) return;

if (sdsEncodedObject(obj)) {
// 把数据添加到buf缓冲区
if (_addReplyToBuffer(c,obj->ptr,sdslen(obj->ptr)) != C_OK)
_addReplyStringToList(c,obj->ptr,sdslen(obj->ptr));
} else if (obj->encoding == OBJ_ENCODING_INT) {
/* For integer encoded strings we just convert it into a string
* using our optimized function, and attach the resulting string
* to the output buffer. */
char buf[32];
size_t len = ll2string(buf,sizeof(buf),(long)obj->ptr);
if (_addReplyToBuffer(c,buf,len) != C_OK)
_addReplyStringToList(c,buf,len);
} else {
serverPanic("Wrong obj->encoding in addReply()");
}
}

addReply()方法首先调用prepareClientToWrite()方法把Client对象保存到server.clients_pending_write链表的末尾:

1
2
3
4
5
6
7
8
9
10
int prepareClientToWrite(client *c) {

// ... 其他省略的一些判断代码
if (!clientHasPendingReplies(c))
// 这里保存
clientInstallWriteHandler(c);

/* Authorize the caller to queue in the output buffer of this client. */
return C_OK;
}

调用clientInstallWriteHandler()保存到链表的末尾

1
2
3
4
5
6
7
8
9
10
void clientInstallWriteHandler(client *c) {
if (!(c->flags & CLIENT_PENDING_WRITE) &&
(c->replstate == REPL_STATE_NONE ||
(c->replstate == SLAVE_STATE_ONLINE && !c->repl_put_online_on_ack)))
{
// 设置标志位并添加数据到链表的末尾
c->flags |= CLIENT_PENDING_WRITE;
listAddNodeHead(server.clients_pending_write,c);
}
}

紧接着会调用_addReplyToBuffer()方法把数据写入到buf缓冲区

1
2
3
4
5
6
7
8
9
int _addReplyToBuffer(client *c, const char *s, size_t len) {

// ... 其他一些省略代码

// 把数据拷贝到buf缓冲区
memcpy(c->buf+c->bufpos,s,len);
c->bufpos+=len;
return C_OK;
}

上面说了,Redis的事件驱动模型会在每次进入事件循环处理请求前会先调用beforeSleep()方法,

1
2
3
4
5
6
7
8
9
10
11
12
13
void beforeSleep(struct aeEventLoop *eventLoop) {

// ... 其他省略代码

/* Write the AOF buffer on disk */
flushAppendOnlyFile(0);

/* Handle writes with pending output buffers. */
// 给client返回数据
handleClientsWithPendingWrites();

// ... 其他省略代码
}

beforeSleep()中会调用handleClientsWithPendingWrites();方法把数据发送给Client:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
int handleClientsWithPendingWrites(void) {
listIter li;
listNode *ln;
int processed = listLength(server.clients_pending_write);

listRewind(server.clients_pending_write,&li);
while((ln = listNext(&li))) {
// 遍历server.clients_pending_write链表,对链表中的每个client执行写数据操作
client *c = listNodeValue(ln);

// ... 其他省略代码

// 把缓冲区中的数据返回给socket
if (writeToClient(c->fd,c,0) == C_ERR) continue;

// ... 其他省略代码
}
return processed;
}

综上,Redis monitor命令的实现原理为:

其他客户端执行的命令都会复制到执行了monitor命令的客户端的缓冲区buf中,然后Redis在每次进入下一个循环前会把每个客户端缓冲区的数据返回给对应的客户端。

可以看出,monitor的实现依赖于事件循环!

shutdown命令(如果看到这里,最好一定要往下看完)

再来看shutdown命令,shutdown命令执行过程为:

1
2
3
4
5
6
void shutdownCommand(client *c) {
// ... 其他一些省略代码,
if (prepareForShutdown(flags) == C_OK)
exit(0);
addReplyError(c,"Errors trying to SHUTDOWN. Check logs.");
}

shutdownCommand()方法中,会调用prepareForShutdown()做关闭前的准备工作,然后直接调用exit()方法退出程序了,所以执行monitor命令客户端看不到shutdown命令的

关于为啥看不到shutdown命令的分析,简直天衣无缝,行云流水!

对!没错!肯定是这个原因!!!

但是!!!!

事情真的有这么简单吗!!!

眉头一皱,隐隐觉得哪里不对劲!!!

回头重新看了下代码,果然,有坑!!!

重新回到call()方法中,

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
void call(client *c, int flags) {
long long dirty, start, duration;
int client_old_flags = c->flags;
struct redisCommand *real_cmd = c->cmd;

/* Sent the command to clients in MONITOR mode, only if the commands are
* not generated from reading an AOF. */
if (listLength(server.monitors) &&
!server.loading &&
!(c->cmd->flags & (CMD_SKIP_MONITOR|CMD_ADMIN)))
{
// 调用replicationFeedMonitors()方法把请求命令复制到monitors链表的每个元素的缓冲区上
replicationFeedMonitors(c,server.monitors,c->db->id,c->argv,c->argc);
}

// ... 其他省略代码

}

把命令复制到monitor对象的时候会先判断命令的属性,

1
!(c->cmd->flags & (CMD_SKIP_MONITOR|CMD_ADMIN))

在Redis里面,每个命令都有自己的属性(多种属性的组合),所有的属性定义如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
#define CMD_WRITE (1<<0)            /* "w" flag */
#define CMD_READONLY (1<<1) /* "r" flag */
#define CMD_DENYOOM (1<<2) /* "m" flag */
#define CMD_MODULE (1<<3) /* Command exported by module. */
#define CMD_ADMIN (1<<4) /* "a" flag */
#define CMD_PUBSUB (1<<5) /* "p" flag */
#define CMD_NOSCRIPT (1<<6) /* "s" flag */
#define CMD_RANDOM (1<<7) /* "R" flag */
#define CMD_SORT_FOR_SCRIPT (1<<8) /* "S" flag */
#define CMD_LOADING (1<<9) /* "l" flag */
#define CMD_STALE (1<<10) /* "t" flag */
#define CMD_SKIP_MONITOR (1<<11) /* "M" flag */
#define CMD_ASKING (1<<12) /* "k" flag */
#define CMD_FAST (1<<13) /* "F" flag *

具体每个属性的作用可以自行去了解,
每个方法具体有哪些属性组合,可以在源码中看到,我们看一下SHUTDOWN命令的属性:

1
{"shutdown",shutdownCommand,-1,"aslt",0,NULL,0,0,0,0,0},

SHUTDOWN命令含有aslt属性,

而有a属性的命令都不会被复制到monitor对象的缓冲区上。

所以,不管shutdown命令会不会直接关闭程序,在monitor客户端上都不会输出

万一打赏了呢^_^