Arthas實踐--使用redefine排查應用奇怪的日志來源

背景

随着應用越來越複雜，依賴越來越多，日志系統越來越混亂，有時會出現一些奇怪的日志，比如：

[] [] [] No credential found           

那麼怎樣排查這些奇怪的日志從哪裡列印出來的呢？因為搞不清楚是什麼logger列印出來的，是以想定位就比較頭疼。

下面介紹用arthas的redefine指令快速定位奇怪日志來源。

• Arthas: https://github.com/alibaba/arthas
• redefine指令： https://alibaba.github.io/arthas/redefine.html

修改StringBuilder

首先在java代碼裡，字元串拼接基本都是通過

StringBuilder

來實作的。比如下面的代碼：

public static String hello(String world) {
        return "hello " + world;
    }           

實際上生成的位元組碼也是用

StringBuilder

來拼接的：

public static java.lang.String hello(java.lang.String);
    descriptor: (Ljava/lang/String;)Ljava/lang/String;
    flags: ACC_PUBLIC, ACC_STATIC
    Code:
      stack=3, locals=1, args_size=1
         0: new           #22                 // class java/lang/StringBuilder
         3: dup
         4: ldc           #24                 // String hello
         6: invokespecial #26                 // Method java/lang/StringBuilder."<init>":(Ljava/lang/String;)V
         9: aload_0
        10: invokevirtual #29                 // Method java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;
        13: invokevirtual #33                 // Method java/lang/StringBuilder.toString:()Ljava/lang/String;
        16: areturn           

在java的logger系統裡，輸出日志時通常也是

StringBuilder

來實作的，最終會調用

StringBuilder.toString()

，那麼我們可以修改

StringBuilder

的代碼來檢測到日志來源。

StringBuilder.toString()

的原生實作是：

@Override
    public String toString() {
        // Create a copy, don't share the array
        return new String(value, 0, count);
    }           

修改為：

@Override
    public String toString() {
        // Create a copy, don't share the array
        String result = new String(value, 0, count);
        if(result.contains("No credential found")) {
            System.err.println(result);
            new Throwable().printStackTrace();
        }
        return result;
    }           

增加的邏輯是：當String裡包含

No credential found

時列印出目前棧，這樣子就可以定位日志輸出來源了。

編繹修改過的StringBuilder

其實很簡單，在IDE裡把

StringBuilder

的代碼複制一份，然後貼到任意一個工程裡，然後編繹即可。

也可以直接用javac來編繹：

javac StringBuilder.java           

啟動應用，使用Arthas redefine修改過的StringBuilder

啟動應用後，在奇怪日志輸出之前，先使用arthas attach應用，再redefine StringBuilder:

$ redefine -p /tmp/StringBuilder.class
redefine success, size: 1           

當執行到輸出

[] [] [] No credential found

的logger代碼時，會列印目前棧。實際運作結果是：

[] [] [] No credential found
java.lang.Throwable
    at java.lang.StringBuilder.toString(StringBuilder.java:410)
    at com.taobao.middleware.logger.util.MessageUtil.getMessage(MessageUtil.java:26)
    at com.taobao.middleware.logger.util.MessageUtil.getMessage(MessageUtil.java:15)
    at com.taobao.middleware.logger.slf4j.Slf4jLogger.info(Slf4jLogger.java:77)
    at com.taobao.spas.sdk.common.log.SpasLogger.info(SpasLogger.java:18)
    at com.taobao.spas.sdk.client.identity.CredentialWatcher.loadCredential(CredentialWatcher.java:128)
    at com.taobao.spas.sdk.client.identity.CredentialWatcher.access$200(CredentialWatcher.java:18)
    at com.taobao.spas.sdk.client.identity.CredentialWatcher$1.run(CredentialWatcher.java:58)
    at java.util.TimerThread.mainLoop(Timer.java:555)
    at java.util.TimerThread.run(Timer.java:505)           

可以看到是

spas.sdk

列印出了

[] [] [] No credential found

的日志。

總結

• logger最終會用StringBuilder來輸出
• 修改StringBuilder來定位輸出特定日志的地方
• 使用Arthas redefine指令來加載修改過的StringBuilder
• redefine指令實際上實作了任意代碼線上debug的功能，可以随意本地修改代碼重新編繹，然後線上redefine加載
• redefine的功能過于強大，是以請小心使用:)

Arthas實踐系列

• 使用Arthas抽絲剝繭排查線上應用日志打滿問題
• 深入Spring Boot：利用Arthas排查NoSuchMethodError