log4j2 RollingFileAppender 带zip 源码分析

背景：
线上出现复现率很小的问题，log4j2带SizeBasedTriggeringPolicy和CronTriggeringPolicy两种策略的自定义log，出现覆盖现象
经分析，不是触发size 2MB的问题，是cron发生的问题

log文件 分析
最重要的是获取

1.被压缩文件的创建时间
2.zip文件的lastmodify时间

因为是用创建时间+5分来命名zip文件的 ★

源码分析
每次log.info 最后都会调入RollingFileAppender   就是log.info都会判断是否要rollover，crontrigger是到时间了判断，size是每打印一句就会判断

    public void append(LogEvent event) {
        ((RollingFileManager)this.getManager()).checkRollover(event);
        super.append(event);
    }
然后经过这一步根据上面的两个策略判断是否需要rollover 

this.triggeringPolicy = {CompositeTriggeringPolicy@4082} 
"CompositeTriggeringPolicy(policies=[SizeBasedTriggeringPolicy(size=1024), CronTriggeringPolicy(schedule=0 0/1 * * * ?)])"
 triggeringPolicies = {TriggeringPolicy[2]@4312} 
  0 = {SizeBasedTriggeringPolicy@4316} "SizeBasedTriggeringPolicy(size=1024)"
  1 = {CronTriggeringPolicy@4317} "CronTriggeringPolicy(schedule=0 0/1 * * * ?)"
 state = {LifeCycle$State@4119} "STARTED"
  name = "STARTED"
  ordinal = 3

public synchronized void checkRollover(LogEvent event) {   //event 将所有的log的信息都封装进去
        if (this.triggeringPolicy.isTriggeringEvent(event)) {
            this.rollover();
        }
    }
在这里的判断中 cronPolicy直接返回false,因为cron是直接在异步线程池里操作的
  public boolean isTriggeringEvent(LogEvent event) {
        return false;
    }

/*
sizebasedPolicy 会根据文件大小来判断是否要更新manager的时间  然后在rollover()//这个策略没有触发，不用管
   public boolean isTriggeringEvent(LogEvent event) {
        boolean triggered = this.manager.getFileSize() > this.maxFileSize;
        if (triggered) {
            this.manager.getPatternProcessor().updateTime();
        }

        return triggered;
    }
*/

然后执行manager的rollover()逻辑 ★这里是主要逻辑

public synchronized void rollover() {
        if (this.hasOutputStream()) {
            if (this.rollover(this.rolloverStrategy)) {  ★这里move()
                try {
                    this.size = 0L;
                    this.initialTime = System.currentTimeMillis();
                    this.createFileAfterRollover();  ★这里create()
                } catch (IOException var2) {
                    this.logError("Failed to create file after rollover", var2);
                }
            }

        }
    }
    
//这里封装了一个带俩action的description  rename和zipAction 都是cron衍生出来的
public RolloverDescription rollover(final RollingFileManager manager) throws SecurityException {

rename：
writeFooter();  不知道写的啥,暂时先不管...
success = descriptor.getSynchronous().execute();//同步的rename 直接改  aaa(文件名) move到对应的位置

zip：
if (success && descriptor.getAsynchronous() != null) {//异步的zip  coreSize为0 maxeSize为INTEGER_MAX的线程池，执行将上步remove过来的文件zip的操作
                    LOGGER.debug("RollingFileManager executing async {}", descriptor.getAsynchronous());
                    asyncExecutor.execute(new AsyncAction(descriptor.getAsynchronous(), this));
                    releaseRequired = false;
                }

aaalog是源文件
aaa是生成的zip文件和中间文件
                
synchronous = {FileRenameAction@16811} "FileRenameAction[D:\app1\files3\aaalog.txt to D:\app1\files3\20191102\aaa, renameEmptyFiles=false]"
asynchronous = {ZipCompressAction@16179} "ZipCompressAction[D:\app1\files3\20191102\aaa to D:\app1\files3\20191102\aaa.zip, level=9, deleteSource=true]"

source = {File@19877} "D:\app1\files3\aaalog.txt"
destination = {File@19878} "D:\app1\files3\20191102\aaa"

重命名其实就是move

public static boolean execute(final File source, final File destination, final boolean renameEmptyFiles) {
 Files.move(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),//★这里是真实的move操作
                            StandardCopyOption.ATOMIC_MOVE, StandardCopyOption.REPLACE_EXISTING);
                    LOGGER.trace("Renamed file {} to {} with Files.move", source.getAbsolutePath(),
                            destination.getAbsolutePath());
                    return true;

try {
                source.delete();            //定时跑的时候，如果aaalog为空，就直接删除
            } catch (final Exception exDelete) {
                LOGGER.error("Unable to delete empty file {}: {} {}", source.getAbsolutePath(),
                        exDelete.getClass().getName(), exDelete.getMessage());
            }

进入cron
RollingFileManager.initialize(); 
里面有初始化cron线程池的操作
     public void initialize(final RollingFileManager aManager) {
            this.manager = aManager;
            final Date now = new Date();
            final Date lastRollForFile = cronExpression.getPrevFireTime(new Date(this.manager.getFileTime()));
            final Date lastRegularRoll = cronExpression.getPrevFireTime(new Date());
            aManager.getPatternProcessor().setCurrentFileTime(lastRegularRoll.getTime());
            LOGGER.debug("LastRollForFile {}, LastRegularRole {}", lastRollForFile, lastRegularRoll);
            aManager.getPatternProcessor().setPrevFileTime(lastRegularRoll.getTime());
            aManager.getPatternProcessor().setTimeBased(true);
            if (checkOnStartup && lastRollForFile != null && lastRegularRoll != null &&
                    lastRollForFile.before(lastRegularRoll)) {
                lastRollDate = lastRollForFile;
                rollover();
            }

            final ConfigurationScheduler scheduler = configuration.getScheduler();
            if (!scheduler.isExecutorServiceSet()) {
                // make sure we have a thread pool
                scheduler.incrementScheduledItems();
            }
            if (!scheduler.isStarted()) {
                scheduler.start();
            }
            lastRollDate = lastRegularRoll;
            future = scheduler.scheduleWithCron(cronExpression, now, new CronTrigger());
            LOGGER.debug(scheduler.toString());
        } 

crontriggerstage 会在初始化的时候 执行这一句
    future = scheduler.scheduleWithCron(cronExpression, now, new CronTrigger());

每次都会跑  跑的就是
 private void rollover() {
        manager.rollover(cronExpression.getPrevFireTime(new Date()), lastRollDate);
        if (future != null) {
            lastRollDate = future.getFireTime();
        }
    }

核心代码  ★  为啥跟上面一样呢？因为有个size策略 所以每次log.info都会执行，又有个cron策略，所以线程池也会执行

 if (rollover(rolloverStrategy)) {  这里有个同步的action和异步的action
            try {
                size = 0;
                initialTime = System.currentTimeMillis();
                createFileAfterRollover();  //★这里直接同步创建新的源文件
            } catch (final IOException e) {
                logError("Failed to create file after rollover", e);
            }
        }

//★ 同上，这里创建文件
 @Override
    protected OutputStream createOutputStream() throws IOException {
        final String filename = getFileName();
        LOGGER.debug("Now writing to {} at {}", filename, new Date());
        final File file = new File(filename);
        final FileOutputStream fos = new FileOutputStream(file, isAppend);
        if (file.exists() && file.length() == 0) {
            try {
            // 而且重命名的时间和当前时间一致 把源文件的创建时间设置成当前时间
                FileTime now = FileTime.fromMillis(System.currentTimeMillis());
                Files.setAttribute(file.toPath(), "creationTime", now);
            } catch (Exception ex) {
                LOGGER.warn("Unable to set current file tiem for {}", filename);
            }
        }
        defineAttributeView(Paths.get(filename));
        return fos;
    }

cronpolicy 

manager.rollover(cronExpression.getPrevFireTime(new Date()), lastRollDate);
        if (future != null) {
            lastRollDate = future.getFireTime();
        }

分析文件创建，删除，zip时间代码如下

获取descriptor  里面俩操作 
一个同步的rename 一个异步的zip
rename是直接执行的  下面的代码  这步骤是同步执行的，将 source move 到指定位置
 Files.move(Paths.get(source.getAbsolutePath()), Paths.get(destination.getAbsolutePath()),
                            StandardCopyOption.ATOMIC_MOVE, StandardCopyOption.REPLACE_EXISTING);
                    LOGGER.trace("Renamed file {} to {} with Files.move", source.getAbsolutePath(),
                            destination.getAbsolutePath());
                    return true;

source是怎么重新出现的 因为是定时任务 所以就是定时的时间 createFileAfterRollover() 创建的就是当时的时间
protected OutputStream createOutputStream() throws IOException {
        final String filename = getFileName();
        LOGGER.debug("Now writing to {} at {}", filename, new Date());
        final File file = new File(filename);
        final FileOutputStream fos = new FileOutputStream(file, isAppend);
        if (file.exists() && file.length() == 0) {
            try {
                FileTime now = FileTime.fromMillis(System.currentTimeMillis());
                Files.setAttribute(file.toPath(), "creationTime", now);
            } catch (Exception ex) {
                LOGGER.warn("Unable to set current file tiem for {}", filename);
            }
        }
        defineAttributeView(Paths.get(filename));
        return fos;
    }

又怎么被删除   只要为空  每次定时任务扫到就会删掉

又出现  同上

/* This executor pool will create a new Thread for every work async action to be performed. Using it allows
       us to make sure all the Threads are completed when the Manager is stopped. */
    private final ExecutorService asyncExecutor = new ThreadPoolExecutor(0, Integer.MAX_VALUE, 0, TimeUnit.MILLISECONDS,
            new EmptyQueue(), threadFactory);
            
            

一种合理的解释：线程池里新建了15分钟 的zip任务，由于某种原因卡住了，卡到20才执行完，
此时20的已经创建好，且zip完了，就会覆盖，至于是哪个覆盖哪个就不知道了            

zip的创建时间
public static boolean execute(final File source, final File destination, final boolean deleteSource,
            final int level) throws IOException {
        if (source.exists()) {
            try (final FileInputStream fis = new FileInputStream(source);
                    final ZipOutputStream zos = new ZipOutputStream(new FileOutputStream(destination))) {
                zos.setLevel(level);

                final ZipEntry zipEntry = new ZipEntry(source.getName());
                zos.putNextEntry(zipEntry);

                final byte[] inbuf = new byte[BUF_SIZE];
                int n;

                while ((n = fis.read(inbuf)) != -1) {//创建时间
                    zos.write(inbuf, 0, n);
                }
            }

            if (deleteSource && !source.delete()) {
                LOGGER.warn("Unable to delete " + source.toString() + '.');
            }

            return true;
        }

        return false;
    }

总结为 定时move，同步create  异步 zip(modifytime)
我们的逻辑为，如果 zip modifytime-createtime>5分 重命名文件+5分 文件本来名就是move  createtime 的名
如果<5分，就不重命名

正常情况下
move和createtime 是一致的  都是0/5这样的分钟数
modifytime 是异步的zip创建时间

异常情况见图片吧，概率很低