threadLocal引发的惨案

目录

案发现场

分析需要知道的ThreadLocal对象

一个请求的过程

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、系统的强壮性需要提高;

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值