一款给日志打标签实现精确定位的日志切面利器

566 阅读7分钟

背景

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

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

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

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

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

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

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

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

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

答案是不用的。

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

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

bryan31.gitee.io/aspect-log

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

联系作者