zl程序教程

您现在的位置是:首页 >  其他

当前栏目

深入浅出日志体系(logback最佳实践)

2023-02-19 12:28:17 时间

大家好,我是陶朱公Boy。

前言

今天跟大家分享一篇我比较敬佩的业界大佬—张建飞同学(阿里高级技术专家,cola框架作者)刚新鲜出炉的一篇关于日志实践的文章。大致分享的是如下几点内容:

在开发阶段应该打印哪些日志、不同的环境如何配置不同的日志、日志框架标准化的重要性、如何避免到处使用ERROR、为什么集中式日志更好。

文章很长,干货满满,建议花几分钟看到最后,相信肯定对你有所帮助!

以下是正文:

在很多人的认知里面,日志的确是可有可无的小问题,因为有没有日志都不影响业务功能的运行。

正因为如此,日志问题也经常被团队忽视。而事实是,日志的问题一点都不小,而是值得我们好好重视的大问题。

因为日志是我们窥见软件这个“黑盒子”内部运行情况的不二法门,特别是线上问题的监控和定位,只能依靠日志。其价值不亚于数据库中的业务数据,只不过日志是“过程数据”,而数据库是“结果数据”。

可以说,日志是影响研发效能的关键因素之一,没有好的日志规范、日志框架、日志系统、日志实践,就不可能有高的研发效率。

本文我会介绍一些这些年,我积累的一些我认为比较好的日志实践,这些内容包括:

  1. 在开发阶段应该打印哪些日志
  2. 不同的环境如何配置不同的日志
  3. 日志框架标准化的重要性
  4. 如何避免到处使用ERROR
  5. 为什么集中式日志更好

开发态的日志

在开发阶段,我们要尽可能的多打日志,因为日志可以给我们提供更多的上下文信息,减少debug的次数,debug是非常不友好且耗时间的开发方式。

当你需要频繁debug代码的时候,就应该回头审视一下我是不是日志打少了。我平时在开发阶段写代码的时候,有几个地方的日志我是一定要完整打印出来的:

  1. 一个是API的完整入参和出参
  2. 另一个是数据库的SQL和参数

比如,我们有一个计费的API是charge(ChargeRequest request) ,如下所示,那么在处理请求的一开始,我会把request的完整信息打印出来。

public Response charge(ChargeRequest request) {
        log.debug("begin charge : " + request);
        Session session = sessionGateway.get(request.getSessionId());
        int durationToCharge = request.getDuration() - session.getChargedDuration();
        List<ChargeRecord> chargeRecordList = new ArrayList<>();
        chargeCalling(session, durationToCharge, chargeRecordList);
        chargeCalled(session, durationToCharge, chargeRecordList);
        chargeGateway.saveAll(chargeRecordList);
        session.setChargedDuration(request.getDuration());
        return Response.buildSuccess();
    }

这样,我在本地开发的时候,每次运行程序,我都能获得比较完整的请求上下文信息,当然过程中的重要节点也需要被记录,比如在真正执行charge的时候,我会把相关信息也打印出来。

DEBUG [main] c.h.c.application.ChargeServiceImpl: begin charge : ChargeRequest(sessionId=00001, duration=10)
DEBUG [main] c.h.charging.domain.account.Account: do charge: [Charge{phoneNo=15921582155, callType=CALLED, chargeDuration=10, chargePlanType=BASIC, cost=Money(amount=40)}]

Charge系统的一项重要任务是要把ChargeRecord(计费记录)保持到数据库中,通常,我们会通过观察数据库的数据是否正确来判断程序是否正确。因此,如下所示,我们应该把和数据库相关的操作详细打印出来,包括SQL和参数绑定。

DEBUG [main] o.h.e.jdbc.spi.SqlStatementLogger: insert into charge_record (call_type, charge_duration, charge_plan_type, cost, create_time, phone_no, session_id, update_time) values (?, ?, ?, ?, ?, ?, ?, ?)
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [1] as [VARCHAR] - [CALLING]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [2] as [INTEGER] - [10]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [3] as [VARCHAR] - [BASIC]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [4] as [BIGINT] - [50]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [5] as [TIMESTAMP] - [Mon Nov 14 18:07:13 CST 2022]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [6] as [BIGINT] - [13681874533]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [7] as [VARCHAR] - [00001]
TRACE [main] o.h.type.descriptor.sql.BasicBinder: binding parameter [8] as [TIMESTAMP] - [Mon Nov 14 18:07:13 CST 2022]

那么要如何才能输出这些数据库相关的日志呢?基本上每一个ORM框架都提供了这样的日志能力,就拿基于Hibernate实现的JPA框架来说,我们可以通过配置下面的logger来做输出。其它框架和语言请自行探索。

<!--SQL日志-->
<logger name="org.hibernate.SQL" level="DEBUG"/>
<!--参数绑定日志-->
<logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE"/>

此外,在开发阶段为了方便,我建议直接把日志输出到控制台(console),这会使我们在IDE里写代码、调试的时候更方便高效。

以logback为例,我通常会写一个如下的logback-test.xml配置文件,即应用基础root会采用INFO级别高亮layout的方式输出到console,然后对于当前应用和其他关键信息(比如数据库相关)的采用DEBUG或者更低日志级别输出到console。

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>
                %highlight(%-5level) [%blue(%t)] %yellow(%C{35}): %msg%n%throwable
            </Pattern>
        </layout>
    </appender>

    <!--rootLogger是默认的logger-->
    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
    </root>

    <!--应用日志-->
    <!--这个logger没有指定appender,它会继承root节点中定义的那些appender-->
    <logger name="com.huawei.charging" level="DEBUG"/>
    <!--SQL日志-->
    <logger name="org.hibernate.SQL" level="DEBUG"/>
    <!--参数绑定日志-->
    <logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE"/>
</configuration>

不同环境的日志

不同的环境对日志的输出、存储的诉求是不一样的,上面给出的是开发阶段的日志输出,我的经验是尽量把详细信息输出到console就好。

上线之后,我们一般就不再需要像SQL参数绑定那么详细的日志了,而且我们的日志也不是输出到console,而是输出到文件,或者通过网络输出到集中式日志系统。

由此,我们可以看到不同的环境需要有不同的日志配置策略。以logback为例,为了实现不同环境的日志配置区隔,如下图所示,我们可以分别在src/main/resources和src/test/resources下面放置不同的配置文件。

注意,想要在开发环境下使用不同的logback配置,需要将其命名为logback-test.xml,这样框架会优先加载logback-test.xml,而不是logback.xml。

框架的这个自动加载机制,是通过logback的ContextInitializer的这段代码实现的:

public class ContextInitializer {
    
    final public static String GROOVY_AUTOCONFIG_FILE = "logback.groovy";
    final public static String AUTOCONFIG_FILE = "logback.xml";
    final public static String TEST_AUTOCONFIG_FILE = "logback-test.xml";
    
    public URL findURLOfDefaultConfigurationFile(boolean updateStatus) {
            ClassLoader myClassLoader = Loader.getClassLoaderOfObject(this);
            URL url = findConfigFileURLFromSystemProperties(myClassLoader, updateStatus);
            if (url != null) {
                return url;
            }
    
            url = getResource(TEST_AUTOCONFIG_FILE, myClassLoader, updateStatus);
            if (url != null) {
                return url;
            }
    
            url = getResource(GROOVY_AUTOCONFIG_FILE, myClassLoader, updateStatus);
            if (url != null) {
                return url;
            }
    
            return getResource(AUTOCONFIG_FILE, myClassLoader, updateStatus);
        }
//...
}

日志框架的原理不复杂,核心概念就是Appender,Logger和Layout,鼓励大家有空多去看看源码。

追源码有很多好处,一方面可以吸收到他人比较好的设计和写代码方式,另一方面是当框架部分出现问题的时候,我们可以深入到框架内部调试问题,协助我们解决问题。

标准化的日志框架

我之所以会深入研究Java的日志框架,是源于在阿里工作的时候一段“痛苦”经历,有一次,我在本地调试程序,搞了一天,无论怎么折腾,日志就是打印不出来。

我只好深入到框架内部开始debug其源码,深入其内部之后,我才发现,这个看似简单的日志比我预想的要复杂,就拿我当时处理的系统来说,其内部有一个像迷宫一样的日志框架嵌套结构(下图)。

出现这个问题的根源在于日志系统标准的缺乏。日志系统在演进,作为应用,又不想改变使用日志的接口,所以就必须要使用各种Bridge(桥接)来在保证日志接口不变的情况下,替换下面的日志框架实现。

比如我一开始使用的是commons-logging,现在要替换为log4j,就需要一个jcl-over-log4j的Bridge。这样虽然我代码里面使用的还是commons-logging,但底层实现已经替换为log4j了。然后再升级logback…

在技术领域,这种缺乏标准带来的麻烦经常会出现,例如早期的浏览器因为缺乏标准,我们必须要多写很多JS代码去适配不同的浏览器。

所以标准很重要,好在,在Java社区,渐渐的是形成了日志标准SLF4J(Simple Logging Facade for Java),因为SLF4J是一个纯抽象接口,使用SLF4J可以做到应用使用日志和具体日志框架解耦的目的,可以说SLF4J是解决上面复杂日志框架迷宫的一把利器,也是通过依赖倒置解耦的典型案例。如果你不是Java应用,最好也要有这样的“中间层”去做解耦。

在SLF4J的众多实现中,logback是对SLF4J支持最好(原生支持),性能最好,也最简洁的框架实现。

所以,我前面说推荐使用SLF4J,实际上就是推荐SLF4J+logback的组合。SLF4J找到具体实现的过程,挺有意思,它不同于我们传统的接口+实现的方式,而是通过runtime classpath绑定的方式,来实现了一个类似于SPI的机制。

它具体是这么做的:

首先,SLF4J定义LoggerFactory,Logger,具体的Logger实现是通过LoggerFactory中的bind( )方法中的StaticLoggerBinder.getSingleton( )这行代码来实现的。

而这个StaticLoggerBinder实际上在SLF4J组件里是没有的,是需要具体的日志框架(logback,log4j等)提供的。

等一下,如果StaticLoggerBinder没有的话,SLF4J是怎么编译通过打包成组件的呢?这是因为SLF4J在源码中原本是有一个dummy StaticLoggerBinder实现,只是在打包过程中通过如下的antrun方式将其移除了:

<plugin>
  <groupId>org.apache.maven.plugins</groupId>
  <artifactId>maven-antrun-plugin</artifactId>
  <executions>
    <execution>
      <phase>process-classes</phase>
      <goals>
        <goal>run</goal>
      </goals>
    </execution>
  </executions>
  <configuration>
    <tasks>
      <echo>Removing slf4j-api's dummy StaticLoggerBinder and StaticMarkerBinder</echo>
      <delete dir="target/classes/org/slf4j/impl"/>
    </tasks>
  </configuration>
</plugin>

然后在logback中,通过提供了这个StaticLoggerBinder,这样在runtime的时候,只要classpath中有logback jar包,logback中的StaticLoggerBinder就会接续SLF4J中的那段代码,完成日志初始化和绑定的工作。

怎么样?是不是还挺有意思的。反正我在看到它这种实现方式之前,没想过还能这么玩。

运行时的日志级别调整

前面说的详细日志一般是在开发和测试的时候用,线上环境,一般我们不需要那么详细的日志。

但凡事都有例外,如果线上出现了啥疑难杂症,这些详细日志将会变得非常宝贵。这时,我们就需要调整日志的输出级别,把详细日志打开,帮助我们定位问题。

比如把日志级别从WARN调整为DEBUG,打印出更多的信息帮助我们定位问题,而这就需要我们有一种在Runtime调整日志级别的能力。

之所以,会把这个问题单独拿出来强调,是因为最近看到不少项目在代码里到处使用ERROR进行普通日志输出,问起原因,说是为了定位线上问题。

可是乱用ERROR不仅不优雅,而且还会扰乱报警系统。我想滥用ERROR的同学要么不知道日志级别能动态调整,要么不知道如何去动态调整。实际上,这个调整并不难。

首先,要想实现动态日志级别调整,你使用的日志框架要能支持动态调整的能力(如果没有,赶紧换一个),我们还是以logback为例,logback有两种方式可以做到runtime日志级别修改。

代码修改

代码修改的话,你需要写一段如下的代码,接收两个参数,一个是要修改的logger名称,另一个是要修改的级别。

public Response changeLogLevel(String logName, String logLevel) {
    LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
    Logger targetLogger = loggerContext.getLogger(logName);
    Level targetLevel = Level.valueOf(logLevel);
    targetLogger.setLevel(targetLevel);
    verifyChange(targetLogger, targetLevel);
    return Response.buildSuccess();
}

剩下的事情就是如何触发这段代码的问题了,触发的方式有很多,可以用REST,也可以用分布式配置系统的Listener,亦或是Spring Boot Actuator,Spring Boot Admin都可以, 选择一种适合自己的就好。

配置扫描

配置扫描就是在logback的配置文件中加上scan属性,如下所示,这个是在告诉logback每15秒reload一下配置文件,如果配置文件有变化会自动被pickup。这个方法不实用,了解就行,一般也不会这样去用。

<configuration scan="true" scanPeriod="15 seconds">
  //......
</configuration>

总而言之,我们应该构建一个系统运行时动态调整日志级别的能力,这样在需要的时候,我们可以方便的获取到更多的日志信息,而不是靠ERROR走江湖。

集中式日志管理

云原生里面有一个Immutable Infrastructure的概念,大意是说,最好不要动生产环境,因为修改生产环境会影响构建的一致性和生产系统的稳定性。

我之前就碰到一个同学因为在生产机器上vi 日志文件把系统搞崩的案例。但是传统的日志文件都是在服务器本地,想要做到“不触碰”除非把日志信息转移走。

实际上对于传统的把日志打印到本地文件,对于当前流行的微服务分布式架构来说,更好的做法是做集中式日志管理,这样我们就不需要去触碰生产环境,直接访问日志系统即可。

我最早接触集中式日志是在eBay工作的时候,eBay可以说是互联网分布式系统的先驱,在分布式系统的实践上积累了很多经验。

当年的taobao就是请的sun的工程师借鉴eBay的分布式架构搭建起来的。在eBay工作期间,给我留下印象最深的就是CAL(Centralized Application Logging)系统,使用CAL,技术人员可以方便的通过CAL查看应用日志、以及分布式系统之间的调用链关系。

CAL也是开发和测试使用最频繁的系统,测试发现一个bug,经常就会扔一个CAL的URL链接给开发,因为有些问题看日志基本就知道原因了。

很多从eBay出来的工程师都对CAL赞不绝口,其中有一位把这个思想带到了大众点评,做了CAT(Centralized Application Tracking),在业界的反响也很不错。

十几年前的CAL在当时的互联网绝对算的上是典型的大数据“高科技”产品,从零搭建一套这样的系统是非常困难的。

不过好在,时至今日,已经有很多商业的、开源的集中式日志系统可供选择。比如阿里的SLS,开源的Logstash等等。

本文完

原文摘自

https://blog.csdn.net/significantfrank/article/details/127994390