奇怪的问题，再次启动jar包会导致bean对象失效?Unknown redis exception Cannot connect, Event executor group is terminated

大家好，我是烤鸭：

踩坑实录。一个某次上线导致的问题，并没有改过什么代码，只是重新上了一次包，没上之前从来没出过这个问题。最开始日志的报错信息一直是 NoClassDefFoundError could not initialize class ,发现是 static 初始化 spring bean 失败，导致类没有加载成功。

1. 报错日志

ex.ToString().org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.NoClassDefFoundError: Could not initialize class com.etc.common.utils.SequenceKit 
ex.Message,Handler dispatch failed; nested exception is java.lang.NoClassDefFoundError: Could not initialize class com.etc.common.utils.SequenceKit 
ex.StackTrace,org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1006) 
ex.Source,java.lang.NoClassDefFoundError: Could not initialize class com.etc.common.utils.SequenceKit

2. 代码复现：

SequenceKit.java

package com.xxx.common.utils;import java.util.concurrent.atomic.AtomicInteger;import org.checkerframework.common.value.qual.StaticallyExecutable;
import org.joda.time.DateTime;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.data.redis.core.RedisTemplate;import com.fasterxml.jackson.core.Versioned;public class SequenceKit {private static final Logger logger = LoggerFactory.getLogger(SequenceKit.class);public static final String TYPE_INCR = "INCR:";public static final RedisTemplate redisTemplate = SpringContextUtil.getBean("redisTemplate", RedisTemplate.class);/*** 根据指定业务前缀生成自增 number* @return*/public static String getBusinessSequenceDoc(String key) {String date = new DateTime().toString("yyyyMMddHHmmss");logger.info("redisTemplate{}"+redisTemplate);Long no = redisTemplate.opsForValue().increment(TYPE_INCR+key, 1);if(no == null ){logger.info("redis 连接失败{}"+TYPE_INCR+key);String uuid = UUIDUtil.generate();return  key+ "-" + date + "-" + uuid;}return  key+ "-" + date + "-" + String.format("%06d", no);}}

SpringContextUtil.java

package com.xxx.common.utils;import org.springframework.beans.BeansException;
import org.springframework.context.ApplicationContext;
import org.springframework.context.ApplicationContextAware;
import org.springframework.stereotype.Component;/*** * @ClassName: SpringContextUtil* @Description: 静态获取Bean* @author gaogang* @date 2016年7月12日 下午4:21:26**/
@Component
public class SpringContextUtil implements ApplicationContextAware {/** 当前IOC上下文环境*/private static ApplicationContext applicationContext; /** 设置当前上下文环境，此方法由spring自动装配 (non-Javadoc)* * @see* org.springframework.context.ApplicationContextAware#setApplicationContext* (org.springframework.context.ApplicationContext)*/@Overridepublic void setApplicationContext(ApplicationContext applicationContext)throws BeansException {SpringContextUtil.applicationContext = applicationContext;}public static ApplicationContext getApplicationContext() {return applicationContext;}/*** * @Description 从spring容器获取bean实例</br>*  <font color='red'>注意，这里beanId是spring ioc中bean实例的名字,如果是注解扫描方式，没有特意指定名称，一般为类名，首字母小写(java遵从驼峰命名规则)，如果有指定名称，则为指定的bean名称</font>* @param name  lmk name,infact it's name in spring IOC* @return  bean实例** @author wjggwm* @data 2016年8月25日 下午2:22:16*/public static Object getBean(String name) throws BeansException {return getApplicationContext().getBean(name);}/*** * @Description 从spring容器获取bean实例</br>*  <font color='red'>注意，这里beanId是spring ioc中bean实例的名字,如果是注解扫描方式，没有特意指定名称，一般为类名，首字母小写(java遵从驼峰命名规则)，如果有指定名称，则为指定的bean名称</font>* @param name  lmk name,infact it's name in spring IOC* @param requiredType  lmk class类型* @return  bean实例* @throws BeansException** @author wjggwm* @data 2017年1月5日 下午5:58:27*/public static <T> T getBean(String name, Class<T> requiredType) throws BeansException {return getApplicationContext().getBean(name, requiredType);}public static <T> T getBean(Class<T> requiredType) {return applicationContext.getBean(requiredType);}}

3. 问题猜想

静态变量初始化在springbean之前，导致获取不到bean对象，报错。

其实有点想不通，测试环境和线上已经运行那么多天，如果是这个问题，早就应该曝光了。

静态变量的初始化是在调用的时候再赋值，也就是调用这个方法的 getBean的时候，项目早已经启动成功，不存在拿不到bean的情况。

4. 场景模拟

后来想模拟线上的场景，将静态变量 = 一个抛异常的方法，类似下面。确实爆错了，原因找到了，就是这个对象初始化失败。

为了避免这个问题，做了一下修改：

5. 根本原因分析

改完就不会报异常了么。如果场景一样的话，还是会报的。再贴一段同时报错信息的日志。是redis 相关的日志，好像有点意思，都是redis相关的。

2020-05-20 15:38:54.356 [TID:591.16551.15899603343206723] [DubboServerHandler-20.0.22.51:20886-thread-105]  INFO  [class:co
m.etc.redis.RedisUtil | method:set | line:177] logInfo==> redis set 异常
org.springframework.data.redis.RedisSystemException: Unknown redis exception; nested exception is java.lang.IllegalStateException: Cannot connect, Event executor group is termin
ated.at org.springframework.data.redis.FallbackExceptionTranslationStrategy.getFallback(FallbackExceptionTranslationStrategy.java:53)at org.springframework.data.redis.FallbackExceptionTranslationStrategy.translate(FallbackExceptionTranslationStrategy.java:43)at org.springframework.data.redis.connection.lettuce.LettuceConnection.convertLettuceAccessException(LettuceConnection.java:257)at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.convertLettuceAccessException(LettuceStringCommands.java:718)at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.setEx(LettuceStringCommands.java:227)at org.springframework.data.redis.connection.DefaultedRedisConnection.setEx(DefaultedRedisConnection.java:252)at org.springframework.data.redis.core.DefaultValueOperations$4.potentiallyUsePsetEx(DefaultValueOperations.java:230)at org.springframework.data.redis.core.DefaultValueOperations$4.doInRedis(DefaultValueOperations.java:223)at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:224)at org.springframework.data.redis.core.RedisTemplate.execute(RedisTemplate.java:184)at org.springframework.data.redis.core.AbstractOperations.execute(AbstractOperations.java:95)at org.springframework.data.redis.core.DefaultValueOperations.set(DefaultValueOperations.java:218)at com.etc.redis.RedisUtil.set(RedisUtil.java:170)at com.etc.service.credit.EtcCreditApplyRelationServiceImpl.createNewApplyOrder(EtcCreditApplyRelationServiceImpl.java:1089)at com.etc.service.credit.EtcCreditApplyRelationServiceImpl$$FastClassBySpringCGLIB$$d7d53003.invoke(<generated>)at org.springframework.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)at org.springframework.aop.framework.CglibAopProxy$CglibMethodInvocation.invokeJoinpoint(CglibAopProxy.java:746)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:294)at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:98)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:92)at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:185)at org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:688)at com.etc.service.credit.EtcCreditApplyRelationServiceImpl$$EnhancerBySpringCGLIB$$a874bba6.createNewApplyOrder(<generated>)at com.alibaba.dubbo.common.bytecode.Wrapper33.invokeMethod(Wrapper33.java)at com.alibaba.dubbo.rpc.proxy.javassist.JavassistProxyFactory$1.doInvoke(JavassistProxyFactory.java:47)at com.alibaba.dubbo.rpc.proxy.AbstractProxyInvoker.invoke(AbstractProxyInvoker.java:76)at com.alibaba.dubbo.config.invoker.DelegateProviderMetaDataInvoker.invoke(DelegateProviderMetaDataInvoker.java:52)at com.alibaba.dubbo.rpc.protocol.InvokerWrapper.invoke(InvokerWrapper.java:56)at com.alibaba.dubbo.rpc.filter.ExceptionFilter.invoke(ExceptionFilter.java:62)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke$original$Mxc753iz(MonitorFilter.java:75)at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke$original$Mxc753iz$accessor$LYrs6xRu(MonitorFilter.java)at com.alibaba.dubbo.monitor.support.MonitorFilter$auxiliary$Xy5iiuam.call(Unknown Source)at org.apache.skywalking.apm.agent.core.plugin.interceptor.enhance.InstMethodsInter.intercept(InstMethodsInter.java:93)at com.alibaba.dubbo.monitor.support.MonitorFilter.invoke(MonitorFilter.java)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.filter.TimeoutFilter.invoke(TimeoutFilter.java:42)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.protocol.dubbo.filter.TraceFilter.invoke(TraceFilter.java:78)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.filter.ContextFilter.invoke(ContextFilter.java:72)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.filter.GenericFilter.invoke(GenericFilter.java:131)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.filter.ClassLoaderFilter.invoke(ClassLoaderFilter.java:38)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.filter.EchoFilter.invoke(EchoFilter.java:38)at com.alibaba.dubbo.rpc.protocol.ProtocolFilterWrapper$1.invoke(ProtocolFilterWrapper.java:72)at com.alibaba.dubbo.rpc.protocol.dubbo.DubboProtocol$1.reply(DubboProtocol.java:103)at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.handleRequest(HeaderExchangeHandler.java:96)at com.alibaba.dubbo.remoting.exchange.support.header.HeaderExchangeHandler.received(HeaderExchangeHandler.java:172)at com.alibaba.dubbo.remoting.transport.DecodeHandler.received(DecodeHandler.java:51)at com.alibaba.dubbo.remoting.transport.dispatcher.ChannelEventRunnable.run(ChannelEventRunnable.java:80)at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)at java.lang.Thread.run(Thread.java:748)
Caused by: java.lang.IllegalStateException: Cannot connect, Event executor group is terminated.at io.lettuce.core.AbstractRedisClient.initializeChannelAsync(AbstractRedisClient.java:254)at io.lettuce.core.cluster.RedisClusterClient.connectStatefulAsync(RedisClusterClient.java:658)at io.lettuce.core.cluster.RedisClusterClient.connectStateful(RedisClusterClient.java:635)at io.lettuce.core.cluster.RedisClusterClient.connectClusterImpl(RedisClusterClient.java:530)at io.lettuce.core.cluster.RedisClusterClient.connect(RedisClusterClient.java:339)at org.springframework.data.redis.connection.lettuce.ClusterConnectionProvider.getConnection(ClusterConnectionProvider.java:55)at org.springframework.data.redis.connection.lettuce.LettuceConnection.doGetAsyncDedicatedConnection(LettuceConnection.java:962)at org.springframework.data.redis.connection.lettuce.LettuceConnection.getDedicatedConnection(LettuceConnection.java:942)at org.springframework.data.redis.connection.lettuce.LettuceConnection.getConnection(LettuceConnection.java:903)at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.getConnection(LettuceStringCommands.java:714)at org.springframework.data.redis.connection.lettuce.LettuceStringCommands.setEx(LettuceStringCommands.java:225)... 53 common frames omitted

我们顺着报错类找到源码看一下。

 protected <K, V, T extends RedisChannelHandler<K, V>> ConnectionFuture<T> initializeChannelAsync(ConnectionBuilder connectionBuilder) {SocketAddress redisAddress = connectionBuilder.socketAddress();if (clientResources.eventExecutorGroup().isShuttingDown()) {throw new IllegalStateException("Cannot connect, Event executor group is terminated.");}//
}

我们看一下 eventExecutorGroup 的说明。内部操作的线程池。

 /*** Returns the computation pool used for internal operations. Such tasks are periodic Redis Cluster and Redis Sentinel* topology updates and scheduling of connection reconnection by {@link io.lettuce.core.protocol.ConnectionWatchdog}.** @return the computation pool used for internal operations*/EventExecutorGroup eventExecutorGroup();

这个判断就是线程池对应的group是不是关闭了。那我们就看一下哪个地方调用了shutdown方法。有点多，先看默认的Default哪个吧。

一路找下去：

DefaultClientResources.shutdown() ——> AbstractRedisClient.shutdownAsync() ——>LettuceConnectionFactory.destroy()

最终找到了 LettuceConnectionFactory 实现了 DisposableBean.destroy()

看下 DisposableBean 的说明：由要在销毁时释放资源的bean实现的接口。将在单个销毁对象时调用destroy方法。也支持在应用程序生命周期的驱动下，在关机时处理所有单例。

/** Copyright 2002-2018 the original author or authors.** Licensed under the Apache License, Version 2.0 (the "License");* you may not use this file except in compliance with the License.* You may obtain a copy of the License at**      http://www.apache.org/licenses/LICENSE-2.0** Unless required by applicable law or agreed to in writing, software* distributed under the License is distributed on an "AS IS" BASIS,* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.* See the License for the specific language governing permissions and* limitations under the License.*/package org.springframework.beans.factory;/*** Interface to be implemented by beans that want to release resources on destruction.* A {@link BeanFactory} will invoke the destroy method on individual destruction of a* scoped bean. An {@link org.springframework.context.ApplicationContext} is supposed* to dispose all of its singletons on shutdown, driven by the application lifecycle.** <p>A Spring-managed bean may also implement Java's {@link AutoCloseable} interface* for the same purpose. An alternative to implementing an interface is specifying a* custom destroy method, for example in an XML bean definition. For a list of all* bean lifecycle methods, see the {@link BeanFactory BeanFactory javadocs}.** @author Juergen Hoeller* @since 12.08.2003* @see InitializingBean* @see org.springframework.beans.factory.support.RootBeanDefinition#getDestroyMethodName()* @see org.springframework.beans.factory.config.ConfigurableBeanFactory#destroySingletons()* @see org.springframework.context.ConfigurableApplicationContext#close()*/
public interface DisposableBean {/*** Invoked by the containing {@code BeanFactory} on destruction of a bean.* @throws Exception in case of shutdown errors. Exceptions will get logged* but not rethrown to allow other beans to release their resources as well.*/void destroy() throws Exception;}

这只是一种猜想，redisTemplate 这个 bean被销毁了(在项目shutdown的过程中)。

6. 再翻日志

再往前翻翻日志，发现启动了项目的时候，前一次的项目并没有停掉，导致新上线的启动失败。

这也怪我，运维说启动成功了，我看日志一直在刷，并没有意识到这个问题。

2020-05-20 15:36:34.443 [TID:N/A] [main-EventThread]  INFO  [class:org.apache.curator.framework.state.ConnectionStateManage
r | method:postState | line:237] logInfo==> State change: CONNECTED
2020-05-20 15:36:53.004 [TID:N/A] [main]  INFO  [class:io.netty.util.internal.logging.Slf4JLogger | method:info | line:101]logInfo==> Starting without optional epoll library
2020-05-20 15:36:53.007 [TID:N/A] [main]  INFO  [class:io.netty.util.internal.logging.Slf4JLogger | method:info | line:101]logInfo==> Starting without optional kqueue library
2020-05-20 15:36:53.361 [TID:N/A] [main]  INFO  [class:com.etc.service.xxx.WeimobServiceImpl | method:refreshAccessToken| line:234] logInfo==> 启动刷新任务，开始执行时间：2020-05-20T16:39:16.724
2020-05-20 15:36:53.961 [TID:N/A] [main]  INFO  [class:com.etc.config.BeforeStartup | method:onApplicationEvent | line:33]logInfo==> onApplicationEvent！！！redisUtil=com.etc.redis.RedisUtil@4407b042
2020-05-20 15:36:54.910 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> Starting ProtocolHandler ["http-nio-8096"]
2020-05-20 15:36:54.916 [TID:N/A] [main]  ERROR [class:org.apache.juli.logging.DirectJDKLog | method:log | line:182] 
logInfo==> Failed to start connector [Connector[HTTP/1.1-8096]]
org.apache.catalina.LifecycleException: Failed to start component [Connector[HTTP/1.1-8096]]at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:167)at org.apache.catalina.core.StandardService.addConnector(StandardService.java:225)at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.addPreviouslyRemovedConnectors(TomcatWebServer.java:256)at org.springframework.boot.web.embedded.tomcat.TomcatWebServer.start(TomcatWebServer.java:198)at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.startWebServer(ServletWebServerApplicationContext.java:300)at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.finishRefresh(ServletWebServerApplicationContext.java:162)at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:553)at org.springframework.boot.web.servlet.context.ServletWebServerApplicationContext.refresh(ServletWebServerApplicationContext.java:140)at org.springframework.boot.SpringApplication.refresh(SpringApplication.java:780)at org.springframework.boot.SpringApplication.refreshContext(SpringApplication.java:412)at org.springframework.boot.SpringApplication.run(SpringApplication.java:333)at org.springframework.boot.SpringApplication.run(SpringApplication.java:1277)at org.springframework.boot.SpringApplication.run(SpringApplication.java:1265)at com.etc.ApplyServiceApplication.main(ApplyServiceApplication.java:33)at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)at java.lang.reflect.Method.invoke(Method.java:498)at org.springframework.boot.loader.MainMethodRunner.run(MainMethodRunner.java:48)at org.springframework.boot.loader.Launcher.launch(Launcher.java:87)at org.springframework.boot.loader.Launcher.launch(Launcher.java:50)at org.springframework.boot.loader.JarLauncher.main(JarLauncher.java:51)
Caused by: org.apache.catalina.LifecycleException: Protocol handler start failedat org.apache.catalina.connector.Connector.startInternal(Connector.java:1020)at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)... 21 common frames omitted
Caused by: java.net.BindException: Address already in useat sun.nio.ch.Net.bind0(Native Method)at sun.nio.ch.Net.bind(Net.java:433)at sun.nio.ch.Net.bind(Net.java:425)at sun.nio.ch.ServerSocketChannelImpl.bind(ServerSocketChannelImpl.java:223)at sun.nio.ch.ServerSocketAdaptor.bind(ServerSocketAdaptor.java:74)at org.apache.tomcat.util.net.NioEndpoint.bind(NioEndpoint.java:219)at org.apache.tomcat.util.net.AbstractEndpoint.start(AbstractEndpoint.java:1151)at org.apache.coyote.AbstractProtocol.start(AbstractProtocol.java:591)at org.apache.catalina.connector.Connector.startInternal(Connector.java:1018)... 22 common frames omitted
2020-05-20 15:36:54.921 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> Pausing ProtocolHandler ["http-nio-8096"]
2020-05-20 15:36:54.922 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> Stopping service [Tomcat]
2020-05-20 15:36:54.961 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> The stop() method was called on component [StandardServer[-1]] after stop() had already been called. The second call will be ignored.
2020-05-20 15:36:54.962 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> Stopping ProtocolHandler ["http-nio-8096"]
2020-05-20 15:36:54.962 [TID:N/A] [main]  INFO  [class:org.apache.juli.logging.DirectJDKLog | method:log | line:180] 
logInfo==> Destroying ProtocolHandler ["http-nio-8096"]

这些都是小问题，但是注意到日志里多了一行，有点麻烦的。停止方法被已经被调用了，这次就忽略了。

The stop() method was called on component [StandardServer[-1]] after stop() had already been called. The second call will be ignored。

是运维的停止脚本(kill pid) 导致触发了第一次的stop方法么。如果这样就说的通了，stop的时候，导致调用了 shutdown ，将 redisTemplate 从工厂移除，从而静态初始化失败。这个也有一个问题，就是为什么继承 DisposableBean 那么多类，怎么就单独移除了一个 RedistTemplate。

只能强行解释一波了，项目由于某些原因没有停下来(可能是有在执行任务的线程)，但是部分类已经触发了 destory 方法，从而导致部分连接池、bean对象失效等问题。