業務背景

筆者參與維護的一個商城專案，其中一些表依賴於一個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能力還有待提高，共勉。