log4j

发表于 更新于 分类于

DEBUG 模式运行

log4j的配置文件中配置log4j.debug=true即可开启

概述

log4j的looger是层级结构的，例如com.li是com.li.springboot的父类logger
可使用如下方式取出logger

1
2
3
4
5
6
7
8
9
package com.li.springboot.advice.log4j;


import org.apache.log4j.Logger;

public class LevelTest {
    Logger logger= Logger.getLogger(LevelTest.class);
    Logger logger= Logger.getLogger("com.li.springboot.advice.log4j.LevelTest");
}

getLogger根据参数name，在任意处取出的logger都是同一个 root logger是所有logger的父类，一定存在但是它不能直接使用getLogger通过name取出。可使用如下方式取出

1
Logger.getRootLogger()

可使用的日志级别org.apache.log4j.Level

TRACE,DEBUG,INFO,WARN,ERROR and FATAL

当指定name的logger日志请求时，同时会将该请求转发至父类logger 当logger没有对应的配置时，会找最近的父类配置，默认情况下logger配置会继承父类的配置，可通过设置log4j.additivity.xxx=false使其不继承(xxx 是 logger 的 name)

配置

  1. 初始化 Logger 容器 Hierarchy,设置根节点为 RootLogger

  2. 初始 LoggerRepositorySelector(容器选择器)为默认的 DefaultRepositorySelector,容器为 Hierarchy

  3. 读取系统属性 log4j.defaultInitOverride,如果没有设置或者为 false 进行初始化,否则跳过初始化

  4. 读取系统属性 log4j.configuration(log4j 文件路径配置),如果存在对应的文件,则得到 URL.如果没有对应的文件,首先检查是否存在 log4j.xml 文件,如果存在,得到 Log4j 配置文件 URL,如果不存在 log4j.xml,继续检查是否存在 log4j.properties 文件,如果存在该文件,得到 log4j 配置文件的 URL,否则提示没有发现配置文件。

  5. 读取系统属性 log4j.configuratorClass(自定义 Configurator 配置类全路径,一般不自定义)

  6. 调用 OptionConverter.selectAndConfigure(url, configuratorClassName,LogManager.getLoggerRepository()),初始化 logger 容器

扩展配置

可使用BasicConfigurator.resetConfiguration()重置配置 可使用PropertyConfigurator.configure指定其他配置文件

tomcat下的log4j

当log4j的jar包在tomcat目录下的时候，使用BasicConfigurator.resetConfiguration()重置配置时，会修改tomcat下所有应用的日志打印，一般情况下 我们在主应用里做配置，忽略其他应用的配置即可。但是当你发布其他应用时，触发log4j的初始化配置，则会影响到主应用，可能造成主应用日志不打印。这个时候我们通过HierarchyEventListener来监听log4j的配置是否被修改，来在其他应用重置配置时，重新触发主应用的配置加载过程即可。

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
static {
    Logger.getRootLogger().getLoggerRepository().addHierarchyEventListener(new HierarchyEventListener() {
        @Override
        public void addAppenderEvent(Category cat, Appender appender) {
            LogLog.debug("add " + cat.getName() + "  " + appender);
            flag = false;
        }
        @Override
        public void removeAppenderEvent(Category cat, Appender appender) {
            //log4j配置被移除前的回调，此时配置还是生效的，所以这里重新加载是无效的，回调后就
            //被重置了，所以需要在外面去重新加载，这里仅打一个标记
            LogLog.debug("remove " + cat.getName() + "  " + appender);
            flag = true;
        }
    });
}

public static void initLog4j() {
    BasicConfigurator.resetConfiguration();
    Properties properties = new Properties();
    try {
        properties.load(ClassLoader.getSystemResourceAsStream("mylog4j.properties"));
    } catch (IOException e) {
        e.printStackTrace();
    }
    //配置logger时，已有的同名Category会被remove掉，即可以触发removeAppenderEvent事件
    PropertyConfigurator.configure(properties);
}

for (int i = 0; i < cycle; i++) {
    Thread.sleep(RandomUtils.nextInt(500, 1500));
        if (flag) {
            initLog4j();
        }
    logger.debug("123");
}

MDC

打造日志链路，MDC类似ThreadLocal类，根据线程存入一些数据，以供打印日志的时候输出(%X{name})

1
2
MDC.clear();
MDC.put("session", "xxxx");
1
log4j.appender.consoleAppender.layout.ConversionPattern= %X{session} %m%n

问题

日志输出问题

应用中需要将多个logger的日志输出到同一个文件中，且需要根据时间每天自动分割文件。我们使用DailyRollingFileAppender 配置如下

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
# 开启log4j的日志
log4j.debug=true
log4j.rootLogger=error, stdout
log4j.logger.l1=DEBUG, fuck1
log4j.logger.l2=DEBUG, fuck2

#l1
log4j.appender.fuck1=org.apache.log4j.DailyRollingFileAppender
log4j.appender.fuck1.DatePattern='.'-yyyy-MM-dd-HH-mm
log4j.appender.fuck1.layout=org.apache.log4j.PatternLayout
log4j.appender.fuck1.File=/Users/li/Downloads/log4j/log4j.log
log4j.appender.fuck1.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

#l2
log4j.appender.fuck2=org.apache.log4j.DailyRollingFileAppender
log4j.appender.fuck2.DatePattern='.'-yyyy-MM-dd-HH-mm
log4j.appender.fuck2.layout=org.apache.log4j.PatternLayout
log4j.appender.fuck2.File=/Users/li/Downloads/log4j/log4j.log
log4j.appender.fuck2.layout.ConversionPattern=%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n

测试代码我使用Spring的Scheduled

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
package com.li.springboot.util;

import org.apache.log4j.Logger;
import org.springframework.scheduling.annotation.Scheduled;
import org.springframework.stereotype.Component;

@Component
public class ScheduledTask {

    Logger logger = Logger.getLogger("l1");
    Logger logger2 = Logger.getLogger("l2");
    private int index = 0;

    @Scheduled(cron = "*/1 * * * * *")
    public void log() {
        logger.info("--------------------" + index++);
        logger2.debug("--------------------" + index++);
    }

}

*/1 * * * * *表示每秒执行一次

log4j.appender.fuck1.DatePattern='.'-yyyy-MM-dd-HH-mm表示每分钟分割一次文件

在执行定时任务到底切割点时，我们可以观察到日志输出

log4j自身的日志一定输出在System.out中

1
2
3
4
5
6
7
8
9
2019-09-05 21:16:59 DEBUG l2:22 - --------------------44
log4j: /Users/li/Downloads/log4j/log4j.log -> /Users/li/Downloads/log4j/log4j.log.-2019-09-05-21-16
log4j: setFile called: /Users/li/Downloads/log4j/log4j.log, true
log4j: setFile ended
2019-09-05 21:17:00 INFO  l1:21 - --------------------45
log4j: /Users/li/Downloads/log4j/log4j.log -> /Users/li/Downloads/log4j/log4j.log.-2019-09-05-21-16
log4j: setFile called: /Users/li/Downloads/log4j/log4j.log, true
log4j: setFile ended
2019-09-05 21:17:00 DEBUG l2:22 - --------------------46

我们观察下源码分析下这个过程

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
  protected void subAppend(LoggingEvent event) {
    long n = System.currentTimeMillis();
    //检测当前时间点是否需要分割文件
    if (n >= nextCheck) {
      now.setTime(n);
      nextCheck = rc.getNextCheckMillis(now);
      try {
        rollOver();
      }
      catch(IOException ioe) {
          if (ioe instanceof InterruptedIOException) {
              Thread.currentThread().interrupt();
          }
        LogLog.error("rollOver() failed.", ioe);
      }
    }
    super.subAppend(event);
   }
}

void rollOver() throws IOException {

    /* Compute filename, but only if datePattern is specified */
    if (datePattern == null) {
      errorHandler.error("Missing DatePattern option in rollOver().");
      return;
    }

    String datedFilename = fileName+sdf.format(now);
    // It is too early to roll over because we are still within the
    // bounds of the current interval. Rollover will occur once the
    // next interval is reached.
    if (scheduledFilename.equals(datedFilename)) {
      return;
    }

    // close current file, and rename it to datedFilename
    this.closeFile();
    //如果存在其他分割后的文件，则删除
    File target  = new File(scheduledFilename);
    if (target.exists()) {
      target.delete();
    }

    File file = new File(fileName);
    //将当前日志文件改名为代日期的文件
    boolean result = file.renameTo(target);
    if(result) {
      LogLog.debug(fileName +" -> "+ scheduledFilename);
    } else {
      LogLog.error("Failed to rename ["+fileName+"] to ["+scheduledFilename+"].");
    }

    try {
      // This will also close the file. This is OK since multiple
      // close operations are safe.
      //将log4j日志的输出重定向为不带日期的文件
      this.setFile(fileName, true, this.bufferedIO, this.bufferSize);
    }
    catch(IOException e) {
      errorHandler.error("setFile("+fileName+", true) call failed.");
    }
    scheduledFilename = datedFilename;
  }

  1. logger的日志在logger2之前，因此先触发rollOver,此时没有文件log4j.log.-2019-09-05-21-16,将log4j.log重命名为log4j.log.-2019-09-05-21-16,并将logger的日志流重定向为log4j.log

  2. 紧接着logger2的日志流触发rollOver,此时会将log4j.log.-2019-09-05-21-16删除，同时将log4j.log重命名为log4j.log.-2019-09-05-21-16，并将logger2的日志流重定向为log4j.log。此时logger的日志流就的文件名被改名了。

  3. 我们可以看出第一轮的日志被logger2触发的rollOver删除了，而logger的日志流输出到上一轮

解决方案

根据分析，我们确保target.delete()和ile.renameTo(target)只被执行一次，且其他logger在指定时间重新将日志流指向到最新的log4j.log即可。

比如说简单的重写DailyRollingFileAppender,在rollOver代码处稍作修改

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
File target = new File(scheduledFilename);
//当目标文件已经存在时，就说明已经被切割过了，则简单重定向即可
if (!target.exists()) {
    File file = new File(fileName);
    boolean result = file.renameTo(target);
    if (result) {
        LogLog.debug(fileName + " -> " + scheduledFilename);
    } else {
        LogLog.error("Failed to rename [" + fileName + "] to [" + scheduledFilename + "].");
    }
}
try {
        this.setFile(fileName, true, this.bufferedIO, this.bufferSize);
    } catch (IOException e) {
        errorHandler.error("setFile(" + fileName + ", true) call failed.");
}
    scheduledFilename = datedFilename;