阅读 39

全面梳理 Java 日志框架

随着互联网和大数据的蓬勃发展,分布式日志系统以及日志分析系统得到了广泛地应用。目前,几乎在所有应用程序中,都会用到各种各样的日志框架来记录程序的运行信息。鉴于此,作为工程师,十分有必要熟悉主流的日志记录框架。

日志的有无虽然不影响应用程序的运行结果,但是没有日志的应用程序是不完整的,甚至可以说是有缺陷的。优雅的日志系统可以记录操作轨迹,监控系统运行状况以及回溯系统故障。在近来的面试中,我发现很多工作多年的应聘者对主流的日志框架仍然是一知半解,日常应用还停留在复制粘贴的层面,因此写作本文,希望对读者有所帮助。

本文将全面系统地介绍 Java 日志框架,主要内容如下:

  • 日志的意义与价值;
  • Java 日志框架进化史;
  • 日志门面与日志系统;
  • 日志框架的使用选择;
  • 日志使用中需要遵循的规范及注意事项;
  • 日志使用示例及常见报错。

第一部分:详细解读主流 Java 日志框架

1.日志的意义与价值

  • 在开发调试阶段: 日志系统有助于更快的定位问题。
  • 在应用运维阶段: 日志系统有助于记录大部分的异常信息,通过收集日志信息可以对系统的运行状态进行实时监控预警。
  • 在数据分析阶段: 日志中通常包含大量的用户数据,包括点击行为、兴趣偏好等,基于这些数据可以对用户进行“画像”,进而助力战略决策。随着大数据技术日渐成熟,海量日志分析已经在互联网公司得到广泛应用。

2.Java 日志框架进化史

在开发过程中,工程师不得不面对一个很现实的问题:Java “混乱”的日志框架体系。为什么说“混乱”呢?原因在于早期 Java 日志框架没有制定统一的标准,使得很多应用程序会同时使用多种日志框架。Java 日志框架的发展历程大致可分为以下几个阶段: 在这里插入图片描述

  • Log4j

Apache Log4j 是一种基于 Java 的日志记录工具,它是 Apache 软件基金会的一个项目。在 jdk1.3 之前,还没有现成的日志框架,Java 工程师只能使用原始的 System.out.println(), System.err.println() 或者 e.printStackTrace()。通过把 debug 日志写到 StdOut 流,错误日志写到 ErrOut 流,以此记录应用程序的运行状态。这种原始的日志记录方式缺陷明显,不仅无法实现定制化,而且日志的输出粒度不够细。鉴于此,1999 年,大牛 Ceki Gülcü 创建了 Log4j 项目,并几乎成为了 Java 日志框架的实际标准。

  • JUL

Log4j 作为 Apache 基金会的一员,Apache 希望将 Log4j 引入 jdk,不过被 sun 公司拒绝了。随后,sun 模仿 Log4j,在 jdk1.4 中引入了 JUL(java.util.logging)。

  • Commons Logging

为了解耦日志接口与实现,2002 年 Apache 推出了 JCL(Jakarta Commons Logging),也就是 Commons Logging。Commons Logging 定义了一套日志接口,具体实现则由 Log4j 或 JUL 来完成。Commons Logging 基于动态绑定来实现日志的记录,在使用时只需要用它定义的接口编码即可,程序运行时会使用 ClassLoader 寻找和载入底层的日志库,因此可以自由选择由 log4j 或 JUL 来实现日志功能。

  • Slf4j&Logback

大牛 Ceki Gülcü 与 Apache 基金会关于 Commons-Logging 制定的标准存在分歧,后来,Ceki Gülcü 离开 Apache 并先后创建了 Slf4j 和 Logback 两个项目。Slf4j 是一个日志门面,只提供接口,可以支持 Logback、JUL、log4j 等日志实现,Logback 提供具体的实现,它相较于 log4j 有更快的执行速度和更完善的功能。

  • Log4j 2

为了维护在 Java 日志江湖的地位,防止 JCL、Log4j 被 Slf4j、Logback 组合取代 ,2014 年 Apache 推出了 Log4j 2。Log4j 2 与 log4j 不兼容,经过大量深度优化,其性能显著提升。

3.日志门面与日志系统

在上文中已经提及,目前常用的日志框架有 Log4j,Log4j 2,Commons Logging,Slf4j,Logback,JUL。这些日志框架可以分为两种类型:门面日志和日志系统。

  • 日志门面:只提供日志相关的接口定义,即相应的 API,而不提供具体的接口实现。日志门面在使用时,可以动态或者静态地指定具体的日志框架实现,解除了接口和实现的耦合,使用户可以灵活地选择日志的具体实现框架。
  • 日志系统:与日志门面相对,它提供了具体的日志接口实现,应用程序通过它执行日志打印的功能。 在这里插入图片描述

如上图所示,Commons-Logging 和 Slf4j 属于日志门面框架,Log4j、Logback、和 JUL 则属于具体的日志系统框架。阅读至此,想必读者一定疑惑——为何如此设计?为何不简单一点?为何分成了门面和实现?

在回答上述问题之前,我们先一起简单回顾一下门面模式(软件设计模式的一种,也称外观模式、正面模式)。门面模式的核心为:外部客户端与一个子系统的通信,必须通过一个统一的外观对象进行,使得子系统更易于使用,其本质就是为子系统中的一组接口提供一个统一的高层接口,如下图所示: 在这里插入图片描述​ 门面模式的核心是门面对象 Facade,它有如下几个特点:

  • 知道所有子模块的责任和功能。
  • 将客户端发来的请求委派到子系统中,本身没有具体业务逻辑。
  • 不参与子系统内业务逻辑的实现。

了解过门面模式的基本信息,再回到最初的问题——为什么日志框架要使用门面模式呢?其实答案很简单,在工程开发中常遇到这样的场景:

  1. 我们自己的系统中使用了 Logback 这个日志系统;
  2. 我们的系统使用了 A.jar,A.jar 中使用的日志系统为 Log4j;
  3. 我们的系统又使用了 B.jar,而 B.jar 中使用的日志系统为 JUL。

在上述场景中,我们的系统需要同时支持并维护 Logback、Log4j、JUL 三种日志框架,其繁琐程度不言而喻。为了解决这个问题,可以引入一个适配层,由适配层决定具体使用哪一种日志系统,应用程序中的调用者只管打印日志,而不必关心日志是如何被打印出来的,如此,问题迎刃而解。显然,Slf4j 和 Commons-Logging 就是这种适配层,而 JUL、Log4j 和 Logback 等就是打印日志的具体实现。换言之,日志门面(适配层)只需要提供日志的接口,日志系统的具体实现则交由其它日志框架,这样就避免了需要维护复杂日志系统的问题。

4.避免环形依赖

Slf4j 的作者 Ceki Gülcü 当年因为觉得 Commons-Logging 的 API 设计的不好,性能也不够高,因而设计了 Slf4j。而他为了 Slf4j 能够兼容各种类型的日志系统实现,还设计了相当多的 adapter 和 bridge 来连接,如下图所示: 在这里插入图片描述

这些 adapter 和 bridge 在此就不做详细介绍,读者需要时可自行查阅上图找到对应的 jar 包。这里只想引出一个由此产生的问题,那就是日志框架的循环依赖问题。具体而言,如果在应用中使用 Slf4j 作为日志门面,就需要引入 slf4j-api-xx.jar,如果同时又引入了 slf4j-log4j12-xx.jar,log4j-xx.jar,log4j-over-slf4j-xx.jar 这几个包,在这种情况下,调用 slf4j-api 就会出现死循环(如下图所示)。 在这里插入图片描述

鉴于此,在引入日志框架依赖的时候要尽力避免,比如以下组合就不能同时出现:

  1. jcl-over-slf4j 和 slf4j-jcl
  2. log4j-over-slf4j 和 slf4j-log4j12
  3. jul-to-slf4j 和 slf4j-jdk14

5.日志框架的使用选择

5.1 日志框架之间的关系

在介绍日志框架的使用之前,简要回顾一下前面四节的内容。Commons Logging 和 Slf4j 是日志门面。Log4j 和 Logback 则是具体的日志实现方案。可以简单的理解为接口与接口的实现,调用者只需要关注接口而无需关注具体的实现,从而做到解耦。在整个日志框架中主要包括日志门面、日志适配器、日志库三个部分,它们之间的关系如下图所示: 在这里插入图片描述

5.2 日志框架的使用选择

比较常用的组合使用方式是 Slf4j 与 Logback 组合使用,Commons Logging 与 Log4j 组合使用,Logback 必须配合 Slf4j 使用。由于 Logback 和 Slf4j 是同一个作者,其兼容性不言而喻。这里顺便介绍一个小故事:Apache 曾试图说服 Log4j 以及其它的日志来按照 Commons-Logging 的标准编写,但是由于 Commons-Logging 的类加载机制在实际应用中存在问题(它使用 ClassLoader 寻找和载入底层的日志库),实现起来也不友好,因此 Log4j 的作者便开发了 Slf4j,与 Commons-Logging 两分天下。

关于如何选择日志框架,如果是新的项目 (没有历史包袱,无需切换日志框架),建议使用 Slf4j 与 Logback 组合,这样有如下的几个优点:

  1. Slf4j 实现机制决定 Slf4j 限制较少,使用范围更广。相较于 Commons-Logging,Slf4j 在编译期间便静态绑定本地的 Log 库,其通用性要好得多。

  2. Logback 拥有更好的性能。Logback 声称:某些关键操作,比如判定是否记录一条日志语句的操作,其性能得到了显著的提高,这个操作在 Logback 中只需 3 纳秒,而在 Log4j 则需要 30 纳秒。

  3. Slf4j 支持参数化,使用占位符号,代码更为简洁,如下例子。

    // 在使用 Commons-Logging 时,通常的做法是 if(log.isDebugEnabled()){ log.debug("User name: " + user.getName() + " buy goods id :" + good.getId()); } // 在 Slf4j 阵营,你只需这么做: log.debug("User name:{} ,buy goods id :{}", user.getName(),good.getId());

  1. Logback 的所有文档是免费提供的,Log4j 只提供部分免费文档而需要用户去购买付费文档。
  2. MDC (Mapped Diagnostic Contexts) 用 Filter,将当前用户名等业务信息放入 MDC 中,在日志 format 定义中即可使用该变量。具体而言,在诊断问题时,通常需要打出日志。如果使用 Log4j,则只能降低日志级别,但是这样会打出大量的日志,影响应用性能;如果使用 Logback,保持原定日志级别而过滤某种特殊情况,如 Alice 这个用户登录,日志将打在 DEBUG 级别而其它用户可以继续打在 WARN 级别。实现这个功能只需加 4 行 XML 配置。
  3. 自动压缩日志。RollingFileAppender 在产生新文件的时候,会自动压缩已经打出来的日志文件。压缩过程是异步的,因此在压缩过程中应用几乎不会受影响。

举例说明:如果直接使用 Slf4j 和 Logback 组合,可通过如下配置进行集成:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>${slf4j-api.version}</version>
</dependency>
<dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-classic</artifactId>
        <version>${logback.version}</version>
</dependency>
<dependency>
        <groupId>ch.qos.logback</groupId>
        <artifactId>logback-core</artifactId>
        <version>${logback.version}</version>
</dependency>
复制代码

对于已有工程,需要根据所使用的日志库来确定门面适配器从而使用 Slf4j。Slf4j 的设计思想比较简洁,使用了 Facade 设计模式,Slf4j 本身只提供了一个 slf4j-api-version.jar 包,这个 jar 中主要是日志的抽象接口,jar 包中本身并没有对抽象出来的接口做实现。对于不同的日志实现方案(例如 Logback,Log4j 等),封装出不同的桥接组件(例如 logback-classic-version.jar,slf4j-log4j12-version.jar),这样使用过程中可以灵活地选取自己项目里的日志实现。

举例说明,如果已有工程中使用了 Log4j 日志库,可通过如下配置进行集成:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>${slf4j-api.version}</version>
</dependency>
<dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>slf4j-log4j12</artifactId>
        <version>${slf4j-log4j12.version}</version>
</dependency>
<dependency>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
        <version>${log4j.version}</version>
</dependency>
复制代码

下面是 Slf4j 与其它日志组件调用关系图: 在这里插入图片描述

具体的接入方式参见下图: 在这里插入图片描述

如果老代码中直接使用非 Slf4j 日志库提供的接口打印日志,需要引入日志库适配器来桥接遗留的 api。在实际环境中我们经常会遇到不同的组件使用的日志框架不同的情况,例如 Spring Framework 使用的是日志组件是 Commons Logging,XSocket 依赖的则是 Java Util Logging。

如果在同一项目中使用不同的组件时,如何解决不同组件依赖的日志组件不一致的情况呢?这就需要统一日志方案,统一使用 Slf4j,把他们的日志输出重定向到 Slf4j,然后 Slf4j 又会根据绑定器把日志交给具体的日志实现工具。Slf4j 带有几个桥接模块,可以重定向 Log4j,JCL 和 java.util.logging 中的 Api 到 Slf4j。

举例说明:如果老代码中直接使用了 Log4j 日志库接口打印日志,需引入如下配置:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>${log4j-over-slf4j.version}</version>
</dependency>
复制代码

桥接方式参加下图: 在这里插入图片描述

5.3 排除项目中依赖的第三方包的日志依赖

在实际使用过程中,项目会根据需要引入一些第三方组件,例如常用的 Spring,而 Spring 本身的日志实现使用了 Commons Logging,如果想使用 Slf4j+Logback 组合,这时候需要在项目中将 Commons Logging 排除掉,通常会用到以下 3 种方案,各有利弊,可以根据项目的实际情况选择最适合自己项目的解决方案。

  • 方案一:采用 maven 的 exclusion 方案

    org.springframework spring-core commons-logging commons-logging ${springframework.version}

这种方案优点是 exclusion 是 maven 原生提供的,不足之处是如果有多个组件都依赖了 commons-logging,则需要在很多处增加 exclusion,比较繁琐。

  • 方案二:在 maven 声明 commons-logging 的 scope 为 provided

    commons-logging commons-logging 1.1.1 provided

这种方案虽然简洁,但也有缺点,在调试代码时有可能导致 IDE 将 commons-logging 放置在 classpath 下,从而导致程序运行时出现异常。

  • 方案三:在 maven 私服中增加类似于 99.0-does-not-exist 这种虚拟的版本号

    commons-logging commons-logging 99.0-does-not-exist

这种方案好处在于声明方式比较简单,用 IDE 调试代码时也不会出现问题,不足之处是 99.0-does-not-exist 这种版本是 maven 中央仓库中可能不存在,需要发布到自己的 maven 私服中。

第二部分:日志使用中需要遵循的规范及注意事项

在第一部分中,笔者介绍了常用的日志框架,本部分作为日志话题的延续,将结合具体案例介绍日志的使用。

1.日志的格式和级别

在使用日志框架的时候,可以根据应用的诉求在日志配置文件中去自定义日志打印格式和日志级别等信息。如下所示,为 logback.xml 配置样例,其中对配置文件中的关键信息做了解释,其它日志框架的使用示例将在下一部分介绍。

<?xml version="1.0" encoding="UTF-8"?>
<configuration debug="false">
<!--定义日志文件的存储地址 勿在 LogBack 的配置中使用相对路径-->
<property name="LOG_HOME" value="/home" />
<!-- 控制台输出 -->
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!--格式化输出:%d 表示日期,%thread 表示线程名,%-5level:级别从左显示 5 个字符宽度,%msg:日志消息,%n 是换行符-->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
</appender>
<!-- 按照每天生成日志文件 -->
<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
<!--日志文件输出的文件名-->
<FileNamePattern>${LOG_HOME}/TestWeb.log.%d{yyyy-MM-dd}.log</FileNamePattern>
<!--日志文件保留天数-->
<MaxHistory>30</MaxHistory>
</rollingPolicy>
<encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
<!-- 日志输出格式:%d 表示日期时间,%thread 表示线程名,%-5level:级别从左显示 5 个字符宽度 %logger{50} 表示 logger 名字最长 50 个字符,否则按照句点分割。 %msg:日志消息,%n 是换行符 -->
<pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
</encoder>
<!--日志文件最大的大小-->
<triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
<MaxFileSize>10MB</MaxFileSize>
</triggeringPolicy>
</appender>

<!-- 日志输出级别 -->
<root level="INFO">
<appender-ref ref="STDOUT" />
</root>
</configuration>
复制代码

1.1 日志命名和保持期限

在公开的阿里巴巴 java 开发手册中对日志规范也有相关介绍,在此,笔者介绍其中两条规范,即日志命名方式和日志保存期限。

  • 日志命名方式:

    appName_logType_logName.log。

其中 appName 表示应用名;logType 表示日志类型,推荐分类有 stats,monitor,visit 等;logName 为日志描述,这种命名好处是可以快速清晰地了解日志文件类型和目的,便于归类查找。

  • 日志保持期限:

如何确定日志保持期限是个比较棘手的问题,如果日志存放时间过长,会消耗大量存储资源,甚至会导致磁盘压力过大影响系统稳定性;如果日志存放时间过短,可能导致日志数据“丢失”,出现问题时无法追溯。阿里 java 开发手册中对日志文件保存期限的建议是至少保存 15 天。在实际应用中,可以根据日志文件的重要程度、文件大小以及磁盘空间自行调整,此外,还可以对日志进行监控,定期转储。

1.2 日志等级

通常,日志记录的优先级分为 OFF、FATAL、ERROR、WARN、INFO、DEBUG、ALL 或自定义的级别。Log4j 建议只使用四个级别,优先级从高到低分别是 ERROR、WARN、INFO、DEBUG。通过在日志框架的配置文件中设置日志级别,可以控制应用程序中相应级别的日志信息开关。比如配置为 INFO 级别,那么只有等于及高于这个级别的日志才进行处理,应用程序中所有 DEBUG 级别的日志信息不会被打印出来。需要说明的是,日志等级不仅关乎“详细程度”,还关系到适用场景、服务对象等。常见日志等级的说明如下:

  • ALL:打印所有的日志。
  • OFF:关闭所有的日志输出。
  • ERROR:错误信息,包括错误的类型,错误的内容,位置和场景,是否可恢复等。只有当错误会影响到系统的正常运行时,才作为信息输出。
  • WARN:起到提醒作用,虽然应用程序目前运行正常,但存在隐含的风险。
  • INFO:记录系统的基本运行过程、运行状态、关键信息。
  • DEBUG:系统运行过程与状态的细节信息,可用于调试。
  • TRACE:系统结构与内容的细节信息,比如一些关键对象的内容,函数调用参数、结果等。

1.3 日志格式

通过配置日志输出格式可以控制输出日志信息的内容和样式。以上面日志配置文件 logback.xml 为例,其中 pattern 标签定义了日志的输出格式,默认参数如下表格所示。

参数

含义

%d

输出日志时间点的日期或时间,如:%d{yyyy-MM-dd HH:mm:ss.SSS}

%thread

输出产生该日志事件的线程名

%-5level

日志级别,从左显示 5 个字符宽度

%msg

输出日志消息,即输出代码中指定的消息

%n

输出一个回车换行符,Windows 平台为“\r\n”,Unix 平台为“\n”

除了上述默认的日志格式参数,Logback 还支持日志格式自定义配置,比如,希望每条日志能打印 ip 地址,实现方式如下:

  • step1:新建一个类 IPLogConfig,重写 convert 方法,实现 ip 获取。

    public class IPLogConfig extends ClassicConverter { @Override public String convert(ILoggingEvent event) { try { return InetAddress.getLocalHost().getHostAddress(); } catch (UnknownHostException e) { e.printStackTrace(); } return null; } }

step2: 修改 logback.xml 配置。

<!--配置规则类的位置-->
<conversionRule conversionWord="ip" converterClass="com.test.conf.IPLogConfig" />
 <appender name="Console" class="ch.qos.logback.core.ConsoleAppender">
        <layout>
            <pattern>[ip=%ip] %d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level %logger{50} - %msg%n</pattern>
        </layout>
    </appender>
复制代码

与 Logback 的日志输出格式配置相比,log4j 的输出格式配置有所不同,主要参数配置如下所示:

参数

含义

%m

输出代码中指定的消息

%p

输出优先级,即 DEBUG,INFO,WARN,ERROR,FATAL

%r

输出自应用启动到输出该日志信息耗费的毫秒数

%c

输出所属的类目,通常就是所在类的全名

%t

输出产生该日志事件的线程名

%n

输出一个回车换行符,Windows 平台为“\r\n”,Unix 平台为“\n”

%d

输出日志时间点的日期或时间,默认格式为 ISO8601,也可以在其后指定格式,比如:%d{yy MMMM dd HH:mm:ss,SSS}

%l

输出日志事件的发生位置,包括类目名、发生的线程,以及在代码中的行数

%F

输出日志消息产生时所在的文件名称

2.日志使用注意事项

本节将结合例子介绍日志应用中需要注意的基础事项,如异常记录、对象实例记录、日志监控、日志分类等。

2.1 异常日志如何记录

记录异常时一定要输出异常堆栈信息。如果没有完整的堆栈信息,那么一旦应用程序出现异常,维护人员将很难定位问题。

示例:某应用对处理链路进行功能点的拆分,每个功能点的失败都会抛异常。在服务入口处对异常日志进行分类记录。

try {
        this.startOrderProcess(request, result, processName);
} catch (ProductBizException e) {
        if (CollectionUtils.isNotEmpty(e.getErrorMessages())) {
                e.getErrorMessages().forEach(errorMessage -> {
                    log.error("biz process error" + e.getMessage(), e);
                });
        }
} catch (ProductSystemException ex) {
        log.error("system error" + ex.getMessage(), ex);
} catch (TMFRuntimeException e) {
        ErrorMessage errorMessage = e.getErrorMessage();
        if (null != errorMessage) {
                log.error("tmf runtime error" + e.getMessage(), e);
        }
}
复制代码

2.2 对象实例如何记录

日志中如果输出对象实例,要确保实例类重写了 toString 方法,否则只会输出对象的 hashCode 值,毫无意义。此外,也可以通过 java 反射来获取对应的属性。主要好处是当增加或修改属性的时候,不需要修改 toString 方法,通常采用 fastjson 将对象转换成 json 对象。

示例:在某项目中,有一处 debug 级别的日志信息需要记录服务调用方的请求参数,因此,对 ProductQueryRequest 对象实例重写了 toString 方法,以获取完整的对象信息。

// 采用 slf4j 中占位符输出形式记录 debug 信息
logger.debug("query request: {}", productQueryRequest);

// 其中 ProductQueryRequest 对象重写了 toString 方法
@Override
public String toString() {
        return "ProductQueryRequest{" +
            "queryOption=" + queryOption +
            ", productIds=" + productIds +
            ", MemberId=" + MemberId +
        '}';
}
复制代码

2.3 日志记录如何分类

日志分类建议从功能上分为监控日志、统计日志、访问日志。

  • 监控日志:

这里的监控日志不包括统计信息,当然统计信息和访问信息均可以配置为监控信息。监控日志是开发人员需要重点关注的,因为监控日志直接关系到系统的稳定性和运维难度。典型的监控日志有请求入口和出口;外部服务调用和返回;资源消耗操作: 如读写文件等;容错行为: 如云硬盘的副本修复操作; 程序异常: 如数据库无法连接;后台操作: 定期执行删除的线程;启动、关闭、配置加载等。

  • 统计日志:

用户访问统计,如用户 IP,上传下载的数据量,请求 qps 情况,请求 rt 等。统计日志对格式需要严格要求,以便统计。实践中,应针对具体的日志分析平台来设计日志格式,便于对数据进行统计分析。

  • 访问日志:

该类日志一般在 nginx 层直接记录,如应用的 access.log,数据格式也基本统一。也可以使用相关日志分析平台来对访问日志进行统计分析。

2.4 日志级别如何判断

在实践中,常用的日志级别有 debug、info、warn、error 四个级别,那么应如何具体判断日志的归属级别呢?

  • error:

记录较重要的错误信息(注:参数检查不通过这种不是 error)。通常情况下,exception 的出现均可以认为是 error 级别的。比如查询用户信息服务获取用户信息失败的,读取文件信息返回 IOException 的,功能模块执行异常的等。

  • warn:

记录较重要的提示信息,如请求参数校验不通过、部分不重要的异常、非正常的条件分支(业务流程预期不符)、请求服务获取的结果为空的(潜在的风险)等。

  • info:

记录可用于业务数据统计、监控、定位一般问题的信息,如系统状态变化日志,业务流程的核心处理、关键动作,业务流程的状态变化。

  • debug:

记录调试信息,如 request/response。通常,在开发中和上线前期 debug 日志才会打开,随着系统稳定会关闭 debug 开关,只有当出现棘手的问题时才会根据需要开启。

2.5 日志数据如何监控

通过对日志中的关键字进行监控,可以及时发现系统故障并报警,对系统运维至关重要。服务的监控和报警是一个很大的话题,本节只介绍日志监控报警需要注意的一些问题:

  1. 非必要,不报警,只有需要运维马上处理的错误才需要发送报警。这样做的原因是避免长期的报警骚扰让运维人员对报警不再敏感,最后变成“狼来了”的故事;
  2. 明确报警关键字,例如用 ERROR 作为报警的关键字,而不是各种各样的复杂规则。这样做的原因是日志监控本质上是不断地进行字符串匹配操作,如果规则太多太复杂,就可能对线上服务产生影响;
  3. 对于一些预警操作,例如某个服务需要重试多次才能成功,或者某个用户的配额快用完等,可以通过每天一封报警邮件的方式来反馈;
  4. 每一次系统出现故障,都需要及时检查日志报警是否灵敏,日志报警的描述是否准确等,不断优化日志报警;

监控配置规范

项目

规范

覆盖率

重大问题故障类、财务资损类、用户投诉类,监控通常须 100% 覆盖

分层监控

监控内容要涵盖系统监控、JVM 监控、关键中间件监控、集群链路监控、依赖上下游业务监控、自身业务监控

多维度分析

监控形式包括:线下和预发环境可以自动化跑全量业务监控、线上重要功能短周期定时单机监控、线上全量功能周期自动化执行监控、线上流量错误率等大盘分析指标实时监控、离线分析业务指标大盘监控

误报率

监控配置后,要跟进数据结果合理设置预警,预警配置后要持续优化直到不再出现误报

2.6 日志文件的大小

日志文件不宜过大,过大的日志文件会降低日志监控、问题定位的效率。因此需要进行日志文件的切分,具体而言,按天来分割还是按照小时分割,可以根据日志量来决定,原则就是方便开发或运维人员能快速查找日志。如下配置所示,日志文件大小定义为 20M,按天来做文件分割,并保留最近 15 天的数据。

<rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
       <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.%i.log</fileNamePattern>
       <maxHistory>15</maxHistory>
       <maxFileSize>20MB</maxFileSize>
       <totalSizeCap>20GB</totalSizeCap>
</rollingPolicy>
复制代码

为了防止日志文件将整个磁盘空间占满,需要定期对日志文件进行删除。例如,在收到磁盘报警时,可以将一周以前的日志文件删除或者转储。在实践中,日志转储/删除应实现自动化,当系统监控发现磁盘空间使用率超过设定的阈值时,便根据日志文件名标注的日期进行转储/删除。

第三部分:日志使用示例及常见报错

承接前面两部份,本部份将介绍几种主流日志框架的使用示例和常见的报错。为了便于读者理解,文中的报错案例力求信息完整,并给出了测试代码,感兴趣的读者,可以通过示例快速实践。

1.日志框架使用示例

1.1 Log4j 使用示例

  • maven 依赖:

    log4j log4j 1.2.17

  • 配置文件:

log4j.properties

### 设置
log4j.rootLogger = debug,stdout,INFO
### 输出信息到控制台,测试的时候便于观察,实际应用中不配置 ###
log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern = [%-5p] %d{yyyy-MM-dd HH:mm:ss,SSS} method:%l%n%m%n
### 输出 INFO 级别以上的日志到指定文件
log4j.appender.INFO = org.apache.log4j.DailyRollingFileAppender
log4j.appender.INFO.File = ~/Code/logs/log4j.log
log4j.appender.INFO.Append = true
log4j.appender.INFO.Threshold = info 
log4j.appender.INFO.layout = org.apache.log4j.PatternLayout
log4j.appender.INFO.layout.ConversionPattern = %-d{yyyy-MM-dd HH:mm:ss}  [ %t:%r ] - [ %p ]  %m%n
复制代码

  • 测试代码:

    public class Log4jTest { private static final Logger LOGGER = Logger.getLogger(Log4jTest.class);

    public static void main(String[] args) {
    
        LOGGER.info("log test");
        try {
            ((Object) null).toString();
    
        } catch (Exception e) {
            LOGGER.info("exception info", e);
        }
        LOGGER.info("This is log4j. Thread=" + Thread.currentThread().getName());
    }
    复制代码

    }

  • 日志输出:

    2019-10-31 21:05:36 [ main:0 ] - [ INFO ] log test 2019-10-31 21:05:36 [ main:5 ] - [ INFO ] exception info java.lang.NullPointerException at Log4jTest.main(Log4jTest.java:18) 2019-10-31 21:05:36 [ main:9 ] - [ INFO ] This is log4j. Thread=main

1.2 commons-logging 使用示例

本例中,使用 Commons-Logging (也称为 JCL) 作为日志门面提供统一的日志接口,Log4j 作为具体的日志实现。

  • maven 依赖:

    commons-logging commons-logging 1.2 log4j log4j 1.2.17

  • 配置文件

1.commons-logging.properties

org.apache.commons.logging.Log=org.apache.commons.logging.impl.Log4JLogger
复制代码

2.log4j.properties

### 设置
log4j.rootLogger = debug,stdout,INFO
### 输出信息到控制台 ###
log4j.appender.stdout = org.apache.log4j.ConsoleAppender
log4j.appender.stdout.Target = System.out
log4j.appender.stdout.layout = org.apache.log4j.PatternLayout
log4j.appender.stdout.layout.ConversionPattern = [%-5p] %d{yyyy-MM-dd HH:mm:ss,SSS} method:%l%n%m%n
### 输出 INFO 级别以上的日志到指定文件
log4j.appender.INFO = org.apache.log4j.DailyRollingFileAppender
log4j.appender.INFO.File = ~/Code/logs/jcllog4j.log
log4j.appender.INFO.Append = true
log4j.appender.INFO.Threshold = info 
log4j.appender.INFO.layout = org.apache.log4j.PatternLayout
log4j.appender.INFO.layout.ConversionPattern = %-d{yyyy-MM-dd HH:mm:ss}  [ %t:%r ] - [ %p ]  %m%n
复制代码

  • 测试代码:

    public class JclTest { private static final Log LOGGER = LogFactory.getLog(JclTest.class);

    public static void main(String[] args) {
    
        LOGGER.info("log test");
        try {
            ((Object) null).toString();
    
        } catch (Exception e) {
            LOGGER.info("exception info", e);
        }
        LOGGER.info("This is jcl log. Thread=" + Thread.currentThread().getName());
    }
    复制代码

    }

  • 日志输出:

    2019-10-31 21:30:42 [ main:0 ] - [ INFO ] log test 2019-10-31 21:30:42 [ main:4 ] - [ INFO ] exception info java.lang.NullPointerException at JclTest.main(JclTest.java:19) 2019-10-31 21:30:42 [ main:6 ] - [ INFO ] This is jcl log. Thread=main

1.3 slf4j 使用示例

本例中,使用 Slf4j 作为日志门面提供统一的日志接口,Logback 作为具体的日志实现。

  • maven 依赖:

    org.slf4j slf4j-api 1.7.28 ch.qos.logback logback-classic 1.2.3 ch.qos.logback logback-core 1.2.3

  • 配置文件:

logback.xml

<configuration debug="true" scan="true" scanPeriod="1 seconds">
    <contextName>logback</contextName>
    <property name="app.name" value="~/Code"/>
    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
        <encoder>
            <pattern>%d [%thread] %-5level %logger{36} [%file : %line] - %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="file" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${app.name}/logs/slf4jlogback.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${app.name}/logs/slf4jlogback.%d{yyyy-MM-dd.HH}.log.gz</fileNamePattern>
            <maxHistory>60</maxHistory>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <maxFileSize>100MB</maxFileSize>
        </triggeringPolicy>
        <encoder>
            <pattern>%d [%thread] %-5level %logger{36} [%file : %line] - %msg%n</pattern>
        </encoder>
    </appender>
    <root level="info">
        <appender-ref ref="stdout"/>
        <appender-ref ref="file"/>
    </root>
</configuration>
复制代码

  • 测试代码:

    public class Slf4jTest { private static final Logger LOGGER = LoggerFactory.getLogger(Slf4jTest.class);

    public static void main(String[] args) {
    
        LOGGER.info("log test");
        try {
            ((Object) null).toString();
    
        } catch (Exception e) {
            LOGGER.info("exception info", e);
        }
        LOGGER.info("This is slf4jLogback log. Thread=" + Thread.currentThread().getName());
    }
    复制代码

    }

  • 日志输出:

    019-10-31 21:26:17,806 [main] INFO Slf4jTest [Slf4jTest.java : 17] - log test 2019-10-31 21:26:17,811 [main] INFO Slf4jTest [Slf4jTest.java : 22] - exception info java.lang.NullPointerException: null at Slf4jTest.main(Slf4jTest.java:19) 2019-10-31 21:26:17,811 [main] INFO Slf4jTest [Slf4jTest.java : 24] - This is slf4jLogback log. Thread=main

2.常见报错案例

2.1 找不到绑定器

如下图所示,应用使用的是 Slf4j 标准接口,目标日志框架为 Log4j,但是没有引入绑定器(slf4j-log4j12)。 在这里插入图片描述

  • maven 依赖:

    org.slf4j slf4j-api 1.7.28 log4j log4j 1.2.17

运行测试代码将会报错,提示加载绑定器失败,具体内容如下:

SLF4J: Failed to load class "org.slf4j.impl.StaticLoggerBinder".
SLF4J: Defaulting to no-operation (NOP) logger implementation
SLF4J: See http://www.slf4j.org/codes.html#StaticLoggerBinder for further details.
复制代码

2.2 配置了多个绑定器

如下图所示,应用使用的是 Slf4j 标准接口,目标日志框架为 Log4j,但是同时引入了两个日志绑定器。 在这里插入图片描述​ 存在问题的 maven 依赖如下所示:

<!-- slf4j -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.28</version>
</dependency>
<!-- Log4j2 -->
<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>
<!-- binder -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.7.28</version>
</dependency>
<dependency>
    <groupId>org.apache.logging.log4j</groupId>
    <artifactId>log4j-slf4j-impl</artifactId>
    <version>2.12.1</version>
</dependency>
复制代码

这种情况下,将无法按照预期打印日志,应用会加载默认的日志配置,将日志打印到控制台,详细的错误信息如下:

SLF4J: Class path contains multiple SLF4J bindings.
SLF4J: Found binding in [jar:file:/Users/test/.m2/repository/org/slf4j/slf4j-log4j12/1.7.28/slf4j-log4j12-1.7.28.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: Found binding in [jar:file:/Users/test/.m2/repository/org/apache/logging/log4j/log4j-slf4j-impl/2.12.1/log4j-slf4j-impl-2.12.1.jar!/org/slf4j/impl/StaticLoggerBinder.class]
SLF4J: See http://www.slf4j.org/codes.html#multiple_bindings for an explanation.
SLF4J: Actual binding is of type [org.slf4j.impl.Log4jLoggerFactory]
复制代码

2.3 循环依赖

如下图,应用使用的是 Slf4j 标准接口,目标日志框架为 Log4j,但是同时引入了两个日志绑定器: log4j-over-slf4j 和 slf4j-log4j12,如此将会出现循环依赖。 在这里插入图片描述​ 存在循环依赖问题的 maven 配置如下:

<!-- slf4j -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-api</artifactId>
    <version>1.7.28</version>
</dependency>
<!-- Log4j2 -->
<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>1.2.17</version>
</dependency>
<!-- binder -->
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>slf4j-log4j12</artifactId>
    <version>1.7.28</version>
</dependency>
<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>1.7.28</version>
</dependency>
复制代码

出现循环依赖问题时,日志系统将无法正常启动,进而导致应用无法启动,详细的错误信息如下:

SLF4J: Detected both log4j-over-slf4j.jar AND bound slf4j-log4j12.jar on the class path, preempting StackOverflowError. 
SLF4J: See also http://www.slf4j.org/codes.html#log4jDelegationLoop for more details.
Exception in thread "main" java.lang.ExceptionInInitializerError
    at org.slf4j.impl.StaticLoggerBinder.<init>(StaticLoggerBinder.java:72)
    at org.slf4j.impl.StaticLoggerBinder.<clinit>(StaticLoggerBinder.java:45)
    at org.slf4j.LoggerFactory.bind(LoggerFactory.java:150)
    at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:124)
    at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:412)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:357)
    at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:383)
    at Log4jTest.<clinit>(Log4jTest.java:13)
Caused by: java.lang.IllegalStateException: Detected both log4j-over-slf4j.jar AND bound slf4j-log4j12.jar on the class path, preempting StackOverflowError. See also http://www.slf4j.org/codes.html#log4jDelegationLoop for more details.
    at org.slf4j.impl.Log4jLoggerFactory.<clinit>(Log4jLoggerFactory.java:54)
    ... 8 more
复制代码

文章分类
后端
文章标签