给日志打标签，让你的日志定位再无困难

背景

不知道各位在生产日志中定位问题时有没有碰到这样的场景：由于coding的时候日志输出的比较少，出现问题时，很难通过日志去定位到问题。又或者是，你明明coding的时候有输出日志。但是在庞大的日志文件中，由于业务线程并发比较多，你输出的日志又没有加关键信息。你也很难定位到你所需要的日志信息。


之前在公司里写业务代码时，为了使每个RPC调用能被日志记录下来，我们在公司基础组件里定义了一个切面，拦截所有的RPC调用，方法开始之前，在日志里输出调用的服务和方法以及参数，方法结束时输出方法的耗时。我相信很多人也是这么做的。


这样一来 ，所有的调用都能通过参数里的关键信息被搜索到。也能定位到调用是什么结束的以及耗时。


但是在有些业务方法中，也打上了很多的业务日志。由于核心业务的tps和qps很高，日志是互相穿插的。如果你的日志没有打上关键的业务信息(比如订单号，业务ID)，那就很难在日志中被定位出来。


也许有些童鞋会说，用线程号呀。通过搜索业务ID定位到调用开始的地方，再搜索这条线程的线程号，就可以定位整个请求的所有日志。其实之前我也是这么干的，但是线程一般都是由线程池进行管理的，在tps很高的业务中，同一个线程号有可能短时间会出现多次，但是却是不同的请求。而且业务方法中可能也会有异步线程，导致了线程号会变。这样对于定位日志就又增加了难度。当然最后可以通过对时间戳的分析，还是可以定位到具体日志。但是这样就增加了定位的时间成本。


如果你的公司对微服务使用了分布式追踪，那么定位日志可以通过traceId来解决。如果没有在生产上应用分布式追踪，又想在并发比较高的应用的日志上快速定位到所需要的日志。其中一个比较有效的办法就是：规范日志的输出格式。


在每行日志输出时尽可能的加上关键的业务信息，然后定位起来就比较清晰了，例如：





这里每一行日志都加上了订单号和请求ID，我们把这样的日志头信息称之为日志标签，有了这些标签定位起来就比较容易了。


那这样是不是意味着每写一行日志，都必须加上这样日志标签信息呢？这是不是也麻烦了？


答案是不用的。


推荐一款自动给日志打标签实现精确定位的日志切面框架，你使用了这个，你的日志可以实现自定义的业务标签！


点击Aspect-log跳转到开源主页，或者复制以下地址：

https://gitee.com/bryan31/aspect-log

Aspect-log介绍

这是一款小巧，轻量级，对业务几乎无侵入的日志切面框架。特性为：

• 使用简单，不侵入业务代码。只需要在方法上配置标注
• 支持log4j，logback，log4j2三种常见的日志框架
• 配置极其简单。提供“一键配置”，自动识别日志框架
• 在方法上配置，无论调用多深或者异步调用。也可以统一加上日志标签
• 无性能损耗

使用方法很简单，如果你是springboot，aspect-log提供了自动装配，GAV为：

<dependency>
  <groupId>com.yomahub</groupId>
  <artifactId>aspect-log-spring-boot-starter</artifactId>
  <version>1.2</version>
</dependency>

如果你是spring，GAV为：

<dependency>
  <groupId>com.yomahub</groupId>
  <artifactId>aspect-log-core</artifactId>
  <version>1.2</version>
</dependency>

配置方式

如果你使用spring，需要在项目里的application.xml里定义：

<bean class="com.yomahub.aspectlog.aop.AspectLogAop"/>

如果你使用springboot，AspectLog切面会自动装配好。

一键配置方法

这种方式用javassit实现，只需要一句话就可以实现。自动识别当前主流的日志框架。

@SpringBootApplication
public class Runner {

    static {AspectLogEnhance.enhance();}//进行日志增强，自动判断日志框架

    public static void main(String[] args) {
        try {
            SpringApplication.run(Runner.class, args);
        } catch (Throwable e) {
            e.printStackTrace();
        }
        while (true) {
            try {
                Thread.sleep(60000);
            } catch (Throwable e) {
                e.printStackTrace();
            }
        }
    }
}

针对于主流的Log日志框架作了适配（推荐用这种）

针对于每种Log日志框架提供了适配，具体使用方法请参照项目主页里的文档。

如何使用

接下来在你的方法上加上@AspectLog标注，简单的例子如下：

@AspectLog({"id"})
public void demo1(String id,String name){
  log.info("这是第一条日志");
  log.info("这是第二条日志");
  log.info("这是第三条日志");
  new Thread(() -> log.info("这是异步日志")).start();
}

假设id的值为'NO1234'，日志打出来的样子如下：

2020-02-08 20:22:33.945 [main] INFO  Demo - [NO1234] 这是第一条日志
2020-02-08 20:22:33.945 [main] INFO  Demo - [NO1234] 这是第二条日志
2020-02-08 20:22:33.945 [main] INFO  Demo - [NO1234] 这是第三条日志
2020-02-08 20:22:33.948 [Thread-3] INFO  Demo - [NO1234] 这是异步日志

@AspectLog支持多个标签:

@AspectLog({"id","name"})
public void demo1(String id,String name){
  log.info("这是第一条日志");
  log.info("这是第二条日志");
  log.info("这是第三条日志");
  new Thread(() -> log.info("这是异步日志")).start();
}

假设传入id的值为'NO1234'，name为'jenny'，日志打出来的样子如下：

2020-02-08 22:09:40.101 [main] INFO  Demo - [NO1234-jenny] 这是第一条日志
2020-02-08 22:09:40.101 [main] INFO  Demo - [NO1234-jenny] 这是第二条日志
2020-02-08 22:09:40.102 [main] INFO  Demo - [NO1234-jenny] 这是第三条日志
2020-02-08 22:09:40.103 [Thread-3] INFO  Demo - [NO1234-jenny] 这是异步日志

@AspectLog支持自定pattern和多个参数的连接符

@AspectLog(value = {"id","name"},pattern = "<-{}->",joint = "_")
public void demo(String id,String name){
  log.info("加了patter和joint的示例");
}

日志打出来的样子如下：

2020-02-08 22:09:40.103 [main] INFO  Demo - <-NO1234_jenny-> 加了patter和joint的示例

@AspectLog支持点操作符，适用于对象的取值，支持类型为业务对象和Map

@AspectLog({"person.id","person.age","person.company.department.dptId"})
public void demo(Person person){
  log.info("多参数加多层级示例");
}

日志打出来的样子如下：

2020-02-08 22:09:40.110 [main] INFO  Demo - [31-25-80013] 多参数加多层级示例

@AspectLog支持自定义Convert，适用于更复杂的业务场景

@AspectLog(convert = CustomAspectLogConvert.class)
public void demo(Person person){
  log.info("自定义Convert示例");
}

public class CustomAspectLogConvert implements AspectLogConvert {
    @Override
    public String convert(Object[] args) {
        Person person = (Person)args[0];
        return "PERSON(" + person.getId() + ")";
    }
}

日志打印出来的样子如下：

2020-02-20 17:05:12.414 [main] INFO  Demo - [PERSON(31] 自定义Convert示例

@AspectLog支持编程式设值

public void demo(){
  AspectLogContext.putLogValue("[SO1001]");
  log.info("代码控制示例");
}

日志打出来的样子：

2020-02-08 22:09:40.110 [main] INFO  Demo - [SO1001] 代码控制示例

结尾

日志输出对于一个服务来说，即是执行轨迹的记录，也是寻错找源的根本。日志打的全面而工整，对于排查问题来说，是事半功倍的，相信小伙伴都有看过乱糟糟的日志吧，在一堆这样的日志文件中取寻根溯源，那是极其痛苦的。

我相信很多开发者都有着代码洁癖，工程的架构，代码的结构，变量的定义，都有着苛刻的要求。这是种好习惯，这种好习惯会使代码的阅读和理解事半功倍。

所以Aspect-log就是这样一款能让你的日志也变得工整和赏心悦目的工具。

最后附上Aspect-log的工程主页，欢迎关注和提出issue

希望这款小工具能让你的日志变得工整，能让你的排查变得简单而快捷。

联系作者

微信关注 「jishuyuanren」或者扫描以下二维码获取更多技术干货：