目录
ControllerInterceptor执行过程&异常场景
must init thread context first异常推理
案发现场
某系统在某日下午,部分请求出现下面的异常信息:
[] - java.lang.RuntimeException: must init thread context first
在 com.haiercash.spring.aop.ControllerInterceptor.updateArgs(ControllerInterceptor.java:171)
在 com.haiercash.spring.aop.ControllerInterceptor.proceedRequestMappingPointcut(ControllerInterceptor.java:201)
在 sun.reflect.GeneratedMethodAccessor549.invoke(Unknown Source)
在 sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
在 java.lang.reflect.Method.invoke(Method.java:497)
在 org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:629)
在 org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:618)
在 org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:70)
在 org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:168)
在 org.springframework.aop.framework.CglibAopProxy$DynamicAdvisedInterceptor.intercept(CglibAopProxy.java:673)
在 com.haiercash.loanplatform.hrlp.controller.OperationController$$EnhancerBySpringCGLIB$$3c3ce503.checkHealth(<generated>)
在 sun.reflect.GeneratedMethodAccessor811.invoke(Unknown Source)
在 sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
在 java.lang.reflect.Method.invoke(Method.java:497)
在 org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205)
在 org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:133)
在 org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:97)
在 org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:827)
在 org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:738)
在 org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:85)
在 org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:967)
在 org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:901)
在 org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:970)
在 org.springframework.web.servlet.FrameworkServlet.doGet(FrameworkServlet.java:861)
在 javax.servlet.http.HttpServlet.service(HttpServlet.java:635)
在 org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:846)
在 javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.boot.web.filter.ApplicationContextHeaderFilter.doFilterInternal(ApplicationContextHeaderFilter.java:55)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:110)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 com.dianping.cat.servlet.CatFilter.logTransaction(CatFilter.java:255)
在 com.dianping.cat.servlet.CatFilter.doFilter(CatFilter.java:93)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.security.web.FilterChainProxy.doFilterInternal(FilterChainProxy.java:208)
在 org.springframework.security.web.FilterChainProxy.doFilter(FilterChainProxy.java:177)
在 org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
在 org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:262)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:99)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.web.filter.HttpPutFormContentFilter.doFilterInternal(HttpPutFormContentFilter.java:105)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.web.filter.HiddenHttpMethodFilter.doFilterInternal(HiddenHttpMethodFilter.java:81)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.session.web.http.SessionRepositoryFilter.doFilterInternal(SessionRepositoryFilter.java:167)
在 org.springframework.session.web.http.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:80)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.cloud.sleuth.instrument.web.TraceFilter.doFilter(TraceFilter.java:169)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:197)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.springframework.boot.actuate.autoconfigure.MetricsFilter.doFilterInternal(MetricsFilter.java:106)
在 org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 com.haiercash.spring.servlet.DispatcherFilter.doFilter(DispatcherFilter.java:64)
在 org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
在 org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
在 org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
在 org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
在 org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:478)
在 org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
在 org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:80)
在 org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
在 org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
在 org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:799)
在 org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
在 org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:868)
在 org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1455)
在 org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
在 java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
在 java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
在 org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
在 java.lang.Thread.run(Thread.java:745)
在elk日志平台中,检索2021年1月-3月的日志中发现,该异常出现的时间段有两个:
22号 出现了几百笔
26号 14:00-00:33出现了几万笔
分析需要知道的ThreadLocal对象
对于ThreadLocal对象的使用:
在xx系统中,相当于有三个ThreadLocalMap,定义和用途如下;
RequestContext,在部分aop对象中,得到request、response进行一些验签之类的业务操作;
private static final class RequestContextData {
private boolean exists; //初始化标志位;ture使用中;false 使用结束
private HttpServletRequest request;
private HttpServletResponse response;
private ServletContext servletContext;
private HttpSession session;
private Map<String, Cookie> cookies;
}
ThreadContext,有两个用途:1、在日志中输出T对象;2、在controller的aop中,通过channelNo得到一些业务数据;
private static final class ThreadContextData {
private final Stack<BaseController> controllerStack = new Stack<>();
private boolean exists;//初始化标志位,true使用中;false使用结束
private boolean grant;
private String token;
private String channel;
private String channelNo;
}
TracexContext,用来进行日志链路追踪的,在日志中,正确的输出traceId、spanId等
public final class Span implements ISpan {
private static final String ROOT_SPAN_ID = StringUtils.EMPTY;
private static final String ROOT_PARENT_SPAN_ID = StringUtils.EMPTY;
private static final String SEPARATOR_SPAN_ID_INDEX = Environment.Dot;
private static final String SEPARATOR_TRACE_ID_SPAN_ID = Environment.Dot;
private final String traceId;//链路唯一标识,一般是系统间的追踪号
private final String spanId;//当前请求的追踪号
private final String parentSpanId;//在同一个链路中,前一个spanId;
}
一个请求的过程
1.一个请求过来,会从线程池获得一个线程(线程不够的时候,会有一些特殊的错误提示);
2.成功占用线程之后,开始按照上面的顺序图,逐一执行(一个请求一个线程);
3.DispathFilter执行过程&可能出现场景
@Override
public void doFilter(ServletRequest servletRequest, ServletResponse servletResponse, FilterChain filterChain) throws IOException, ServletException {
/**
* 当在同一个线程中,这个fitler被第二次经过的时候,什么也不做;请求按照图的顺序,漏到下一个filter或者contoller
* 第二次经过的条件是,RestContext对应的线程本地对象的标志位为true,表示使用中;
* 如果标志位处理不得当,会导致该filter被执行两遍;
* 如果标志位,在上一个请求中,没有被合理重置,会导致本次请求被没有执行该过滤器中的代码,直接进入下一个过滤器中执行;
* 如果同一个请求,为了确保该过滤器只会被执行1次,一般会通过继承OncePerRequestFilter来实现,那么上面的两个如果就不存在了*/
//转发 (forward) 保持原始上下文
if (RequestContext.exists()) {
filterChain.doFilter(servletRequest, servletResponse);
return;
}
//非转发 (not forward)
DispatcherRequestWrapper request = new DispatcherRequestWrapper((HttpServletRequest) servletRequest);
DispatcherResponseWrapper response = new DispatcherResponseWrapper((HttpServletResponse) servletResponse);
IncomingLog.writeBeginLog(request);
/**
*这一段代码,主要完成8件事情
* 1、RequestContextData本地线程对象,完成初始化
* 2、ThreadContextData本地线程对象,完成初始化
* 3、TraceContextData本地线程对象,完成初始化
* 4、执行后面的过滤器
* 5、输出正常结束日志 || 输出异常日志
* 6、RequestContextData本地线程对象,完成重置
* 7、ThreadContextData本地线程对象,完成重置
* 8、TraceContextData本地线程对象,完成重置
*
* 在这个过程中,可能会出现下面几种异常现象:
* a、如果1、2、3在初始化的过程中,出现异常
* 都可能会导致线程本地变量完成了初始化,由于异常的出现,请求结束返回,同时没有对本地线程对象进行重置;
* b、如果6、7、8在重置的过程中,出现异常
* 会导致排在器后面的本地变量不能够进行重置
*/
//非转发 (not forward)
//得到当前线程本地RequestContextData对象,把标志位设置为true,表示使用中
RequestContext.init(request, response);
//得到当前线程本地ThreadContext对象,把标志位设置为true,表示使用中
ThreadContext.init(anyArg(request, NAME_ACCESS_TOKEN), firstArg(request, NAME_ACCESS_TOKEN, NAME_TOKEN), firstArg(request, NAME_CHANNEL), firstArg(request, NAME_CHANNEL_NO_PRIMARY, NAME_CHANNEL_NO_SECONDARY));
//得到当前线程本地TraceContext对象,把标志位设置为true,表示使用中
TraceContext.init();
long begin = System.currentTimeMillis();
try {
//过滤器执行下一步
filterChain.doFilter(request, response);
//输出日志
IncomingLog.writeEndLog(request, response, System.currentTimeMillis() - begin);
} catch (ClientAbortException e) {
//输出异常日志
IncomingLog.writeClientAbortErrorLog(request, System.currentTimeMillis() - begin);
} catch (Exception e) {
//输出异常日志
IncomingLog.writeErrorLog(request, e, System.currentTimeMillis() - begin);
} finally {
//得到当前线程本地RequestContextData对象,把标志位设置为false,表示不使用(相当于清零)
TraceContext.reset();
//得到当前线程本地ThreadContextData对象,把标志位设置为false,表示不使用(相当于清零)
ThreadContext.reset();
//得到当前线程本地RequestContextData对象,把标志位设置为false,表示不使用(相当于清零)
RequestContext.reset();
}
}
ControllerInterceptor执行过程&异常场景
private void updateArgs(Parameter[] params, String[] paramNames, Object[] args) {
/**
* 这个的判断,确保contorller的请求使用DispathcherFilter之后执行的;
*/
if (!ThreadContext.exists())
throw new RuntimeException("must init thread context first");
CommonArgs commonArgs = this.getCommonArgs(params, args);//合并参数
this.setCommonArgs(params, paramNames, args, commonArgs);//更新参数
this.logger.info(String.format("==>Common args token: %s channel: %s channelNo: %s", commonArgs.getToken(), commonArgs.getChannel(), commonArgs.getChannelNo()));
}
@Pointcut("execution(* com.haiercash..*.*(..)) && (@annotation(org.springframework.web.bind.annotation.RequestMapping)" +
" || @annotation(org.springframework.web.bind.annotation.GetMapping)" +
" || @annotation(org.springframework.web.bind.annotation.DeleteMapping)" +
" || @annotation(org.springframework.web.bind.annotation.PostMapping)" +
" || @annotation(org.springframework.web.bind.annotation.PutMapping))")
private void requestMappingPointcut() {
}
/**
* 对于com.haiercash包里面有(RequestMapping、GetMapping、DeleteMapping、PostMapping、PutMapping)注解之一的,该aop就会被执行;
* 1、同业所有的controller必须继承BaseController,否则抛异常;
* 2、完成业务请求相关的参数转换;(如果没有经过DispathcherFilter、或者DispathcherFilter执行异常了,就会导致“must init thread context first”)
* 3、ThreadContext.enterController(controller)请放入try中
*/
@Around(value = "requestMappingPointcut()")
public Object proceedRequestMappingPointcut(ProceedingJoinPoint joinPoint) throws Throwable {
//获取实例
Object target = joinPoint.getTarget();
if (!(target instanceof BaseController))
throw new RuntimeException(String.format("%s must extends %s", target.getClass(), BaseController.class));
BaseController controller = (BaseController) target;
//获取方法
Signature signature = joinPoint.getSignature();
if (!(signature instanceof MethodSignature))
throw new RuntimeException("join point signature must be " + MethodSignature.class);
MethodSignature methodSignature = (MethodSignature) signature;
//更新参数
Parameter[] params = methodSignature.getMethod().getParameters();
String[] paramNames = methodSignature.getParameterNames();
Object[] args = joinPoint.getArgs();
this.updateArgs(params, paramNames, args);
//执行
ThreadContext.enterController(controller);//进入
try {
return joinPoint.proceed(args);
} finally {
ThreadContext.exitController();//退出
}
}
must init thread context first异常推理
抛出异常信息的代码段
private void updateArgs(Parameter[] params, String[] paramNames, Object[] args) {
if (!ThreadContext.exists())
throw new RuntimeException("must init thread context first");
CommonArgs commonArgs = this.getCommonArgs(params, args);//合并参数
this.setCommonArgs(params, paramNames, args, commonArgs);//更新参数
this.logger.info(String.format("==>Common args token: %s channel: %s channelNo: %s", commonArgs.getToken(), commonArgs.getChannel(), commonArgs.getChannelNo()));
}
异常出现的过程
通过追加日志输出,定位到问题代码块:
if (RequestContext.exists()) {
filterChain.doFilter(servletRequest, servletResponse);
return;
}
//非转发 (not forward)
DispatcherRequestWrapper request = new DispatcherRequestWrapper((HttpServletRequest) servletRequest);
DispatcherResponseWrapper response = new DispatcherResponseWrapper((HttpServletResponse) servletResponse);
IncomingLog.writeBeginLog(request);
// 在这里,它执行失败了会发生什么呢?
RequestContext.init(request, response);
ThreadContext.init(**);
TraceContext.init();
long begin = System.currentTimeMillis();
try {
filterChain.doFilter(request, response);
IncomingLog.writeEndLog(request, response, System.currentTimeMillis() - begin);
} catch (ClientAbortException e) {
IncomingLog.writeClientAbortErrorLog(request, System.currentTimeMillis() - begin);
} catch (Exception e) {
IncomingLog.writeErrorLog(request, e, System.currentTimeMillis() - begin);
} finally {
TraceContext.reset();
ThreadContext.reset();
RequestContext.reset();
}
根据问题代码,来进行反推问题的发生过程:
当线程池里面所有的线程被某类请求污染成线程A的样子,那么同业所有的请求都将出现"must init thread context first"。
RequestContext.init的try代码块,捕获到珍贵的错误栈信息:
如何降低同类问题的出现
1、需要优化目前已知的问题代码,同时其他系统进行自查,是否有同样的问题;
2、需要有人对公共使用的jar足够的了解;
3、需要有人对一些流量很高的系统的基本框架很了解;
4、Try的使用需要科普一下;
5、正确的日志输出;
6、系统的强壮性需要提高;