log4j2 自动删除过期日志文件的配置及实现原理

<?xml version="1.0" encoding="UTF-8" ?>
<Configuration status="warn" monitorInterval="30" strict="true"
        schema="Log4J-V2.2.xsd">
  <Properties>
    <Property name="log_level">info</Property>
  </Properties>
  <Appenders>
    <!-- 输出到控制台 -->
    <Console name="Console" target="SYSTEM_OUT">
      <ThresholdFilter level="${log_level}" onMatch="ACCEPT" onMismatch="DENY" />
      <PatternLayout pattern="%d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%t] %p - %c - %m%n" />
    </Console>
    <!-- 与properties文件中位置存在冲突，如有问题，请注意调整 -->
    <RollingFile name="logFile" fileName="logs/app/test.log"
           filePattern="logs/app/history/test-%d{MM-dd-yyyy}-%i.log.gz">
      <ThresholdFilter level="${log_level}" onMatch="ACCEPT" onMismatch="DENY" />
      <PatternLayout pattern="%d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%p] [%c:%L] -- %m%n" />
      <Policies>
        <!-- 按天递计算频率 -->
        <TimeBasedTriggeringPolicy interval="1" />
        <SizeBasedTriggeringPolicy size="500 MB" />
        <OnStartupTriggeringPolicy />
      </Policies>
      <!-- 删除策略配置 -->
      <DefaultRolloverStrategy max="5">
        <Delete basePath="logs/app/history" maxDepth="1">
          <IfFileName glob="*.log.gz"/>
          <IfLastModified age="7d"/>
        </Delete>
        <Delete basePath="logs/app/history" maxDepth="1">
          <IfFileName glob="*.docx"/>
        </Delete>
        <Delete basePath="logs/app/history" maxDepth="1">
          <IfFileName glob="*.vsdx"/>
        </Delete>
      </DefaultRolloverStrategy>
    </RollingFile>
    <Async name="Async" bufferSize="2000" blocking="false">
      <AppenderRef ref="logFile"/>
    </Async>
  </Appenders>

  <Loggers>
    <Root level="${log_level}">
      <AppenderRef ref="Console" />
      <AppenderRef ref="Async" />
    </Root>
    <!-- 配置个例 -->
    <Logger name="com.xx.filter" level="info" />
  </Loggers>
</Configuration>

<dependency>
        <groupId>commons-logging</groupId>
        <artifactId>commons-logging</artifactId>
        <version>1.2</version>
      </dependency>
      <!-- 桥接：告诉commons logging使用Log4j2 -->
      <dependency>
        <groupId>org.slf4j</groupId>
        <artifactId>jcl-over-slf4j</artifactId>
        <version>1.7.26</version>
      </dependency>

      <!-- 此处老版本，需注释掉 -->
      <!--<dependency>
        <groupId>log4j</groupId>
        <artifactId>log4j</artifactId>
        <version>1.2.17</version>
      </dependency>-->

      <dependency>
        <groupId>org.apache.commons</groupId>
        <artifactId>commons-compress</artifactId>
        <version>1.10</version>
      </dependency>
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-core</artifactId>
        <version>2.8.2</version>
      </dependency>
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-slf4j-impl</artifactId>
        <version>2.8.2</version>
      </dependency>
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-api</artifactId>
        <version>2.8.2</version>
      </dependency>
      <dependency>
        <groupId>org.apache.logging.log4j</groupId>
        <artifactId>log4j-web</artifactId>
        <version>2.8.2</version>
      </dependency>

// 在每次添加日志时判定
  // org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender#append
  /**
   * Write the log entry rolling over the file when required.
   *
   * @param event The LogEvent.
   */
  @Override
  public void append(final LogEvent event) {
    final RollingRandomAccessFileManager manager = getManager();
    // 重点：直接检查是否需要 rollover, 如需要直接进行
    manager.checkRollover(event);

    // Leverage the nice batching behaviour of async Loggers/Appenders:
    // we can signal the file manager that it needs to flush the buffer
    // to disk at the end of a batch.
    // From a user's point of view, this means that all log events are
    // _always_ available in the log file, without incurring the overhead
    // of immediateFlush=true.
    manager.setEndOfBatch(event.isEndOfBatch()); // FIXME manager's EndOfBatch threadlocal can be deleted

    // LOG4J2-1292 utilize gc-free Layout.encode() method: taken care of in superclass
    super.append(event);
  }

  // org.apache.logging.log4j.core.appender.rolling.RollingFileManager#checkRollover
  /**
   * Determines if a rollover should occur.
   * @param event The LogEvent.
   */
  public synchronized void checkRollover(final LogEvent event) {
    // 由各触发策略判定是否需要进行 rolling
    // 如需要, 则调用 rollover()
    if (triggeringPolicy.isTriggeringEvent(event)) {
      rollover();
    }
  }

 // 1. 判断是否是 触发事件时机
  // org.apache.logging.log4j.core.appender.rolling.TimeBasedTriggeringPolicy#isTriggeringEvent
  /**
   * Determines whether a rollover should occur.
   * @param event  A reference to the currently event.
   * @return true if a rollover should occur.
   */
  @Override
  public boolean isTriggeringEvent(final LogEvent event) {
    if (manager.getFileSize() == 0) {
      return false;
    }
    final long nowMillis = event.getTimeMillis();
    // TimeBasedTriggeringPolicy, 是基于时间判断的, 此处为每天一次
    if (nowMillis >= nextRolloverMillis) {
      nextRolloverMillis = manager.getPatternProcessor().getNextTime(nowMillis, interval, modulate);
      return true;
    }
    return false;
  }
  // org.apache.logging.log4j.core.appender.rolling.RollingFileManager#rollover()
  public synchronized void rollover() {
    if (!hasOutputStream()) {
      return;
    }
    // strategy 是xml配置的策略
    if (rollover(rolloverStrategy)) {
      try {
        size = 0;
        initialTime = System.currentTimeMillis();
        createFileAfterRollover();
      } catch (final IOException e) {
        logError("Failed to create file after rollover", e);
      }
    }
  }
  // RollingFileManager 统一管理触发器
  // org.apache.logging.log4j.core.appender.rolling.RollingFileManager#rollover
  private boolean rollover(final RolloverStrategy strategy) {

    boolean releaseRequired = false;
    try {
      // Block until the asynchronous operation is completed.
      // 上锁保证线程安全
      semaphore.acquire();
      releaseRequired = true;
    } catch (final InterruptedException e) {
      logError("Thread interrupted while attempting to check rollover", e);
      return false;
    }

    boolean success = true;

    try {
      // 由各触发器运行 rollover 逻辑
      final RolloverDescription descriptor = strategy.rollover(this);
      if (descriptor != null) {
        writeFooter();
        closeOutputStream();
        if (descriptor.getSynchronous() != null) {
          LOGGER.debug("RollingFileManager executing synchronous {}", descriptor.getSynchronous());
          try {
            // 先使用同步方法，改名，然后再使用异步方法操作更多
            success = descriptor.getSynchronous().execute();
          } catch (final Exception ex) {
            success = false;
            logError("Caught error in synchronous task", ex);
          }
        }
        // 如果配置了异步器, 则使用异步进行 rollover
        if (success && descriptor.getAsynchronous() != null) {
          LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous());
          // CompositeAction, 使用异步线程池运行用户的 action
          asyncExecutor.execute(new AsyncAction(descriptor.getAsynchronous(), this));
          // 在异步运行action期间，锁是不会被释放的，以避免线程安全问题
          // 直到异步任务完成，再主动释放锁
          releaseRequired = false;
        }
        return true;
      }
      return false;
    } finally {
      if (releaseRequired) {
        semaphore.release();
      }
    }

  }

 // org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy#rollover
  /**
   * Performs the rollover.
   *
   * @param manager The RollingFileManager name for current active log file.
   * @return A RolloverDescription.
   * @throws SecurityException if an error occurs.
   */
  @Override
  public RolloverDescription rollover(final RollingFileManager manager) throws SecurityException {
    int fileIndex;
    // 默认 minIndex=1
    if (minIndex == Integer.MIN_VALUE) {
      final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager);
      fileIndex = eligibleFiles.size() > 0 ? eligibleFiles.lastKey() + 1 : 1;
    } else {
      if (maxIndex < 0) {
        return null;
      }
      final long startNanos = System.nanoTime();
      // 删除case1: 获取符合条件的文件数，同时清理掉大于 max 配置的日志文件
      // 如配置 max=5, 当前只有4个满足时, 不会立即清理文件, 但也不会阻塞后续流程
      // 只要没有出现错误, fileIndex 不会小于0
      fileIndex = purge(minIndex, maxIndex, manager);
      if (fileIndex < 0) {
        return null;
      }
      if (LOGGER.isTraceEnabled()) {
        final double durationMillis = TimeUnit.NANOSECONDS.toMillis(System.nanoTime() - startNanos);
        LOGGER.trace("DefaultRolloverStrategy.purge() took {} milliseconds", durationMillis);
      }
    }
    // 进入此区域即意味着，必然有文件需要滚动，重新命名了
    final StringBuilder buf = new StringBuilder(255);
    manager.getPatternProcessor().formatFileName(strSubstitutor, buf, fileIndex);
    final String currentFileName = manager.getFileName();

    String renameTo = buf.toString();
    final String compressedName = renameTo;
    Action compressAction = null;

    FileExtension fileExtension = manager.getFileExtension();
    if (fileExtension != null) {
      renameTo = renameTo.substring(0, renameTo.length() - fileExtension.length());
      compressAction = fileExtension.createCompressAction(renameTo, compressedName,
          true, compressionLevel);
    }
    // 未发生文件重命名情况，即文件未被重命名未被滚动
    // 该种情况应该不太会发生
    if (currentFileName.equals(renameTo)) {
      LOGGER.warn("Attempt to rename file {} to itself will be ignored", currentFileName);
      return new RolloverDescriptionImpl(currentFileName, false, null, null);
    }
    // 新建一个重命令的 action, 返回待用
    final FileRenameAction renameAction = new FileRenameAction(new File(currentFileName), new File(renameTo),
          manager.isRenameEmptyFiles());
    // 异步处理器，会处理用户配置的异步action，如本文配置的 DeleteAction
    // 它将会在稍后被提交到异步线程池中运行
    final Action asyncAction = merge(compressAction, customActions, stopCustomActionsOnError);
    // 封装Rollover返回, renameAction 是同步方法, 其他用户配置的动态action 则是异步方法
    // 删除case2: 封装异步返回action
    return new RolloverDescriptionImpl(currentFileName, false, renameAction, asyncAction);
  }
  private int purge(final int lowIndex, final int highIndex, final RollingFileManager manager) {
    // 默认使用 accending 的方式进行清理文件
    return useMax ? purgeAscending(lowIndex, highIndex, manager) : purgeDescending(lowIndex, highIndex, manager);
  }
  // org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy#purgeAscending
  /**
   * Purges and renames old log files in preparation for rollover. The oldest file will have the smallest index, the
   * newest the highest.
   *
   * @param lowIndex low index. Log file associated with low index will be deleted if needed.
   * @param highIndex high index.
   * @param manager The RollingFileManager
   * @return true if purge was successful and rollover should be attempted.
   */
  private int purgeAscending(final int lowIndex, final int highIndex, final RollingFileManager manager) {
    final SortedMap<Integer, Path> eligibleFiles = getEligibleFiles(manager);
    final int maxFiles = highIndex - lowIndex + 1;

    boolean renameFiles = false;
    // 依次迭代 eligibleFiles, 删除
    while (eligibleFiles.size() >= maxFiles) {
      try {
        LOGGER.debug("Eligible files: {}", eligibleFiles);
        Integer key = eligibleFiles.firstKey();
        LOGGER.debug("Deleting {}", eligibleFiles.get(key).toFile().getAbsolutePath());
        // 调用nio的接口删除文件
        Files.delete(eligibleFiles.get(key));
        eligibleFiles.remove(key);
        renameFiles = true;
      } catch (IOException ioe) {
        LOGGER.error("Unable to delete {}, {}", eligibleFiles.firstKey(), ioe.getMessage(), ioe);
        break;
      }
    }
    final StringBuilder buf = new StringBuilder();
    if (renameFiles) {
      // 针对未完成删除的文件，继续处理
      // 比如使用 匹配的方式匹配文件, 则不能被正常删除
      // 还有些未超过maxFiles的文件
      for (Map.Entry<Integer, Path> entry : eligibleFiles.entrySet()) {
        buf.setLength(0);
        // LOG4J2-531: directory scan & rollover must use same format
        manager.getPatternProcessor().formatFileName(strSubstitutor, buf, entry.getKey() - 1);
        String currentName = entry.getValue().toFile().getName();
        String renameTo = buf.toString();
        int suffixLength = suffixLength(renameTo);
        if (suffixLength > 0 && suffixLength(currentName) == 0) {
          renameTo = renameTo.substring(0, renameTo.length() - suffixLength);
        }
        Action action = new FileRenameAction(entry.getValue().toFile(), new File(renameTo), true);
        try {
          LOGGER.debug("DefaultRolloverStrategy.purgeAscending executing {}", action);
          if (!action.execute()) {
            return -1;
          }
        } catch (final Exception ex) {
          LOGGER.warn("Exception during purge in RollingFileAppender", ex);
          return -1;
        }
      }
    }
    // 此处返回的 findIndex 一定是 >=0 的
    return eligibleFiles.size() > 0 ?
        (eligibleFiles.lastKey() < highIndex ? eligibleFiles.lastKey() + 1 : highIndex) : lowIndex;
  }

 // 文件查找规则 
  // org.apache.logging.log4j.core.appender.rolling.AbstractRolloverStrategy#getEligibleFiles
  protected SortedMap<Integer, Path> getEligibleFiles(final RollingFileManager manager) {
    return getEligibleFiles(manager, true);
  }
  protected SortedMap<Integer, Path> getEligibleFiles(final RollingFileManager manager,
                            final boolean isAscending) {
    final StringBuilder buf = new StringBuilder();
    // 此处的pattern 即是在appender上配置的 filePattern, 一般会受限于 MM-dd-yyyy-$i.log.gz
    String pattern = manager.getPatternProcessor().getPattern();
    // 此处会将时间替换为当前, 然后按照此规则进行匹配要处理的文件
    manager.getPatternProcessor().formatFileName(strSubstitutor, buf, NotANumber.NAN);
    return getEligibleFiles(buf.toString(), pattern, isAscending);
  }
  // 细节匹配要处理的文件
  protected SortedMap<Integer, Path> getEligibleFiles(String path, String logfilePattern, boolean isAscending) {
    TreeMap<Integer, Path> eligibleFiles = new TreeMap<>();
    File file = new File(path);
    File parent = file.getParentFile();
    if (parent == null) {
      parent = new File(".");
    } else {
      parent.mkdirs();
    }
    if (!logfilePattern.contains("%i")) {
      return eligibleFiles;
    }
    Path dir = parent.toPath();
    String fileName = file.getName();
    int suffixLength = suffixLength(fileName);
    if (suffixLength > 0) {
      fileName = fileName.substring(0, fileName.length() - suffixLength) + ".*";
    }
    String filePattern = fileName.replace(NotANumber.VALUE, "(\\d+)");
    Pattern pattern = Pattern.compile(filePattern);

    try (DirectoryStream<Path> stream = Files.newDirectoryStream(dir)) {
      for (Path entry: stream) {
        // 该匹配相当精确
        // 只会删除当天或者在时间交替的时候删除上一天的数据咯
        // 如果在这个时候进行了重启操作，就再也不会删除此文件了
        Matcher matcher = pattern.matcher(entry.toFile().getName());
        if (matcher.matches()) {
          Integer index = Integer.parseInt(matcher.group(1));
          eligibleFiles.put(index, entry);
        }
      }
    } catch (IOException ioe) {
      throw new LoggingException("Error reading folder " + dir + " " + ioe.getMessage(), ioe);
    }
    return isAscending? eligibleFiles : eligibleFiles.descendingMap();
  }
  // 此处会将 各种格式的文件名，替换为当前时间或者最后一次滚动的文件的时间。所以匹配的时候，并不会匹配超时当前认知范围的文件
  /**
   * Formats file name.
   * @param subst The StrSubstitutor.
   * @param buf string buffer to which formatted file name is appended, may not be null.
   * @param obj object to be evaluated in formatting, may not be null.
   */
  public final void formatFileName(final StrSubstitutor subst, final StringBuilder buf, final boolean useCurrentTime,
                   final Object obj) {
    // LOG4J2-628: we deliberately use System time, not the log4j.Clock time
    // for creating the file name of rolled-over files.
    final long time = useCurrentTime && currentFileTime != 0 ? currentFileTime :
        prevFileTime != 0 ? prevFileTime : System.currentTimeMillis();
    formatFileName(buf, new Date(time), obj);
    final LogEvent event = new Log4jLogEvent.Builder().setTimeMillis(time).build();
    final String fileName = subst.replace(event, buf);
    buf.setLength(0);
    buf.append(fileName);
  }

 // org.apache.logging.log4j.core.appender.rolling.RollingFileManager.AsyncAction
  /**
   * Performs actions asynchronously.
   */
  private static class AsyncAction extends AbstractAction {

    private final Action action;
    private final RollingFileManager manager;

    /**
     * Constructor.
     * @param act The action to perform.
     * @param manager The manager.
     */
    public AsyncAction(final Action act, final RollingFileManager manager) {
      this.action = act;
      this.manager = manager;
    }

    /**
     * Executes an action.
     *
     * @return true if action was successful. A return value of false will cause
     *     the rollover to be aborted if possible.
     * @throws java.io.IOException if IO error, a thrown exception will cause the rollover
     *               to be aborted if possible.
     */
    @Override
    public boolean execute() throws IOException {
      try {
        // 门面调用 action.execute(), 一般是调用 CompositeAction, 里面封装了多个 action
        return action.execute();
      } finally {
        // 任务执行完成，才会释放外部的锁
        // 虽然不是很优雅，但是很准确很安全
        manager.semaphore.release();
      }
    }
    ...
  }

  // CompositeAction 封装了多个 action 处理
  // org.apache.logging.log4j.core.appender.rolling.action.CompositeAction#run
  /**
   * Execute sequence of actions.
   *
   * @return true if all actions were successful.
   * @throws IOException on IO error.
   */
  @Override
  public boolean execute() throws IOException {
    if (stopOnError) {
      // 依次调用action
      for (final Action action : actions) {
        if (!action.execute()) {
          return false;
        }
      }

      return true;
    }
    boolean status = true;
    IOException exception = null;

    for (final Action action : actions) {
      try {
        status &= action.execute();
      } catch (final IOException ex) {
        status = false;

        if (exception == null) {
          exception = ex;
        }
      }
    }

    if (exception != null) {
      throw exception;
    }

    return status;
  }

 // CompositeAction 封装了多个 action 处理
  // org.apache.logging.log4j.core.appender.rolling.action.CompositeAction#run
  /**
   * Execute sequence of actions.
   *
   * @return true if all actions were successful.
   * @throws IOException on IO error.
   */
  @Override
  public boolean execute() throws IOException {
    if (stopOnError) {
      // 依次调用action
      for (final Action action : actions) {
        if (!action.execute()) {
          return false;
        }
      }

      return true;
    }
    boolean status = true;
    IOException exception = null;

    for (final Action action : actions) {
      try {
        status &= action.execute();
      } catch (final IOException ex) {
        status = false;

        if (exception == null) {
          exception = ex;
        }
      }
    }

    if (exception != null) {
      throw exception;
    }

    return status;
  }
  
  // DeleteAction 做真正的删除动作
  // org.apache.logging.log4j.core.appender.rolling.action.DeleteAction#execute()
  @Override
  public boolean execute() throws IOException {
    // 如果没有script配置，则直接委托父类处理
    return scriptCondition != null ? executeScript() : super.execute();
  }
  org.apache.logging.log4j.core.appender.rolling.action.AbstractPathAction#execute()
  @Override
  public boolean execute() throws IOException {
    // 根据指定的basePath, 和过滤条件，选择相关文件
    // 调用 DeleteAction 的 createFileVisitor(), 返回 DeletingVisitor
    return execute(createFileVisitor(getBasePath(), pathConditions));
  }
  // org.apache.logging.log4j.core.appender.rolling.action.DeleteAction#execute(java.nio.file.FileVisitor<java.nio.file.Path>)
  @Override
  public boolean execute(final FileVisitor<Path> visitor) throws IOException {
    // 根据maxDepth设置，遍历所有可能的文件路径
    // 使用 Files.walkFileTree() 实现, 添加到 collected 中
    final List<PathWithAttributes> sortedPaths = getSortedPaths();
    trace("Sorted paths:", sortedPaths);

    for (final PathWithAttributes element : sortedPaths) {
      try {
        // 依次调用 visitFile, 依次判断是否需要删除
        visitor.visitFile(element.getPath(), element.getAttributes());
      } catch (final IOException ioex) {
        LOGGER.error("Error in post-rollover Delete when visiting {}", element.getPath(), ioex);
        visitor.visitFileFailed(element.getPath(), ioex);
      }
    }
    // TODO return (visitor.success || ignoreProcessingFailure)
    return true; // do not abort rollover even if processing failed
  }

 // org.apache.logging.log4j.core.appender.rolling.action.DeletingVisitor#visitFile
  @Override
  public FileVisitResult visitFile(final Path file, final BasicFileAttributes attrs) throws IOException {
    for (final PathCondition pathFilter : pathConditions) {
      final Path relative = basePath.relativize(file);
      // 遍历所有条件，只要有一个不符合，即不进行删除。
      // 所以，所以条件是 AND 关系， 没有 OR 关系
      // 如果想配置 OR 关系，只能配置多个DELETE
      if (!pathFilter.accept(basePath, relative, attrs)) {
        LOGGER.trace("Not deleting base={}, relative={}", basePath, relative);
        return FileVisitResult.CONTINUE;
      }
    }
    // 直接删除文件
    if (isTestMode()) {
      LOGGER.info("Deleting {} (TEST MODE: file not actually deleted)", file);
    } else {
      delete(file);
    }
    return FileVisitResult.CONTINUE;
  }

<RollingFile name="logFile" fileName="logs/app/test.log"
         filePattern="logs/app/history/test-%d{MM-dd-yyyy}-%i.log.gz">
    <ThresholdFilter level="${log_level}" onMatch="ACCEPT" onMismatch="DENY" />
    <PatternLayout pattern="%d{yyyy-MM-dd'T'HH:mm:ss.SSS} [%p] [%c:%L] -- %m%n" />
    <Policies>
      <!-- 按天递计算频率 -->
      <TimeBasedTriggeringPolicy interval="1" />
      <SizeBasedTriggeringPolicy size="500 MB" />
      <OnStartupTriggeringPolicy />
    </Policies>
    <!-- 删除策略配置 -->
    <DefaultRolloverStrategy max="5000">
      <Delete basePath="logs/app/history" maxDepth="1">
        <!-- 配置且关系 -->
        <IfFileName glob="*.log.gz"/>
        <IfLastModified age="7d"/>
      </Delete>
      <!-- 配置或关系 -->
      <Delete basePath="logs/app/history" maxDepth="1">
        <IfFileName glob="*.docx"/>
      </Delete>
      <Delete basePath="logs/app/history" maxDepth="1">
        <IfFileName glob="*.vsdx"/>
      </Delete>
    </DefaultRolloverStrategy>
  </RollingFile>