业务中使用ThreadLocal中途居然还能变?(How can ThreadLocal be used in business?)

业务背景

笔者参与维护的一个商城项目,其中一些表依赖于一个gameCode字段进行分表处理,例如 a_sell_bill、b_sell_bill,a、b为不同的gameCode。在需要用的gameCode的接口处,前端会在header中传入gameCode,后端有统一的过滤器会将gameCode设置进一个ThreadLocal变量中,如:

...
HttpServletRequest httpServletRequest = (HttpServletRequest)request;
String gameCode = httpServletRequest.getHeader("gameCode");
gameContext.setGameCode(gameCode);
...
@Component
public class GameContext {

    static final ThreadLocal<String> ctx = new ThreadLocal<>();

    public void setGameCode(String gameCode){
        ctx.set(gameCode);
    }

    public String currentGameCode(){
        return ctx.get();
    }

}

后续很多业务场景都依赖于gameContext中的gameCode值进行分表处理。

问题描述

在某次开发一个订单需求时,开发环境能够正常下单,但是测试环境订单会下单不成功,正式环境也是正常的(不然早就有人反馈问题了)。通过添加日志发现订单Controller中还能从数据库中查到这笔卖单,结果到了订单Service就查不到这笔卖单了,比对查询参数发现并没有问题,直接查测试环境数据库也能查到相应数据。

初步怀疑可能是因为gameCode出现问题,导致没有走到对应的表上,继续增加日志,打印当前的gameCode值,发现订单Controller中从gameContext中获取到的gameCode还是正确的,结果到了调用的订单Service,从gameContext中获取到的gameCode就有问题了,是另一个值。

怎么回事?ThreadLocal值中途还会变的吗?仔细查看代码,在过滤器设置完gameCode之后,整个方法调用并没有去设置gameCode值呀,虽然考虑了tomcat是会存在线程复用的情况,但是一次请求还没完成的话,tomcat并不会把线程放回线程池呀。

继续排查,在所有设置gameContext值的地方打印日志,并且打印方法栈,看是否有其它方法会调用:

public void setGameCode(String gameCode){
    logger.error("gameCode setGameCode={}", gameCode);
    printCallStack();
    ctx.set(gameCode);
}

private static void printCallStack() {
    Throwable exception = new Throwable();
    StackTraceElement[] stackTraceElements = exception.getStackTrace();
    StringBuilder sb = new StringBuilder("gameCode ");
    if (stackTraceElements != null) {
        for (StackTraceElement element : stackTraceElements) {
            sb.append(element.getClassName()).append("\t")
                .append(element.getFileName()).append("\t")
                .append(element.getLineNumber()).append("\t")
                .append(element.getMethodName()).append("\n");
        }
        logger.error(sb.toString());
    }
}

果不其然,发现了在进入订单Service之前,会调用另一个检查用户金额Service的方法,该方法会从数据库中取出用户余额变动记录进行遍历,并且当类型为购买商品时,并将订单中的gameCode重新设置到gameContext变量中,用于查找对应的订单(因为订单依赖于gameContext中的gameCode值进行分表),导致检查完用户余额之后,再次查询由于gameCode值变了就找不到这笔订单了。该方法是通过注解进行调用的,所以先前并没有排查到该方法。

解决办法

在中途需要设置gameCode值的地方之前先保存原先的值,待方法结束之前再恢复到原来的gameCode值,如:

@UserMoneyType(Constants.MONEY_LOG_TYPE_BUY)
private UserMoney modifyUserMoneyBuy(UserMoneyLog userMoneyLog, BigDecimal change) {
    // 1. 设置gameCode之前一定要先保存到前的值
    String restoreGameCode = gameContext.currentGameCode();
    gameContext.setGameCode(userMoneyLog.getGameCode());
    // ...
    // 这里需要使用userMoneyLog.getGameCode()中的gameCode值去对应的表查询订单数据
    // ...
    // 2. 用完恢复
    gameContext.setGameCode(restoreGameCode);
    return new UserMoney(userMoneyLog.getUserid(), amount, trade, recharge, freeze);
}

感悟

由于笔者参与这个项目时,项目代码已基本成型,后续只是增加新的功能,故有一些代码笔者并不了解其实现逻辑,导致解决这个bug花了整整2天,期间还问了一些前辈同事。由于不能在测试环境debug,只能依赖于代码中打印的日志来排查问题,期间也走了很多弯路,其中在日志中打印执行的方法栈也是前辈提醒的,自己的debug能力还有待提高,共勉。

————————

Business background

The author participated in the maintenance of a mall project. Some tables depend on a Gamecode field for table splitting, such as a_ sell_ bill、b_ sell_ Bill, a and B are different gamecodes. At the interface of the Gamecode to be used, the front end will pass in the Gamecode in the header, and the back end will have a unified filter to set the Gamecode into a ThreadLocal variable, such as:

...
HttpServletRequest httpServletRequest = (HttpServletRequest)request;
String gameCode = httpServletRequest.getHeader("gameCode");
gameContext.setGameCode(gameCode);
...
@Component
public class GameContext {

    static final ThreadLocal<String> ctx = new ThreadLocal<>();

    public void setGameCode(String gameCode){
        ctx.set(gameCode);
    }

    public String currentGameCode(){
        return ctx.get();
    }

}

Many subsequent business scenarios rely on the Gamecode value in the gamecontext for table splitting.

Problem description

When an order requirement is developed at a certain time, the development environment can place an order normally, but the order in the test environment will not be placed successfully, and the formal environment is also normal (otherwise someone would have fed back the problem long ago). By adding a log, it is found that the sales order can also be found in the database in the order controller. As a result, the sales order cannot be found in the order service. It is found that there is no problem by comparing the query parameters. The corresponding data can also be found by directly checking the test environment database.

It is preliminarily suspected that there may be a problem with the Gamecode, resulting in the failure to go to the corresponding table. Continue to increase the log and print the current Gamecode value. It is found that the Gamecode obtained from the gamecontext in the order controller is still correct. As a result, there is a problem with the Gamecode obtained from the gamecontext in the called order service. It is another value.

What’s going on? Will the ThreadLocal value change halfway? Check the code carefully. After the filter sets the Gamecode, the whole method call does not set the Gamecode value. Although Tomcat considers that there will be thread reuse, if a request is not completed, Tomcat will not put the thread back to the thread pool.

Continue troubleshooting, print the log in all places where the gamecontext value is set, and print the method stack to see if there are other methods that will call:

public void setGameCode(String gameCode){
    logger.error("gameCode setGameCode={}", gameCode);
    printCallStack();
    ctx.set(gameCode);
}

private static void printCallStack() {
    Throwable exception = new Throwable();
    StackTraceElement[] stackTraceElements = exception.getStackTrace();
    StringBuilder sb = new StringBuilder("gameCode ");
    if (stackTraceElements != null) {
        for (StackTraceElement element : stackTraceElements) {
            sb.append(element.getClassName()).append("\t")
                .append(element.getFileName()).append("\t")
                .append(element.getLineNumber()).append("\t")
                .append(element.getMethodName()).append("\n");
        }
        logger.error(sb.toString());
    }
}

Not surprisingly, it was found that before entering the order service, another method to check the user amount service will be called. This method will take the user balance change record from the database for traversal, and when the type is purchased goods, reset the Gamecode in the order to the gamecontext variable, It is used to find the corresponding order (because the order depends on the Gamecode value in the gamecontext for table splitting). After checking the user balance, query again. Because the Gamecode value changes, the order cannot be found. This method is called through annotations, so this method has not been checked previously.

terms of settlement

Save the original value before setting the Gamecode value halfway, and restore to the original Gamecode value before the end of the method, such as:

@UserMoneyType(Constants.MONEY_LOG_TYPE_BUY)
private UserMoney modifyUserMoneyBuy(UserMoneyLog userMoneyLog, BigDecimal change) {
    // 1. 设置gameCode之前一定要先保存到前的值
    String restoreGameCode = gameContext.currentGameCode();
    gameContext.setGameCode(userMoneyLog.getGameCode());
    // ...
    // 这里需要使用userMoneyLog.getGameCode()中的gameCode值去对应的表查询订单数据
    // ...
    // 2. 用完恢复
    gameContext.setGameCode(restoreGameCode);
    return new UserMoney(userMoneyLog.getUserid(), amount, trade, recharge, freeze);
}

Perception

When the author participated in this project, the project code was basically formed, and only new functions were added later. Therefore, the author did not understand the implementation logic of some codes, resulting in that it took two days to solve this bug. During this period, he also asked some senior colleagues. Because you can’t debug in the test environment, you can only rely on the log printed in the code to troubleshoot the problem. During this period, you have also taken many detours. The method stack printed in the log is also reminded by your predecessors. Your debugging ability needs to be improved and encouraged.