Log4j2 - Configure RolloverStrategy to delete old log files

Question

I'm trying to configure log4j to keep only specified amount of backup files or keep files that are not older than some age. Ultimately I want to have time [daily] based triggering policy and keep 30 backup files or delete files that are older then 30 days.

After doing some research I learned that I can't specify max number of backup files when using time policy however I came across this issue https://issues.apache.org/jira/browse/LOG4J2-435 and this documentation fragment http://logging.apache.org/log4j/2.x/manual/appenders.html#CustomDeleteOnRollover that describes how to delete files based on their age and name pattern. Now I'm trying to apply this configuration in simple example that will create new backup file every minute and will automatically delete files that are older then 3 minutes. To do this I created simple maven project with following pom:

<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0"
         xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
         xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
    <modelVersion>4.0.0</modelVersion>

    <groupId>test</groupId>
    <artifactId>test</artifactId>
    <version>1.0-SNAPSHOT</version>

    <dependencies>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-api</artifactId>
            <version>2.5</version>
        </dependency>
        <dependency>
            <groupId>org.apache.logging.log4j</groupId>
            <artifactId>log4j-core</artifactId>
            <version>2.5</version>
        </dependency>
    </dependencies>

    <build>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-dependency-plugin</artifactId>
                <executions>
                    <execution>
                        <id>copy-dependencies</id>
                        <phase>prepare-package</phase>
                        <goals>
                            <goal>copy-dependencies</goal>
                        </goals>
                        <configuration>
                            <outputDirectory>${project.build.directory}/lib</outputDirectory>
                            <overWriteReleases>false</overWriteReleases>
                            <overWriteSnapshots>false</overWriteSnapshots>
                            <overWriteIfNewer>true</overWriteIfNewer>
                        </configuration>
                    </execution>
                </executions>
            </plugin>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-jar-plugin</artifactId>
                <configuration>
                    <archive>
                        <manifest>
                            <addClasspath>true</addClasspath>
                            <classpathPrefix>lib/</classpathPrefix>
                            <mainClass>test.Main</mainClass>
                        </manifest>
                    </archive>
                </configuration>
            </plugin>
        </plugins>
    </build>
</project>

log4j2.xml config file:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" name="MyApp" packages="">
    <Appenders>
        <RollingFile name="RollingFile" fileName="D:/app.log"
                     filePattern="D:/app-%d{yyyy-MM-dd-HH-mm-ss}.log">
            <PatternLayout>
                <Pattern>%d %p %c{1.} [%t] %m%n</Pattern>
            </PatternLayout>
            <Policies>
                <TimeBasedTriggeringPolicy interval="60" modulate="true"/>
                <!--<SizeBasedTriggeringPolicy size="250 MB"/>-->
            </Policies>
            <DefaultRolloverStrategy>
                <Delete basePath="D:" maxDepth="1">
                    <IfFileName glob="app-*.log" />
                    <IfLastModified age="3m" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>
    <Loggers>
        <Root level="trace">
            <AppenderRef ref="RollingFile"/>
        </Root>
    </Loggers>
</Configuration>

and Main class:

package test;


import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;

/**
 * Created by mzurawski on 2015-12-22.
 */
public class Main {

    final static Logger logger = LogManager.getLogger(Main.class);

    public static void main(String[] args) {
        runMe("test");
    }

    private static void runMe(String parameterParam){
        String parameter;
        for(int i=0; i<100; ++i) {
            parameter = parameterParam + i;
            System.out.println("log iteration: "+i);
            if (logger.isDebugEnabled()) {
                logger.debug("This is debug : " + parameter);
            }

            if (logger.isInfoEnabled()) {
                logger.info("This is info : " + parameter);
            }

            logger.warn("This is warn : " + parameter);
            logger.error("This is error : " + parameter);
            logger.fatal("This is fatal : " + parameter);
            try {
                Thread.sleep(60000);
            } catch (InterruptedException e) {
                e.printStackTrace();
            }
        }
    }
}

after building this program you can run it with following command (watch out for hard coded disc locations):

java -jar test-1.0-SNAPSHOT.jar

So far the log files are created every minute but no old files are being deleted. How can I get this test configuration to work? How should I modify this configuration so that ultimately only files from last 30 days will be kept?

Thanks for any help.

Answer 1

Your configuration and test program look fine. I tested your Main.java and log4j2.xml configuration and it works as expected: every minute the rollover is triggered, the Delete action scans the base directory and deletes only files older than 3 minutes.

I did not create a standalone app, but tested in my IDE instead. (Looks like you are shading the log4j jar files and your class and config into a single jar. Could that cause the issue?)

After enabling log4j internal logging by changing the config to <Configuration status="TRACE" ..., I get the following output:

• Iteration 3: no files are deleted yet: oldest file is 173 seconds old.
• Iteration 4: the oldest file is deleted.

... (startup log omitted)...

log iteration: 3
2016-01-16 14:26:23,192 main TRACE PatternProcessor.getNextTime returning 2016/01/16-14:27:00.000, nextFileTime=2016/01/16-14:26:59.000, prevFileTime=2016/01/16-14:25:59.000, current=2016/01/16-14:26:23.192, freq=EVERY_SECOND
2016-01-16 14:26:23,193 main TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
2016-01-16 14:26:23,194 main DEBUG RollingFileManager executing synchronous FileRenameAction[c:\temp\log\app.log to c:\temp\log\app-2016-01-16-14-25-59.log, renameEmptyFiles=false]
2016-01-16 14:26:23,198 main DEBUG RollingFileManager executing async CompositeAction[DeleteAction[basePath=c:\temp\log, options=[], maxDepth=1, conditions=[IfFileName(glob:app-*.log), IfLastModified(age=PT3M)]]]
2016-01-16 14:26:23,199 Log4j2-2 DEBUG Starting DeleteAction[basePath=c:\temp\log, options=[], maxDepth=1, conditions=[IfFileName(glob:app-*.log), IfLastModified(age=PT3M)]]
2016-01-16 14:26:23,200 Log4j2-2 DEBUG DeleteAction complete in 0.001186309 seconds
2016-01-16 14:26:23,201 Log4j2-2 TRACE Sorted paths:
2016-01-16 14:26:23,201 Log4j2-2 TRACE c:\temp\log\app.log (modified: 2016-01-16T05:26:23.199631Z)
2016-01-16 14:26:23,201 Log4j2-2 TRACE c:\temp\log\app-2016-01-16-14-25-59.log (modified: 2016-01-16T05:25:30.832634Z)
2016-01-16 14:26:23,203 Log4j2-2 TRACE c:\temp\log\app-2016-01-16-14-24-59.log (modified: 2016-01-16T05:25:23.188525Z)
2016-01-16 14:26:23,203 Log4j2-2 TRACE c:\temp\log\app-2016-01-16-14-23-59.log (modified: 2016-01-16T05:23:29.466887Z)
2016-01-16 14:26:23,204 Log4j2-2 TRACE IfFileName REJECTED: 'glob:app-*.log' does not match relative path 'app.log'
2016-01-16 14:26:23,204 Log4j2-2 TRACE Not deleting base=c:\temp\log, relative=app.log
2016-01-16 14:26:23,205 Log4j2-2 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-25-59.log'
2016-01-16 14:26:23,205 Log4j2-2 TRACE IfLastModified REJECTED: app-2016-01-16-14-25-59.log ageMillis '52373' < 'PT3M'
2016-01-16 14:26:23,205 Log4j2-2 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-25-59.log
2016-01-16 14:26:23,206 Log4j2-2 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-24-59.log'
2016-01-16 14:26:23,206 Log4j2-2 TRACE IfLastModified REJECTED: app-2016-01-16-14-24-59.log ageMillis '60018' < 'PT3M'
2016-01-16 14:26:23,206 Log4j2-2 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-24-59.log
2016-01-16 14:26:23,206 Log4j2-2 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-23-59.log'
2016-01-16 14:26:23,207 Log4j2-2 TRACE IfLastModified REJECTED: app-2016-01-16-14-23-59.log ageMillis '173740' < 'PT3M'
2016-01-16 14:26:23,207 Log4j2-2 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-23-59.log
log iteration: 4
2016-01-16 14:27:23,200 main TRACE PatternProcessor.getNextTime returning 2016/01/16-14:28:00.000, nextFileTime=2016/01/16-14:27:59.000, prevFileTime=2016/01/16-14:26:59.000, current=2016/01/16-14:27:23.200, freq=EVERY_SECOND
2016-01-16 14:27:23,201 main TRACE DefaultRolloverStrategy.purge() took 0.0 milliseconds
2016-01-16 14:27:23,202 main DEBUG RollingFileManager executing synchronous FileRenameAction[c:\temp\log\app.log to c:\temp\log\app-2016-01-16-14-26-59.log, renameEmptyFiles=false]
2016-01-16 14:27:23,204 main DEBUG RollingFileManager executing async CompositeAction[DeleteAction[basePath=c:\temp\log, options=[], maxDepth=1, conditions=[IfFileName(glob:app-*.log), IfLastModified(age=PT3M)]]]
2016-01-16 14:27:23,205 Log4j2-3 DEBUG Starting DeleteAction[basePath=c:\temp\log, options=[], maxDepth=1, conditions=[IfFileName(glob:app-*.log), IfLastModified(age=PT3M)]]
2016-01-16 14:27:23,207 Log4j2-3 DEBUG DeleteAction complete in 0.001230382 seconds
2016-01-16 14:27:23,207 Log4j2-3 TRACE Sorted paths:
2016-01-16 14:27:23,207 Log4j2-3 TRACE c:\temp\log\app.log (modified: 2016-01-16T05:27:23.20571Z)
2016-01-16 14:27:23,208 Log4j2-3 TRACE c:\temp\log\app-2016-01-16-14-26-59.log (modified: 2016-01-16T05:26:23.946671Z)
2016-01-16 14:27:23,208 Log4j2-3 TRACE c:\temp\log\app-2016-01-16-14-25-59.log (modified: 2016-01-16T05:25:30.832634Z)
2016-01-16 14:27:23,209 Log4j2-3 TRACE c:\temp\log\app-2016-01-16-14-24-59.log (modified: 2016-01-16T05:25:23.188525Z)
2016-01-16 14:27:23,209 Log4j2-3 TRACE c:\temp\log\app-2016-01-16-14-23-59.log (modified: 2016-01-16T05:23:29.466887Z)
2016-01-16 14:27:23,210 Log4j2-3 TRACE IfFileName REJECTED: 'glob:app-*.log' does not match relative path 'app.log'
2016-01-16 14:27:23,210 Log4j2-3 TRACE Not deleting base=c:\temp\log, relative=app.log
2016-01-16 14:27:23,211 Log4j2-3 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-26-59.log'
2016-01-16 14:27:23,211 Log4j2-3 TRACE IfLastModified REJECTED: app-2016-01-16-14-26-59.log ageMillis '59265' < 'PT3M'
2016-01-16 14:27:23,211 Log4j2-3 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-26-59.log
2016-01-16 14:27:23,212 Log4j2-3 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-25-59.log'
2016-01-16 14:27:23,212 Log4j2-3 TRACE IfLastModified REJECTED: app-2016-01-16-14-25-59.log ageMillis '112380' < 'PT3M'
2016-01-16 14:27:23,212 Log4j2-3 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-25-59.log
2016-01-16 14:27:23,213 Log4j2-3 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-24-59.log'
2016-01-16 14:27:23,213 Log4j2-3 TRACE IfLastModified REJECTED: app-2016-01-16-14-24-59.log ageMillis '120025' < 'PT3M'
2016-01-16 14:27:23,213 Log4j2-3 TRACE Not deleting base=c:\temp\log, relative=app-2016-01-16-14-24-59.log
2016-01-16 14:27:23,214 Log4j2-3 TRACE IfFileName ACCEPTED: 'glob:app-*.log' matches relative path 'app-2016-01-16-14-23-59.log'
2016-01-16 14:27:23,214 Log4j2-3 TRACE IfLastModified ACCEPTED: app-2016-01-16-14-23-59.log ageMillis '233748' >= 'PT3M'
2016-01-16 14:27:23,214 Log4j2-3 TRACE Deleting c:\temp\log\app-2016-01-16-14-23-59.log

Can you enable status logging and show your output?