记一次线上问题的排查过程

问题描述

前不久运维在例行发布线上CS系统的时候，发现在服务启动的过程中，后台一直在报如下错误，同时导致用户页面访问异常

2017-10-10 18:28:51,077 [ERROR] org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1289)Consumer thread error, thread abort.java.lang.ExceptionInInitializerError    at com.jolly.service.process.impl.ProcessServiceImpl.returnedOrderProcessHandle(ProcessServiceImpl.java:2574)    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)    at java.lang.reflect.Method.invoke(Method.java:606)    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)    at com.sun.proxy.$Proxy19.returnedOrderProcessHandle(Unknown Source)    at com.jolly.mq.listen.oms.OrderReturnProcessListener.processMessage(OrderReturnProcessListener.java:44)    at com.jolly.mq.listen.BaseListener.onMessage(BaseListener.java:32)    at org.springframework.amqp.rabbit.listener.adapter.MessageListenerAdapter.onMessage(MessageListenerAdapter.java:273)    at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.doInvokeListener(AbstractMessageListenerContainer.java:757)    at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.invokeListener(AbstractMessageListenerContainer.java:680)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$001(SimpleMessageListenerContainer.java:93)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$1.invokeListener(SimpleMessageListenerContainer.java:183)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.invokeListener(SimpleMessageListenerContainer.java:1358)    at org.springframework.amqp.rabbit.listener.AbstractMessageListenerContainer.executeListener(AbstractMessageListenerContainer.java:661)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.doReceiveAndExecute(SimpleMessageListenerContainer.java:1102)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.receiveAndExecute(SimpleMessageListenerContainer.java:1086)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer.access$1100(SimpleMessageListenerContainer.java:93)    at org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1203)    at java.lang.Thread.run(Thread.java:745)Caused by: java.lang.NullPointerException    at com.jolly.util.SpringMvcUtil.getBean(SpringMvcUtil.java:21)    at com.jolly.util.common.UserUtils.<clinit>(UserUtils.java:42)    ... 38 more2017-10-10 18:28:51,100 [ERROR] org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1322)Stopping container from aborted consumer2017-10-10 18:29:24,575 [WARN] org.springframework.web.servlet.DispatcherServlet.noHandlerFound(DispatcherServlet.java:1108)No mapping found for HTTP request with URI [/GPlatform_v2/home] in DispatcherServlet with name 'mvc-dispatcher'2017-10-10 18:29:29,049 [WARN] org.springframework.web.servlet.DispatcherServlet.noHandlerFound(DispatcherServlet.java:1108)No mapping found for HTTP request with URI [/GPlatform_v2/aaaa] in DispatcherServlet with name 'mvc-dispatcher'2017-10-10 18:29:30,106 [WARN] org.springframework.web.servlet.DispatcherServlet.noHandlerFound(DispatcherServlet.java:1108)No mapping found for HTTP request with URI [/GPlatform_v2/aaaa] in DispatcherServlet with name 'mvc-dispatcher'2017-10-10 18:29:31,037 [WARN] org.springframework.web.servlet.DispatcherServlet.noHandlerFound(DispatcherServlet.java:1108)No mapping found for HTTP request with URI [/GPlatform_v2/aaaa] in DispatcherServlet with name 'mvc-dispatcher'2017-10-10 18:29:31,793 [WARN] org.springframework.web.servlet.DispatcherServlet.noHandlerFound(DispatcherServlet.java:1108)No mapping found for HTTP request with URI [/GPlatform_v2/aaaa] in DispatcherServlet with name 'mvc-dispatcher'2017-10-10 18:29:43,791 [ERROR] com.jolly.common.template.ServiceTemplateImpl.executeWithoutTransaction(ServiceTemplateImpl.java:68)System errorjava.lang.NoClassDefFoundError: Could not initialize class com.jolly.util.common.UserUtils    at com.jolly.service.process.impl.ProcessServiceImpl.saveProcess(ProcessServiceImpl.java:1069)    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)    at java.lang.reflect.Method.invoke(Method.java:606)    at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:317)    at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:183)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.transaction.interceptor.TransactionInterceptor$1.proceedWithInvocation(TransactionInterceptor.java:96)    at org.springframework.transaction.interceptor.TransactionAspectSupport.invokeWithinTransaction(TransactionAspectSupport.java:260)    at org.springframework.transaction.interceptor.TransactionInterceptor.invoke(TransactionInterceptor.java:94)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:91)    at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)    at org.springframework.aop.framework.JdkDynamicAopProxy.invoke(JdkDynamicAopProxy.java:204)    at com.sun.proxy.$Proxy19.saveProcess(Unknown Source)    at com.jolly.controller.process.ProcessCSController$7.executeService(ProcessCSController.java:530)    at com.jolly.common.template.ServiceTemplateImpl.executeWithoutTransaction(ServiceTemplateImpl.java:48)    at com.jolly.controller.process.ProcessCSController.saveProcess(ProcessCSController.java:525)    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)    at java.lang.reflect.Method.invoke(Method.java:606)    at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:219)    at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:132)    at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:104)    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandleMethod(RequestMappingHandlerAdapter.java:745)    at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:686)    at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)    at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:925)    at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:856)    at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:936)    at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:838)    at javax.servlet.http.HttpServlet.service(HttpServlet.java:650)    at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:812)    at javax.servlet.http.HttpServlet.service(HttpServlet.java:731)    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:303)    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)    at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)    at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)    at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)    at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:241)    at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:208)    at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:220)    at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:122)    at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:505)    at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:170)    at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103)    at org.apache.catalina.valves.AccessLogValve.invoke(AccessLogValve.java:956)    at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:116)    at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:423)    at org.apache.coyote.http11.AbstractHttp11Processor.process(AbstractHttp11Processor.java:1079)    at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:625)    at org.apache.tomcat.util.net.AprEndpoint$SocketWithOptionsProcessor.run(AprEndpoint.java:2459)    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)    at java.lang.Thread.run(Thread.java:745)

经了解，当天CS系统没有做什么特别的修改，而之前都发布正常。于是通过日志中的两个异常java.lang.ExceptionInInitializerError和java.lang.NoClassDefFoundError: Could not initialize class com.jolly.util.common.UserUtils的异常栈推测问题可能出在UserUtils工具类的初始化过程中。

排查过程

根据异常栈，异常发生的入口在mq消费的过程中（项目中使用了rabbitmq），通过跟踪项目代码，其中一个mq listener中确实调用了UserUtils工具类中的静态方法，之前发布都没有报错是因为在发布的时候监听的队列里面没有待消费的消息，而这一次在服务发布之前队列里面就已经累积了很多消息。那为什么这次UserUtils会初始化异常而之前都不会呢？

通过对项目整体的了解，项目中使用了两个spring上下文，根上下文和mvc上下文。其中mq消费监听配置是在根上下文中，UserUtils工具类中有个静态变量使用了SpringMvcUtil来获取mvc上下文中的A对象实例，如下

package cn.cjc.share.util;import org.springframework.beans.BeansException;import org.springframework.context.ApplicationContext;import org.springframework.context.ApplicationContextAware;/** * @author chenjc * @since 2017-10-14 */public class SpringMvcUtil implements ApplicationContextAware {    private static ApplicationContext applicationContext;    @Override    public void setApplicationContext(ApplicationContext applicationContext) throws BeansException {        System.out.println("SpringMvcUtil.setApplicationContext方法调用，当前线程：" + Thread.currentThread().getName());        SpringMvcUtil.applicationContext = applicationContext;    }    public static <T> T getBean(Class<T> clazz) {        return applicationContext.getBean(clazz);    }}

UserUtils静态变量如下

private static UserComponent userComponent = SpringMvcUtil.getBean(UserComponent.class);

其中SpringMvcUtil和UserComponent（简称A对象）都被配置在mvc上下文中，当服务启动的过程中，先是初始化根上下文，然后异步执行mq消息消费，接着再初始化mvc上下文，由于mq的消费和mvc上下文的初始化过程是并发进行的，那么就有可能在mq消费时调用UserUtils类的过程中，mvc上下文还没有初始化完成，SpringMvcUtil实例还没有被注入applicationContext，导致初始化UserUtils静态变量时报空指针异常，进而导致UserUtils加载到JVM失败，报java.lang.ExceptionInInitializerError，当再次使用UserUtils类时，就直接报java.lang.NoClassDefFoundError了。用户页面访问时也是直接抛出了类定义找不到错误，因为CS系统首页使用到了UserUtils类。

解决方案（三者取其一即可）

• 将mq消费监听配置文件放入到mvc上下文中。
• 将UserUtils引用的A对象配置到根上下文中，然后使用根上下文工具类SpringUtil去获取。
• 项目中不要配置两个spring上下文，只需要配置mvc上下文即可。

经验总结

之前发布的时候一直没问题是因为都是在mvc上下文初始化完成后才使用到了UserUtils类，所以尽量避免在根上下文的对象实例中使用mvc上下文中的对象，同时项目能用一个上下文最好使用一个。

样例程序

为了简化问题，我写了个demo程序，先使用MessageProducerTest类来生产消息到rabbitmq服务器，然后再启动服务，即可重现错误。

下载程序