博客

希望用易懂的方式讲解如何使用 Log4j 来管理 Java 程序的日志

动机

最近在工作中遇到了日志文件占用过多磁盘空间的状况。

具体来说是:一个运行在服务器上的 Java 程序每日生成 1.5 GB 的日志,而那台服务器的硬盘容量只有 150GB,所以程序上线运行几个月后磁盘空间就满了。

因为程序已经使用 Log4j 来生成日志,所以解决方式是配置启用了 Log4j 的轮转模式 (Rotation)。

在日志轮转的基础上,我还启用了 Log4j 另外两个很有用的小功能,也将在文章最后提及。

这篇文章将 讲解如何配置 Log4j 和实现日志轮转的方式

 

阅读前须知 / Prerequisite

这篇文章主要写给 已经在 Java 程序中使用 Log4j 生成日志,但想了解 / 配置轮转模式 的开发者。

而对于 仍还未使用过 Log4j 的读者,那么这篇文章会缺少 Log4j 的使用细节。

在讲解如何设置 Log4j 的日志轮转之前,我想先简单介绍 Log4j 的XML配置文件。

配置文件包含了记录器和输出器的定义,而日志轮转实际上是由一个特殊的输出器来实现的。

我将尽可能地把英文翻译成中文,比如 Configuration - 配置,Logger - 记录器,Appender - 输出器 。

 

导入依赖库

Log4j 是一个第三方的库,所以需要下载并把它导入项目。

企业的 Java 项目通常使用一些项目编译工具,常见的有 Maven 和 Gradle。它们能自动下载需要的库,并把它们和我们的项目代码一同编译。

我的项目用的是 Gradle,所以添加这两行到 build.gradle 文件中的 dependencies 里。

dependencies {
    compile group: 'org.apache.logging.log4j', name: 'log4j-api', version: '2.12.1'
    compile group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.12.1'
}

注意,这里我们用的是 2.0 以上的版本。

如果你用的是其他包管理工具,导入方式可以参考官网

当然啦,如果没有用任何工具,也可以在官网下载 Jar 文件,在 Classpath 中手动添加他们的完整路径。

 

系统参数

这篇文章的讲解将基于用 XML 文件来设置 Log4j 的日志功能。

(如果你想写代码来配置 Log4j ,那么这里的部分概念和原理的讲解依然值得参考)

首先在我们的项目里,创建 log4j2.xml 文件,如果你们的项目已经有专门放配置文件的目录,比如Config 或者 Configurations,那就放这个目录下。如果你的项目已经有 log4j2.xml 则不必新建啦。

那么程序运行时怎么知道去哪找这个文件呢 ?答案是通过系统属性 / System Property

最简单的做法是在程序启动时传入这个参数:

-Dlog4j2.configurationFile=/[完整路径]/log4j2.xml

参数的前缀-D意味着:虚拟机将定义一个名叫 log4j2.configurationFile 系统属性,供程序运行时查询它。

如果你也用 IDE 开发的话,可以在运行配置 (Run / Debug Configuration) 里可以找到 VM options, 把这个参数加入,这样在 IDE 运行程序时也将利用 Log4j 的配置。

因为人们通常希望在开发和测试时使用不同的日志生成方式,常常会创建多个配置文件。Log4j 也能够在不同条件下使用不同的配置文件的,但这篇文章并不涉及。

如果你想了解 Log4j 具体如何查找配置文件,可以阅读这个文档

 

配置文件

前一节里我们创建了log4j2.xml,并让程序获知了它的位置,现在我们要编写配置文件啦。

官网的入门教程会提供一个最基础的配置文件,大概是这样的。

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
  <Appenders>
    <Console name="Console" target="SYSTEM_OUT">
      <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
    </Console>
  </Appenders>
  <Loggers>
    <Root level="error">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>
</Configuration>

不论多复杂的配置文件都将是同样的结构,它们都有这几个组成部分:

Configuration, Appenders 和 Loggers。

因为配置文件的格式是 XML ,第一行涵盖了当前 XML 文件的基本信息。

 

配置 / Configuration

可以这么想,Log4j 库每次启动时都会构建一个配置对象,其中存着各种配置信息:日志的生成格式,日志文件怎么命名,是否轮转,等等。

而我们所写的配置文件也就是在描述这个对象,所以最外层是 Configuration。

它有一个 status 属性,值可以是 TRACE, DEBUG 等等,表示 Log4j 运行时本身生成的日志的详细程度

你可以把它设置成 DEBUG,随后在命令行运行时将看到 Log4j 的一些运行细节,比如往哪个文件写入了多少日志信息,日志是从哪些类 / 对象生成的,等等。

 

输出器 / Appenders

我们必须 至少定义一个输出器,这样程序运行时,日志才能被写到某个地方供之后查看。

可以这么理解,每个输出器定义了 它们接收到日志信息后

1)以什么样的格式(是否加上时间戳日期等等)写出去,和

2)写到哪。可以是控制台,也可以是文件,甚至是网络通道 / Socket。

复杂的项目往往有多个输出器,将日志写往不同的地方。

<Console name="Console" target="SYSTEM_OUT">
  <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
</Console>

比如在最基础的配置文件中,有一个名叫 Console / 控制台 的输出器。

它包含一个 PatternLayout,它的 pattern 属性定义了日志中每一行信息的格式,比如按照这里的定义,输入日志的每一行都将有时间信息,信息分级 / level,和最后的日志信息本身,将出现在 %msg 的位置。

那么这个控制台输出器将日志写到哪呢 ?从它的 target 属性 能看出,是进程的标准输出。

 

另外,有读者可能想问这个不是叫 Console 吗,怎么不叫 XXAppender 呢 ?实际上,每一个输出器组件的名称对应了 Log4j 包中的一个类的名称,可以把它们看作是实现了 Appender 接口的的类。

如果能读到 Log4j 的源代码的话,就能找到一个叫 Console 的类。当然啦,Log4j 也支持导入我们自己写的输出器,具体见官网。

另外,我们可以通过 name 属性值设置名字,在 Logger 中的 AppenderRef 将指向它,稍后会讲到。

  <Loggers>
    <Root level="error">
      <AppenderRef ref="Console"/>
    </Root>
  </Loggers>

 

记录器 / Loggers

每个记录器定义了不同级别和来源的信息将被送往哪个输出器。通常我们也会有多个记录器。

最基础的配置里,我们会有一个 Root / 根记录器,意味着所有的信息都将经过它。它的定义也很简单粗暴,只要日志信息的级别是 ‘错误’,都将被送往控制台输出器,

我们因此能够在程序运行时,在控制台 (进程默认的标准输出) 只会看到错误信息,其他信息则被不输出。

要注意的是,每个记录器内都有一个 AppenderRef,它的 ref 属性值必须对应输出器的 name 属性

 

轮转输出器 / Rolling Appender

介绍完配置文件中的几个基本组成后,终于可以开始讲讲如何设置轮转模式啦。

还记得吗,真正决定了日志信息如何被写和被写到哪的是 输出器 。这里我们就要用到 Log4j 提供的一个叫 RollingRandomAccessFile 的输出器啦,你可以把 Appenders 中的 Console 组件替换成下面这个。

<Appenders>
  <RollingRandomAccessFile name="fileAppender">
    <!--	内容随后添加 -->
    </RollingRandomAccessFile>
</Appenders>

 

日志轮转 / Log Rotation

这个做法 / 技术起源于这样一个情景。想象一下,我们在命令行里像这样启动了程序,随后便不再管它。

./my_program.sh > program.log &

那么程序运行时生成的所有日志信息都将被写到这个 program.log文件中。如果程序的日志信息很多,那么可能没多久后日志文件就变得非常大,比如达到数个千兆 / GB的大小。

这样当我们想阅读 / 查找某些日志信息时,将非常困难,因为这意味着文本阅读器要将很大的文件加载到内存,而在数百兆的文件中搜索字符串也将比较耗时。

日志轮转的做法随之出现:人们就把日志信息按时间放到不同的文件里,比如今天晚上7点到9点的日志将被分别放到这三个文件里。

program.log.2019-08-21-19
program.log.2019-08-21-20
program.log.2019-08-21-21

这样人们想要阅读日志信息时,也能直接定位到具体时间段的日志。通常人们要查看日志的原因就是程序出错了,而对于程序出错的时间,人们总是有大概估计的。

 

旧日志管理

日志轮转 / 按时间来分类日志文件的另一个好处是,管理旧日志和清理不需要的日志变得方便许多。

比如,我们知道哪些文件里存的是若干天 / 月前的程序日志,将它们删除,获得更多可用的硬盘空间。

我们也可以每天都将一天前的日志自动压缩,减小硬盘空间占用。

当然,在多少天前的 / 什么样的日志是没用的这个问题上,不同程序和不同人都有不同的理解。

 

配置轮转输出器

现在我们就要配置之前加到 Appenders 内的这个 RollingRandomAccessFile 输出器啦。

首先可以在它的内部加上 PatternLayout,定义每行条日志信息的被输出的格式,向上文的 Console 里那样。

然后要加的是两个重要属性 fileName 和 filePattern,我将逐一介绍。

fileName

这个表示的是在下一次的轮转发生以前,当下日志将被写到的文件的路径,也可以把它称作 当前日志文件

那么轮转什么时候会发生呢,随后会讲到,我们可以自定义轮转触发的条件,比如时间。

filePattern

它表示轮转发生之后,当前日志文件 将被重命名成什么。如果我们像下面这样定义它们,

  <RollingRandomAccessFile name="fileAppender"
			fileName="app-name.log"
      filePattern="app-name.log.%d{yyyy-MM-dd-HH}" >
    <PatternLayout 
      pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n" />
<RollingRandomAccessFile/>

比如我们在19点启动了程序,运行后 log4j 将立刻生成这个文件,里面存着不断增加的日志信息。

app-name.log

假设我们定义了按小时轮转 (下一节讲解),那么在20点时,app-name.log 将被清空,它的内容被移到这:

app-name.log.2019-08-21-19

它将包含着从程序19点运行开始,一直到 20:00 所产生的所有日志信息。

也可以这样想,在 20:00 时,log4j 把之前的 app-name.log 重命名成了 app-name.log.2019-08-21-19,再把 app-name.log清空以接收 20:00 之后的日志。这也就是日志轮转的具体结果。

再过若干个小时,我们也就能看到更多的日志文件啦。

app-name.log.2019-08-21-20
app-name.log.2019-08-21-21
..

 

轮转触发条件 / Triggering Policy

我们通过 fileName 和 filePattern 定义了日志轮转前后的命名方式,现在要定义轮转发生的条件啦。

最简单直接的方式就是按时间触发是日志轮转。

TimeBasedTriggeringPolicy加入 RollingRandomAccessFile 里。

<RollingRandomAccessFile>
    <!-- 省略了其他内容 -->
    <TimeBasedTriggeringPolicy />
</RollingRandomAccessFile>

需要注意的是,如果只按时间轮转日志,这个是一定要加的,因为 Log4j 并没有默认的轮转条件。

可以尝试一下把这行注释掉,将配置的 status 设为 DEBUG,再启动程序,将看到 Log4j 报错。

你可能想问,这一行什么好像什么也没说啊,如果我想每分钟轮转一次,该怎么配置呢?

Log4j 在这方面比较智能,它将根据 filePattern 中定义的文件名格式来判断轮转的具体频率

也就是说,如果我们把它改为下面这样,日志轮转就会每分钟发生一次啦。

filePattern="app-name.log.%d{yyyy-MM-dd-HH-mm}"

 

根据日志容量轮转

也有时候人们觉得,简短的日志文件查看起来更方便一些,就希望当日志文件积累到一定大小时再轮转。

那么应对这种需求,可以用的就是 SizeBasedTriggeringPolicy,把它加入输出器内就好啦。

它的 size 属性值定义了日志达到多少容量后将触发轮转,可以是 “4 KB” 也可以是 “1 GB“ 。

也可以把它看作,每个日志文件占用空间的上限

<RollingRandomAccessFile>
    <!-- 省略了属性等等 -->
    <SizeBasedTriggeringPolicy size="16 KB" />
</Policies>

 

那么你可能想问了,按容量触发的轮转发生后,生成的文件叫什么呢 ?这仍取决于 filePattern

举个例子,如果轮转每 16 KB 发生一次,而程序在19点和20点之间生成了33KB的日志。

如果用之前的 filePattern="app.log.%d{yyyy-MM-dd-HH}" 定义,最终只会两个文件。

app-name.log
app-name.log.2019-08-21-19

具体发生了什么呢 ?

一开始,最早的 16KB 日志信息被陆续写到 app-name.log 中,当它达到 16KB 时,第一次轮转触发。

app-name.log.2019-08-21-19 被创建来存储这 16KB 的日志信息。

app-name.log 此时被清空,开始存储接下来的 16KB 日志。当它再次达到 16KB 时,触发第二次轮转。

Log4j 将查看 filePattern 和当下的时间,发现这会儿还是19点。

它的决策是 把此时积累的 16KB (又一次) 轮转到 app-name.log.2019-08-21-19

因而最初的16KB日志被抹去app-name.log 再次被清空,接收最后的 1KB 信息。

 

日志丢失

SizeBasedTriggeringPolicy 和 按照时间定义的 filePattern 实际上是在向 Log4j 表明这样的需求:

我们只希望在这个时间段内最多保留这个容量的日志信息,把最新的那部分留着就行了。

而我们既希望控制单个日志文件大小,有希望保留所有日志,就应该换个方式定义 filePattern 嘛,比如

filePattern="app-name.log.%i"

这里的 %i 在程序运行时会被替换成 轮转的次数,比如第一次轮转生成的就是 app-name.log.1文件。

而轮转次数则可以通过这个 max 属性来定义的。

<DefaultRolloverStrategy max="100" />

随着日志轮转次数的增加,这个变量是不断增加的,Log4j 也就不会再把轮转日志覆写到已存在的文件里啦。

当然啦,我们仍然能给日志文件添上保留时间信息,像这样

filePattern="app-name.log.%d{yyyy-MM-dd-HH}.%i"

要注意的是,这个配置方式依然声明着: 这个时间段内最多保留这个容量的日志信息

比如说,当 max 设为20时,在同一个时间戳上 (同一小时内),变量最多能增到 20。

这一小时里我们最多只会有20个日志文件,当有更多日志信息时,Log4j 依然会抛弃最旧的信息。

 

Default Rollover Strategy

人啊,就是要求多。还有一种常见需求是 希望最多保留N个日志文件

这时候需要的就是把 DefaultRolloverStrategy 加到我们的输出器内。

它的 max 属性定义了最多保留多少最新的轮转日志文件

<RollingRandomAccessFile>
    <!-- 省略了属性等等 -->
    <DefaultRolloverStrategy max="2" />
</RollingRandomAccessFile>

举个例子,比如我们把 max设为 2,同时把SizeBasedTriggeringPolicy 中的 size 1 KB。

假如我们的程序将生成 4KB 的日志 / 4个千字节块,那么运行完我们将得到这3个文件

# 最后生成的1KB / 最新的那1KB日志信息
app-name.log

# 第2个千字节块
app-name.log.1

# 第3个千字节块
app-name.log.2

也就是说,最旧的 / 第一个千字节块 将被抛弃掉。还有一个值得注意的是,当log.2写满后,

第三次轮转时并不会把最新的日志写到 log.1 (轮转并不同于 Round Robin 那样的循环)

轮转意味着:先把 log.2 的内容覆盖到 log.1中,再把最新的放到 log.2里。

如果有3个文件的话,则先把 log.2 移到 log.1, 再把 log.3 移到 log.2, 最后再把新的 app.log 移到 log.3

也就是说 计数变量最大的日志文件永远存着最新的日志信息

 

按时间和容量触发

人的需求总是无限的,这个需求也蛮常见的:

要么当时间到达某个点时,要么当日志积累到某个容量时,轮转日志。俩条件达成一个就轮转。

那么这时候我们需要定义俩触发条件,每个条件在 Log4j 的配置中被称作 Triggering Policy

按照文法要求,当我们有多个条件时,必须用一个 Policies 把它们集合在其中,像下面这样。

<RollingRandomAccessFile
    filePattern="app-name.log.%d{yyyy-MM-dd-HH}">
    <!-- 省略了其他属性等等 -->
    <Policies>
      <TimeBasedTriggeringPolicy />
      <SizeBasedTriggeringPolicy size="16 KB" />
    </Policies>
</RollingRandomAccessFile>

还记得那个按时间定义的 filePattern 吗,它通常是伴随着 TimeBasedTriggeringPolicy 的。

你可能会想,那要是没有 TimeBasedTriggeringPolicy, 只要按时间定义好轮转文件名,再用上

SizeBasedTriggeringPolicy,不也能相当按时间和容量轮转吗 ?

准确说,这样的确会在轮转日志的文件名上记录时间,但意味着日志可能并不按时间分隔开

想象一下,如果程序 19:00 到 21:30 只断断续续生成了 15 KB 的日志,在22:00时才生成满 16KB。最后生成的文件 app-name.log.2019-08-21-22 将包含这三个小时的日志。如果生成速度更慢的话,人们将很难按小时定位。

加上 TimeBasedTriggeringPolicy 意味着告诉 Log4j 别管积累量到了没,到点了就存一下

(是不是很像游戏里的自动存档,管你任务进展到哪了,定期存档总是稳的)

最后要注意的是,上面的这个配置,每个小时发生多于一次轮转时,旧日志将丢失。

因此很常见的做法是:只使用 TimeBasedTriggeringPolicy,每小时轮转一次,而不用 SizeBasedTriggeringPolicy,因为人们通常很清楚:自己的程序每小时也产生不了多少日志啦。

如果非要控制文件大小,那就再加上 %i 吧。

 

还有啥

Log4j 所提供的功能还有很多很多。这篇文章仅仅提到的轮转相关的几个设置方式。

值得探索的输出器 / Appender 还有还有许多,它们适用于不同的场景。

触发轮转也还有其他更复杂的条件,如果好奇 / 有需求的话,应该官方网站文档。

但这里,我还想再加两个值得一提的配置。

 

压缩日志

准确说,是压缩被轮转的日志。Log4j 是自带这个功能的,而且很容易启用。

只要给 RollingRandomAccessFilefilePattern 文件名添上压缩文件的后缀就可以。

# Unix / Linux 上常用 Gzip
filePattern="app.log.%i.gz"

# 也可以用 Zip
filePattern="app.log.%i.zip"

换句话说,当前正在被写入的 / 包含最新日志的文件 àpp.log 每次轮转重命名完都会被压缩。

对于节约硬盘空间,压缩日志还是很有效果的。日志作为文本文件,有很好的压缩率。我在测试时发现 100 MB 的日志文件通常可以被压缩到 7 - 8 MB 左右,接近15倍的缩小。

 

定期删除

还记得那个轮转策略 / Default Rollver Strategy 吗 ?

本质上,它定义了轮转发生时该如何处理旧的 / 之前轮转的日志文件

我们之前设置的 max 属性也就是在告诉 Log4j, 轮转时看下旧日志有多少,超过 N 个了就删最旧的

轮转时这里我们还能做许多其他事,比如 更精确定位要删的旧日志

<DefaultRolloverStrategy>
  <Delete basePath="日志的目录完整路径" maxDepth="2">
    <IfFileName glob="app.log.gz.*" />
    <IfLastModified age="30d" />
  </Delete>
</DefaultRolloverStrategy>

只需要在策略里加上一个 Delete 设置就好啦,它的内部是 被删文件必须达到的所有条件

这里我写了两个最常用的删除条件,一个是模糊文件名,另一个是文件上次被更新的时间(衡量新旧)。

定义模糊文件名的目的是,我们只希望删除日志文件,而不希望误删了同目录下的其他文件。

在上面的定义里,甚至通过文件后缀写明了要删除的是 压缩了的日志

另外想说的是,IfFileName 是有两个属性 globregex ,定义其中一个就好。

后者是正则表达式,前者 glob 的语法非常相近,更常用于文件系统的匹配。

 

Log4j 在删文件时还是很谨慎的,必须定义 basePath 属性,只有在这个目录里的文件可能被匹配删除。

还有一个 maxDepth 表示,当 basePath 里有子目录时,最多进入多深的子目录去搜索文件。

把它设置成 1 的话,Log4j 就不会进入任何 basePath 的子目录去删除文件啦。

 

更多

Log4j 还有很多不同的策略,DefaultRolloverStrategy 只是默认的最简便的。

后退一步,Log4j 还有很多的功能,由不同的 Logger, Appender 和 Policy 组合提供。

如果想要了解它们,还是应该阅读官网的文档。

https://logging.apache.org/log4j/2.x/manual/index.html