Log4j2 RollingFile Appender - add custom info at t

Question

Using log4j2 (beta9) with java 1.7.

My complete log4j2.xml:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
  <Properties>
    <Property name="projectPrefix">Tts</Property>
    <Property name="rawPattern">%d %-5p [%t] %C{2} (%F:%L) - %m%n</Property>
    <Property name="coloredPattern">%d %highlight{%-5p}{FATAL=bright red, ERROR=red, WARN=yellow, INFO=cyan, DEBUG=green, TRACE=bright blue} %style{[%t] %C{2} (%F:%L) -}{bright,black} %m%n</Property>
    <Property name="fileName">Log/${projectPrefix}.log</Property>
    <Property name="filePattern">Log/${projectPrefix}-%i.log</Property>
  </Properties>
  <Appenders>
    <Console name="Stdout" target="SYSTEM_OUT">
      <PatternLayout pattern="${coloredPattern}"/>
    </Console>
    <RollingFile name="Logfile" fileName="${fileName}" filePattern="${filePattern}">
      <PatternLayout pattern="${rawPattern}"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="16 MB"/>
      </Policies>
      <DefaultRolloverStrategy fileIndex="min" max="16"/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Stdout"/>
      <AppenderRef ref="Logfile"/>
    </Root>
  </Loggers>
</Configuration>

I want to add some custom info at the top of each logfile, like the version string of my application, the application uptime and the system uptime. And even writing some »bye, bye / eof« to the bottom of the just closed logfile would also be fine.

Is there something like a hook or callback to get notified when the RollingFileAppander has created a new file, so that I can put my things at first into these new logfile (or any other suggestion)?

Answer 1

New solution available

Some time has passed since this question was asked, and now, when I wanted to do the same I have found out that it is possible to solve without messing with factories, but it was not easy to find. The log4j2 team have made it possible to do this by configuration. I hope my post will be of use and save time for someone else.

They have hidden this feature in the PatternLayout element. Not where I first looked, but why complain when it works?

This is my configuration (pay attention to header and footer, and the properties they use):

<?xml version="1.0" encoding="UTF-8"?>
<Configuration>
    <Properties>
        <Property name="log-path">${sys:catalina.home}/logs/my-app</Property>
        <Property name="archive">${log-path}/archive</Property>
        <Property name="defaultPattern">[%d] [%-5p] [%t] %C{5} - %m%n</Property>
        <Property name="defaultRollOverMax">450</Property>
        <Property name="fileHeader">[%d] Start of log \n========================================================================\n
Will be archived in ${archive}\n\n</Property>
        <Property name="fileFooter">\n========================================================================\n[%d] End of log</Property>
    </Properties>
    <Appenders>
        <Console name="Console" target="SYSTEM_OUT">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            <PatternLayout pattern="%highlight{[%d] [%-5p] [%t] %C{3} (%F:%L) - %m%n}" charset="UTF-8"/>
        </Console>

        <RollingFile name="Root"
                     fileName="${log-path}/root.log"
                     filePattern="${archive}/root.log.%d{yyyy-MM-dd}_%i.gz"
                     immediateFlush="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY"/>
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="10 MB"/>
                <TimeBasedTriggeringPolicy/>
            </Policies>

            <PatternLayout pattern="${defaultPattern}"
                           charset="UTF-8"
                           header="This is the ROOT logger and it should be silent \n - define loggers when you see something in here"
                           footer="Closing"/>
            <DefaultRolloverStrategy max="${defaultRollOverMax}" fileIndex="max"/>
        </RollingFile>

        <RollingFile name="System"
                     fileName="${log-path}/system.log"
                     filePattern="${archive}/system.log.%d{yyyy-MM-dd}_%i.gz"
                     immediateFlush="true">
            <ThresholdFilter level="INFO" onMatch="ACCEPT" onMismatch="DENY" />
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="10 MB"/>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <PatternLayout pattern="${defaultPattern}"
                           charset="UTF-8"
                           header="${fileHeader}"
                           footer="${fileFooter}"/>
            <DefaultRolloverStrategy max="${defaultRollOverMax}" fileIndex="max"/>
        </RollingFile>

        <RollingFile name="Error"
                     fileName="${log-path}/error.log"
                     filePattern="${archive}/error.log.%d{yyyy-MM-dd}_%i.gz"
                     immediateFlush="true">
            <ThresholdFilter level="WARN" onMatch="ACCEPT" onMismatch="DENY"/>
            <Policies>
                <OnStartupTriggeringPolicy/>
                <SizeBasedTriggeringPolicy size="10 MB"/>
                <TimeBasedTriggeringPolicy/>
            </Policies>
            <PatternLayout pattern="${defaultPattern}"
                           charset="UTF-8"
                           header="${fileHeader}"
                           footer="${fileFooter}"/>
            <DefaultRolloverStrategy max="${defaultRollOverMax}" fileIndex="max"/>
        </RollingFile>
    </Appenders>

    <Loggers>
        <Logger name="org.myOrganization.myApplication" additivity="false" level="INFO">
            <appender-ref ref="System"/>
            <appender-ref ref="Console"/>
            <appender-ref ref="Error"/>
        </Logger>

        <Logger name="org.myOrganization.myApplication.peculiarPackage" additivity="false" level="TRACE">
            <appender-ref ref="System"/>
            <appender-ref ref="Console"/>
            <appender-ref ref="Error"/>
        </Logger>

        <Logger name="org.springframework" additivity="false" level="WARN">
            <appender-ref ref="System"/>
            <appender-ref ref="Console"/>
            <appender-ref ref="Error"/>
        </Logger>

        <Logger name="javax" additivity="false" level="WARN">
            <appender-ref ref="System"/>
            <appender-ref ref="Console"/>
            <appender-ref ref="Error"/>
        </Logger>

        <!-- Root logger should be empty -->
        <Root level="all">
            <AppenderRef ref="Root"/>
            <AppenderRef ref="Console"/>
            <!--Make sure all errors are logged to the error log-->
            <appender-ref ref="Error"/>
        </Root>
    </Loggers>
</Configuration>

As you can see I have included a timestamp, and a property, that includes a system property. Log4j2 can show many different kinds of properties, with this you can do a lot of things of what you asked for.

The log file looks like this:

[2016-08-09 17:00:43,924] Start of log 
========================================================================

Will be archived in /home/emanciperingsivraren/program/apache-tomcat-8.0.32/logs/my-app/archive

[2016-08-09 17:00:44,000] [INFO ] [RMI TCP Connection(2)-127.0.0.1]    [snip]

========================================================================
[2016-08-09 17:02:17,871] End of log

Do you need more custom information? - try to put that information in properties, system properties, or something else that log4j2 can read.

See Property Substitution in log4j2 for details in what kind of properties you can have.

Comments about the configuration

• I use properties instead of repeating common settings
• If something is written in the root logger, then it is unhandled, and a logger should be written to define what we want to do with it
• Since errors/exceptions can be "hidden" among a lot of other log messages they are also printed there, and can easily be found
• Messages printed on Console have different colours

Answer 2

Ok, there is a working solution for this problem by extending DefaultRolloverStrategy like described here. But

• it needs about 150 lines of code (incl. wrapping RolloverDescription and appender.rolling.helper.Action) and
• smells a bit because the need to completely copy DefaultRolloverStrategy's factory method (makes this solution maintenance-unfriendly eg. if DefaultRolloverStrategy gets more config parameters in future versions)

To let log4j2 call our factory method, the root tag of log4j2.xml must be attributed with the package of our class, e.g.:

<Configuration packages="de.jme.toolbox.logging">
...
</Configuration>

and within our own RolloverStrategy we have to deal with @Plugin and @PluginFactory as described here.

Finally here my complete log4j2.xml (you don't need all that properties - that's just the way how I like to configure my logging):

<?xml version="1.0" encoding="UTF-8"?>
<Configuration packages="de.jme.toolbox.logging">
  <Properties>
    <Property name="projectPrefix">Tts</Property>
    <Property name="rawPattern">%d %-5p [%t] %C{2} (%F:%L) - %m%n</Property>
    <Property name="coloredPattern">%d %highlight{%-5p}{FATAL=bright red, ERROR=red, WARN=yellow, INFO=cyan, DEBUG=green, TRACE=bright blue} %style{[%t] %C{2} (%F:%L) -}{bright,black} %m%n</Property>
    <Property name="coloredShortPattern">%d %highlight{%-5p}{FATAL=bright red, ERROR=red, WARN=yellow, INFO=cyan, DEBUG=green, TRACE=bright blue} %style{[%t] -}{bright,black} %m%n</Property>
    <Property name="fileName">Log/${projectPrefix}.log</Property>
    <Property name="filePattern">Log/${projectPrefix}-%i.log</Property>
  </Properties>
  <Appenders>
    <Console name="Stdout" target="SYSTEM_OUT">
      <PatternLayout pattern="${coloredPattern}"/>
    </Console>
    <RollingFile name="Logfile" fileName="${fileName}" filePattern="${filePattern}">
      <PatternLayout pattern="${rawPattern}"/>
      <Policies>
        <SizeBasedTriggeringPolicy size="1 MB"/>
      </Policies>
      <MyRolloverStrategy fileIndex="min" max="16"/>
    </RollingFile>
  </Appenders>
  <Loggers>
    <Root level="info">
      <AppenderRef ref="Stdout"/>
      <AppenderRef ref="Logfile"/>
    </Root>
  </Loggers>
</Configuration>

And here MyRolloverStrategy.java:

package de.jme.toolbox.logging;

import java.io.BufferedWriter;
import java.io.File;
import java.io.FileWriter;
import java.io.IOException;
import java.util.zip.Deflater;

import org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy;
import org.apache.logging.log4j.core.appender.rolling.RollingFileManager;
import org.apache.logging.log4j.core.appender.rolling.RolloverDescription;
import org.apache.logging.log4j.core.appender.rolling.helper.Action;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.plugins.PluginAttribute;
import org.apache.logging.log4j.core.config.plugins.PluginConfiguration;
import org.apache.logging.log4j.core.config.plugins.PluginFactory;
import org.apache.logging.log4j.core.helpers.Integers;
import org.apache.logging.log4j.core.lookup.StrSubstitutor;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.status.StatusLogger;

/**
 * Own RolloverStrategy to hook the DefaultRolloverStrategy's rollover events
 *
 * Siehe auch:
 * - https://issues.apache.org/jira/browse/LOG4J2-486
 * - http://apache-logging.6191.n7.nabble.com/log4j2-getting-started-amp-rolling-files-tt8406.html#a42402
 * - http://stackoverflow.com/questions/20819376/log4j2-rollingfile-appender-add-custom-info-at-the-start-of-each-logfile
 *
 * @author Joe Merten
 */
@org.apache.logging.log4j.core.config.plugins.Plugin(name="MyRolloverStrategy", category="Core", printObject=true)
public class MyRolloverStrategy extends DefaultRolloverStrategy {

    protected static final Logger logger = StatusLogger.getLogger();

    // ==============================
    // ↓↓↓ Some stuff copied from ↓↓↓
    // https://svn.apache.org/repos/asf/logging/log4j/log4j2/trunk/log4j-core/src/main/java/org/apache/logging/log4j/core/appender/rolling/DefaultRolloverStrategy.java r1556050
    // Just changed »DefaultRolloverStrategy« to »MyRolloverStrategy«

    private static final int MIN_WINDOW_SIZE = 1;
    private static final int DEFAULT_WINDOW_SIZE = 7;

    @PluginFactory
    public static MyRolloverStrategy createStrategy(
            @PluginAttribute("max") final String max,
            @PluginAttribute("min") final String min,
            @PluginAttribute("fileIndex") final String fileIndex,
            @PluginAttribute("compressionLevel") final String compressionLevelStr,
            @PluginConfiguration final Configuration config) {
        final boolean useMax = fileIndex == null ? true : fileIndex.equalsIgnoreCase("max");
        int minIndex;
        if (min != null) {
            minIndex = Integer.parseInt(min);
            if (minIndex < 1) {
                LOGGER.error("Minimum window size too small. Limited to " + MIN_WINDOW_SIZE);
                minIndex = MIN_WINDOW_SIZE;
            }
        } else {
            minIndex = MIN_WINDOW_SIZE;
        }
        int maxIndex;
        if (max != null) {
            maxIndex = Integer.parseInt(max);
            if (maxIndex < minIndex) {
                maxIndex = minIndex < DEFAULT_WINDOW_SIZE ? DEFAULT_WINDOW_SIZE : minIndex;
                LOGGER.error("Maximum window size must be greater than the minimum windows size. Set to " + maxIndex);
            }
        } else {
            maxIndex = DEFAULT_WINDOW_SIZE;
        }
        final int compressionLevel = Integers.parseInt(compressionLevelStr, Deflater.DEFAULT_COMPRESSION);
        return new MyRolloverStrategy(minIndex, maxIndex, useMax, compressionLevel, config.getStrSubstitutor());
    }
    // ↑↑↑ Some stuff copied from ↑↑↑
    // ==============================

    protected MyRolloverStrategy(int minIndex, int maxIndex, boolean useMax, int compressionLevel, StrSubstitutor subst) {
        super(minIndex, maxIndex, useMax, compressionLevel, subst);
    }

    // Wrapper class only for setting a hook to execute()
    static class MyAction implements Action {
        final Action delegate;
        final String fileName;

        public MyAction(final Action delegate, final String fileName) {
            this.delegate = delegate;
            this.fileName = fileName;
        }

        @Override public void run() {
            delegate.run();
        }

        @Override public boolean execute() throws IOException {
            try {
                BufferedWriter writer = null;
                try {
                    writer = new BufferedWriter(new FileWriter(new File(fileName), true));
                    writer.write("****************************\n");
                    writer.write("*** Bye, bye old logfile ***\n");
                    writer.write("****************************\n");
                } finally {
                    if (writer != null)
                        writer.close();
                }
            } catch (Throwable e) {
                logger.error("Writing to bottom of old logfile \"" + fileName + "\" with", e);
            }

            boolean ret = delegate.execute();

            try {
                BufferedWriter writer = null;
                try {
                    writer = new BufferedWriter(new FileWriter(new File(fileName), true));
                    writer.write("*************************\n");
                    writer.write("*** Hello new logfile ***\n");
                    writer.write("*************************\n");
                } finally {
                    if (writer != null)
                        writer.close();
                }
            } catch (Throwable e) {
                logger.error("Writing to top of new logfile \"" + fileName + "\" with", e);
            }

            return ret;
        }

        @Override public void close() {
            delegate.close();
        }

        @Override public boolean isComplete() {
            return delegate.isComplete();
        }
    }

    // Wrapper class only for setting a hook to getSynchronous().execute()
    static class MyRolloverDescription implements RolloverDescription {
        final RolloverDescription delegate;

        public MyRolloverDescription(final RolloverDescription delegate) {
            this.delegate = delegate;
        }

        @Override public String getActiveFileName() {
            return delegate.getActiveFileName();
        }

        @Override public boolean getAppend() {
            //return delegate.getAppend();
            // As long as we already put some data to the top of the new logfile, subsequent writes should be performed with "append".
            return true;
        }

        // The synchronous action is for renaming, here we want to hook
        @Override public Action getSynchronous() {
            Action delegateAction = delegate.getSynchronous();
            if (delegateAction == null) return null;
            return new MyAction(delegateAction, delegate.getActiveFileName());
        }

        // The asynchronous action is for compressing, we don't need to hook here
        @Override public Action getAsynchronous() {
            return delegate.getAsynchronous();
        }
    }

    public RolloverDescription rollover(final RollingFileManager manager) {
        RolloverDescription ret = super.rollover(manager);
        return new MyRolloverDescription(ret);
    }
}

Solving this requirement might be easier in future versions of log4j2, if my posted feature request would implemented.

Answer 3

Currently there is no callback hook for rollovers. May I suggest raising this as a feature request in the log4j2 issue tracker?