1. 程式人生 > >記一次線上問題的排查過程

記一次線上問題的排查過程

問題描述

前不久運維在例行釋出線上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 more 2017-10-10 18:28:51,100 [ERROR] org.springframework.amqp.rabbit.listener.SimpleMessageListenerContainer$AsyncMessageProcessingConsumer.run(SimpleMessageListenerContainer.java:1322) Stopping container from aborted consumer 2017-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 error java.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.ExceptionInInitializerErrorjava.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伺服器,然後再啟動服務,即可重現錯誤。

下載程式