自研日志打印器工具类

作者：刘仁鹏
GitHub地址：https://github.com/LingPaicoder/agile-base-4j

转载请注明出处

1. 前言

今天为大家介绍的是一款自研的日志打印器。相信大家在工作中，少不了要和日志打交道。正所谓“日志打得好，bug没地儿跑”，清晰、简洁、全面的日志有助于快速定位问题，而混乱、冗余、丢三落四的日志则会浪费大量时间。
那么一款好用的日志打印器应该具有哪些特性呢？笔者认为主要有以下几点：

支持多维分析：
比如，有时我们想从用户（userId）的维度来查看某一个用户对系统进行过哪些操作；有时我们想从请求的维度来查看一次请求的具体细节；有时我们又想从统计的维度来查看某些页面/接口的PV、UV。
支持上下文收集：
上下文是指在一次请求过程中，与之相关的信息，例如：START日志、事务Id、接口名、接口描述、接口实参、运行时参数、业务进度、耗时时长、END日志等等。有些信息在前置拦截器中就可获得，有些必须在业务代码中获得，而像耗时时长这样的信息，则适合放到后置拦截器中计算。
日志打印，主要是为了记系统在当前上下文里的运行情况。如果系统出现问题，我们通过日志最想要得到的信息就是清晰的上下文。如果没办法做到这一点，日志只会越多越乱。
日志要易读、要格式化：
日志主要是面向人的，给人来看的。格式混乱、不易断句的日志，容易让人丢失掉排查问题的关键线索。
要对AOP友好：
AOP对Access日志、End日志、请求参数、处理时间等信息的打印更灵活。一个对AOP友好的日志打印器，可以事半功倍。

2. 简介

今天要说的这款日志打印器是怎样做到上面那些特性的呢？先来看一下它都提供了哪些接口吧：

public interface LoggerDecorator extends Logger {
    /**
     * 设置logId
     */
    LoggerDecorator setLogId(String logId);

    /**
     * 设置前缀.可通过拦截器由{@link LogDesc#value()}提供
     */
    LoggerDecorator setBusinessPrefix(String prefix);

    /**
     * 注册参数
     */
    LoggerDecorator register(String key, Object val);

    /**
     * 清除
     */
    LoggerDecorator clear();
}

setLogId
setLogId接口通常在一个事务开始时调用。例如一次请求，可以在前置拦截器中通过该接口传入一个唯一性较强的logId（一般不需要绝对唯一，因为日志文件一般都会以天为单位截断，只要保持一天内不会重复即可）。然后在该请求内的任何日志打印，都会自动带上此logId。当需要查看某次请求的具体过程时，利用该功能可以很方便的实现。该接口是为事务/请求维度服务的。
setBusinessPrefix
setBusinessPrefix接口与setLogId类似，也是在事务开始时调用，事务内的任何日志都会自动带上接口传入的参数。不同的是，它是为功能/接口维度服务的。例如对于“用户注册”功能，可以将“用户注册”作为参数传入，或者直接传入接口名（eg：registUser）也可以。
一般无论是web框架还是服务容器，都会提供在拦截器中获取Function对象的接口，因此能够获得方法名。或者自定义一个注解，加在方法上，就可以自定义功能描述信息了。像下面这样：

@LogDesc("查询商家信息")
public Response<Custom> getCustomById(long customId)

register
regist接口用来收集关键的运行时参数，例如会决定代码跳转的boolean类型变量（eg：isCustomExist）、用户主键等等。所有被注册了的K-V，都会在后续的任何打印（info/error/warn）时自动追加在日志内容之后。
clear
clear通常在事务结束时使用，例如后置拦截器。这个接口的功能是，将本次事务中的所有收集的内容（即通过之前三个接口收集的内容）清空。以免影响下次事务的日志打印。

3. 演示

来看一下示例代码：
下面的代码，模拟了1000次事务处理，日志打印分三个部分：前置拦截器日志打印、业务代码日志打印、后置拦截器日志打印。

public class LOGTest {

    private static final LoggerDecorator LOG = BaseLoggerDecorator.getLogger(LOGTest.class);

    public static void main(String[] args) throws Exception {
        for (int i = 1; i <= 1000; i++) {
            // 模仿前置拦截器
            LOG.setLogId(RandomUtil.shortUUID())
                    .setBusinessPrefix("具体业务描述")
                    .register("currNum", i)
                    .info("START");
            long startTime = System.currentTimeMillis();

            // 模仿业务代码
            LOG.register("userId", RandomUtil.nextInt(1000, 10000));
            Thread.sleep(RandomUtil.nextInt(5, 10));
            if (i % 2 == 0) {
                LOG.info("currNum是偶数");
            }
            if (i % 3 == 0) {
                LOG.info("currNum是3的倍数");
            }

            // 模仿后置拦截器
            long endTime = System.currentTimeMillis();
            LOG.register("usedTime", endTime - startTime).info("END");
            LOG.clear();
        }
    }

}

部分日志截图：

consoleLog.png-403.6kB

我们截取部分（前6次）日志来进行说明：

logId:6056ff3f52e6 【 具体业务描述 - START 】 - logArgs:{"currNum":1}
logId:6056ff3f52e6 【 具体业务描述 - END 】 - logArgs:{"usedTime":5,"userId":6404,"currNum":1}
logId:62971514bf59 【 具体业务描述 - START 】 - logArgs:{"currNum":2}
logId:62971514bf59 【 具体业务描述 - currNum是偶数 】 - logArgs:{"userId":3433,"currNum":2}
logId:62971514bf59 【 具体业务描述 - END 】 - logArgs:{"usedTime":5,"userId":3433,"currNum":2}
logId:59fd7fdc357f 【 具体业务描述 - START 】 - logArgs:{"currNum":3}
logId:59fd7fdc357f 【 具体业务描述 - currNum是3的倍数 】 - logArgs:{"userId":1736,"currNum":3}
logId:59fd7fdc357f 【 具体业务描述 - END 】 - logArgs:{"usedTime":6,"userId":1736,"currNum":3}
logId:adf9a8e07d1a 【 具体业务描述 - START 】 - logArgs:{"currNum":4}
logId:adf9a8e07d1a 【 具体业务描述 - currNum是偶数 】 - logArgs:{"userId":1805,"currNum":4}
logId:adf9a8e07d1a 【 具体业务描述 - END 】 - logArgs:{"usedTime":10,"userId":1805,"currNum":4}
logId:83f8366c488f 【 具体业务描述 - START 】 - logArgs:{"currNum":5}
logId:83f8366c488f 【 具体业务描述 - END 】 - logArgs:{"usedTime":6,"userId":7144,"currNum":5}
logId:c649de0705f2 【 具体业务描述 - START 】 - logArgs:{"currNum":6}
logId:c649de0705f2 【 具体业务描述 - currNum是偶数 】 - logArgs:{"userId":4828,"currNum":6}
logId:c649de0705f2 【 具体业务描述 - currNum是3的倍数 】 - logArgs:{"userId":4828,"currNum":6}
logId:c649de0705f2 【 具体业务描述 - END 】 - logArgs:{"usedTime":8,"userId":4828,"currNum":6}

1.多维分析：

查看某一个用户(例如6404)对系统进行过哪些操作：

more log.txt | grep 'END' | grep '6404'

输出：
logId:6056ff3f52e6 【 具体业务描述 - END 】 - logArgs:{"usedTime":5,"userId":6404,"currNum":1}

查看某次请求（例如第6次请求）的具体细节：

more log.txt | grep 'c649de0705f2'

输出：
logId:c649de0705f2 【 具体业务描述 - START 】 - logArgs:{"currNum":6}
logId:c649de0705f2 【 具体业务描述 - currNum是偶数 】 - logArgs:{"userId":4828,"currNum":6}
logId:c649de0705f2 【 具体业务描述 - currNum是3的倍数 】 - logArgs:{"userId":4828,"currNum":6}
logId:c649de0705f2 【 具体业务描述 - END 】 - logArgs:{"usedTime":8,"userId":4828,"currNum":6}

查看请求的PV：

more log.txt | grep 'START' | grep '具体业务描述' | wc -l

输出：
6

......

2.上下文收集：

setLogId接口可用来收集事务Id。
setBusinessPrefix接口用来收集接口描述。
register接口用来收集关键运行时参数。
clear接口用来清空本次事务的信息。

3.日志格式化：

这里说的格式化，是指对业务代码的格式化。至于时间、日志级别、线程信息、类信息等，可以通过底层日志框架的配置文件来进行配置。例如：
```
<Pattern>[%d{MM-dd HH:mm:ss SSS} %-5level] [%t] %c{3} - %m%n%ex</Pattern>
```

日志打印器会按照下面的格式进行打印：

logId:具体事务Id 【 具体业务描述 - 具体业务进度 】 - logArgs:{具体参数}
//例如：
logId:adf9a8e07d1a 【 用户注册 - 校验失败：姓名为空 】 - logArgs:{"userName":"","phone":"13200000000"}

4.AOP支持

日志打印器内置三个ThreadLocal，分别存储logId、businessPrefix、关键运行时参数：

private static final ThreadLocal<String> LOG_ID_THREAD_LOCAL = new ThreadLocal<>();
private static final ThreadLocal<String> BUSINESS_PREFIX_THREAD_LOCAL = new ThreadLocal<>();
private static final ThreadLocal<Map<String, Object>> LOG_ARGS_THREAD_LOCAL = new ThreadLocal<>();

具体使用方式可随业务场景自定义。

4. GitHub

日志打印器的GitHub地址是https://github.com/LingPaicoder/agile-base-4j。
所有的校验器相关代码都放在 com.lpcoder.agile.base.forj.log 包下。
使用示例代码，放在test的 com.lpcoder.agile.base.forj.log 包下。

end
欢迎留言反馈对日志打印器的改进意见。

扫码可关注微信公众号：

wx.jpg