【Java進階】利用APT優雅的實現統一日誌格式

天府雲創發表於2018-01-12

統一日誌格式的幾種方式

無論是搭建日誌平臺還是進行大資料分析,統一日誌格式都是一個重要的前提條件。假設要統一成下面的日誌格式,

日誌格式:[{系統}|{模組}]{描述}[param1=value1$param2=value2],例如:[API|Weixin]Weixin send message failed. [senderId=1234$receiverId=5678]

常見的方法有:

  • 方法1:每次記錄日誌時,根據上下文在原始的訊息內容前後分別加上合適的[{系統}|{模組}]字首和引數字尾。
  • 方法2:自定義日誌類,將{系統}和{模組}作為建構函式的引數傳入,並且在所提供的日誌介面中自動格式化傳入的引數陣列。
  • 方法3:自定義註解類宣告所屬的{系統}和{模組},然後通過AOP的方式,統一在日誌中插入[{系統}|{模組}]字首。
  • 方法4:在方法2的基礎上,自定義註解類宣告所屬的{系統}和{模組},然後通過APT自動生成自定義型別的log成員變數。

方法1依賴於人工來保證統一的日誌格式,方法3雖然簡化了方法呼叫,但對效能有一定的影響。方法2是最常見的手段,但每個類都要顯示宣告log成員變數,略顯冗餘。方法4兼具方法2和方法3的優點,同時又避免了兩者的不足,是一種優雅的實現方式,也是lombok所採用的方式。

下面就針對方法4,結合示例程式碼介紹一下相關技術。

APT: 編譯期自動生成log成員變數

APT的全稱是Annotation Processing Tool,誕生於Java 6版本,主要用於在編譯期根據不同的註解類生成或者修改程式碼。APT執行於獨立的JVM程式中(編譯之前),並且在一次編譯過程中可能會被多次呼叫。

首先,宣告一個包含{系統}和{模組}定義的日誌註解類。注意@Retention應設定為RetentionPolicy.SOURCE,表示編譯後擦除該註解資訊。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
/**
 * 用於自動生成log成員變數.僅適用於class或enum,不適用於介面.
 */
@Retention(RetentionPolicy.SOURCE)
@Target(ElementType.TYPE)
public @interface Slf4j {

    /**
     * 系統名稱.如果為空則取"-Dvlogging.system"系統屬性,如果系統屬性也為空,則取"Unknown".
     */
    String system() default "";

    /**
     * 模組名稱.如果為空則取"-Dvlogging.module"系統屬性,如果系統屬性也為空,則取"Unknown".
     */
    String module() default "";
}

然後,宣告一個註解處理類,繼承Java預設提供的AbstractProcessor類,其中:

  • messager: 用於記錄處理日誌
  • trees: 用於解析Java AST樹
  • maker: 用於生成Java AST節點
  • names: 用於生成Java AST節點名稱
1
2
3
4
5
6
7
8
9
10
11
12
13
14
public class Slf4jProcessor extends AbstractProcessor {

    @Override
    public synchronized void init(ProcessingEnvironment processingEnv) {
        super.init(processingEnv);
        messager = processingEnv.getMessager();
        trees = Trees.instance(processingEnv);
        Context context = ((JavacProcessingEnvironment) processingEnv).getContext();
        maker = TreeMaker.instance(context);
        names = Names.instance(context);
    }

    ...
}

在process方法中呼叫Java Compiler API根據註解資訊動態生成log日誌成員變數:

private static final Logger log = LoggerFactory.getLogger(LoggerFactory.Type.SLF4J, annotatedClass.class, system, module);

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
@Override
public boolean process(Set<? extends TypeElement> annotations, RoundEnvironment roundEnv) {
    // 1 檢查型別
    roundEnv.getElementsAnnotatedWith(Slf4j.class).stream().forEach(elm -> {
        if (elm.getKind() != ElementKind.CLASS && elm.getKind() != ElementKind.ENUM) {
            messager.printMessage(Diagnostic.Kind.ERROR, "Only classes or enums can be annotated with " + Slf4j.class.getSimpleName());
            return;
        }

        // 2 檢查log成員變數是否已存在
        TypeElement typeElm = (TypeElement) elm;
        if (typeElm.getEnclosedElements().stream()
                .filter(e -> e.getKind() == ElementKind.FIELD && Logger.FIELD_NAME.equals(e.getSimpleName())).count() > 0) {
            messager.printMessage(Diagnostic.Kind.WARNING, MessageFormat.format("A member field named {0} already exists in the annotated class", Logger.FIELD_NAME));
            return;
        }

        // 3 注入log成員變數
        CompilationUnitTree cuTree = trees.getPath(typeElm).getCompilationUnit();
        if (cuTree instanceof JCTree.JCCompilationUnit) {
            JCTree.JCCompilationUnit cu = (JCTree.JCCompilationUnit) cuTree;
            // only process on files which have been compiled from source
            if (cu.sourcefile.getKind() == JavaFileObject.Kind.SOURCE) {
                _findType(cu, typeElm.getQualifiedName().toString()).ifPresent(type -> {
                    Slf4j slf4j = typeElm.getAnnotation(Slf4j.class);
                    String system = slf4j.system();
                    String module = slf4j.module();

                    // 生成private static final Logger log = LoggerFactory.getLogger(LoggerFactory.Type.SLF4J, <annotatedClass>, <system>, <module>);
                    JCTree.JCExpression loggerType = _toExpression(Logger.class.getCanonicalName());
                    JCTree.JCExpression getLoggerMethod = _toExpression(LoggerFactory.class.getCanonicalName() + ".getLogger");
                    JCTree.JCExpression typeArg = _toExpression(LoggerFactory.Type.class.getCanonicalName() + "." + LoggerFactory.Type.SLF4J.name());
                    JCTree.JCExpression nameArg = _toExpression(typeElm.getQualifiedName() + ".class");
                    JCTree.JCExpression systemArg = maker.Literal(system);
                    JCTree.JCExpression moduleArg = maker.Literal(module);
                    JCTree.JCMethodInvocation getLoggerCall = maker.Apply(List.nil(), getLoggerMethod, List.of(typeArg, nameArg, systemArg, moduleArg));
                    JCTree.JCVariableDecl logField = maker.VarDef(
                            maker.Modifiers(Flags.PRIVATE | Flags.STATIC | Flags.FINAL),
                            names.fromString(Logger.FIELD_NAME), loggerType, getLoggerCall);

                    _insertField(type, logField);
                });
            }
        }
    });

    return true;
}

整合示例

1
2
3
4
5
6
7
8
9
@Slf4j(system = "Vlogging", module = "Integration")
public class VloggingAnnotated {

    public static void main(String[] args) {
        HashMap<String, String> params = new HashMap<>();
        params.put("foo", "xyz");
        log.info(VloggingAnnotated.class.getCanonicalName(), params);
    }
}

由此可見,使用方法4,業務類只要加上自定義註解,然後正常呼叫日誌API,就可以以統一的日誌格式記錄日誌。

輸出示例

1
2016-07-10 17:26:45 +0800 [INFO] from VloggingAnnotated in main - [Vlogging|Integration]com.xingren.v.logging.integration.VloggingAnnotated[foo=xyz]

IntelliJ Plugin: 自動生成PSI Element,消除編譯錯誤

至此,在命令列方式下,方法4已經可以正確執行。但在IDE環境中(比如IntelliJ,Eclipse),由於一般它們都會使用自定義的編譯模型,需要額外實現一個外掛來根據註解資訊動態修改IDE的語法樹,以避免編譯錯誤。對於IntelliJ而言,使用的是PSI模型,相應的外掛程式碼如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
// 繼承com.intellij.psi.augment.PsiAugmentProvider類

@NotNull
@Override
public <Psi extends PsiElement> List<Psi> getAugments(@NotNull PsiElement psiElement, @NotNull Class<Psi> type) {
    final List<Psi> emptyResult = Collections.emptyList();
    // skip processing during index rebuild
    final Project project = psiElement.getProject();
    if (DumbService.isDumb(project)) {
        return emptyResult;
    }
    // Expecting that we are only augmenting an PsiClass
    // Don't filter !isPhysical elements or code auto completion will not work
    if (!(psiElement instanceof PsiExtensibleClass) || !psiElement.isValid()) {
        return emptyResult;
    }
    // filter non-field type
    if (!PsiField.class.isAssignableFrom(type)) {
        return emptyResult;
    }
    final PsiClass psiClass = (PsiClass) psiElement;
    // see AbstractClassProcessor#process()
    PsiAnnotation psiAnnotation = PsiAnnotationUtil.findAnnotation(psiClass, Slf4j.class);
    if (null == psiAnnotation) {
        return emptyResult;
    }
    // check cache first
    if (loggerCache.containsKey(psiClass.getQualifiedName())) {
        return Arrays.asList((Psi) loggerCache.get(psiClass.getQualifiedName()));
    }

    final PsiManager manager = psiClass.getContainingFile().getManager();
    final PsiElementFactory psiElementFactory = JavaPsiFacade.getElementFactory(project);
    PsiType psiLoggerType = psiElementFactory.createTypeFromText(LOGGER_TYPE, psiClass);
    LightFieldBuilder loggerField = new LightFieldBuilder(manager, LOGGER_NAME, psiLoggerType);
    LightModifierList modifierList = (LightModifierList) loggerField.getModifierList();
    modifierList.addModifier(PsiModifier.PRIVATE);
    modifierList.addModifier(PsiModifier.STATIC);
    modifierList.addModifier(PsiModifier.FINAL);
    loggerField.setContainingClass(psiClass);
    loggerField.setNavigationElement(psiAnnotation);

    final String loggerInitializerParameter = String.format(LOGGER_CATEGORY, psiClass.getName());
    final PsiExpression initializer = psiElementFactory.createExpressionFromText(String.format(LOGGER_INITIALIZER, loggerInitializerParameter), psiClass);
    loggerField.setInitializer(initializer);
    // add to cache
    loggerCache.put(psiClass.getQualifiedName(), loggerField);

    return Arrays.asList((Psi) loggerField);
}

參考

相關文章