log4j2: registering custom TriggeringPolicy

问题:

I have written a custom TriggeringPolicy for log4j2 that is suppose to roll-over .log file at the end of every hour/day/your_interval following advices from this SO post.

Though I followed TimeBasedTriggeringPolicy conventions (naming, etc) I am not able to see my policy being instantiated and used.

Solution comprise of 3 java files + a maven file and is available at the github.
Here you can find main lines from the policy itself:

@Plugin(name = "FTimeBasedTriggeringPolicy", category = "Core", printObject = true)
public class FTimeBasedTriggeringPolicy implements TriggeringPolicy {

    private final TimeBasedTriggeringPolicy timeBasedTriggeringPolicy;  
    private RollingFileManager manager;

    private FTimeBasedTriggeringPolicy(final int interval, final boolean modulate) {
        timeBasedTriggeringPolicy = TimeBasedTriggeringPolicy.createPolicy(String.valueOf(interval), String.valueOf(modulate));
        LogRotateThread.registerPolicy(this);
    }

    public void checkRollover(final LogEvent event) {
        this.manager.checkRollover(event);
    }

    @Override
    protected void finalize() throws Throwable {
        LogRotateThread.unregisterPolicy(this);
        super.finalize();
    }

    @Override
    public void initialize(final RollingFileManager manager) {
        this.manager = manager;
        timeBasedTriggeringPolicy.initialize(manager);
    }

    @Override
    public boolean isTriggeringEvent(final LogEvent event) {
        return timeBasedTriggeringPolicy.isTriggeringEvent(event);
    }

    @Override
    public String toString() {
        return "FTimeBasedTriggeringPolicy";
    }

    @PluginFactory
    public static FTimeBasedTriggeringPolicy createPolicy(
            @PluginAttribute("interval") final String interval,
            @PluginAttribute("modulate") final String modulate) {
        final int increment = Integers.parseInt(interval, 1);
        final boolean mod = Boolean.parseBoolean(modulate);
        return new FTimeBasedTriggeringPolicy(increment, mod);
    }
}

The log4j2.xml file:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="debug" name="RoutingLoggingConfiguration" packages="org.log4j2plugin" verbose="true">
    <Properties>
        <Property name="routing_filename">${log.path}/table-$${sd:type}.log</Property>
    </Properties>

    <Appenders>
        <Console name="STDOUT">
            <PatternLayout pattern="%d{yyyyMMddHH}{GMT+0} %m%n"/>
        </Console>

        <Routing name="Routing">
            <Routes pattern="$${sd:type}">
                <Route>
                    <RollingFile name="RollingFile-${sd:type}"
                                 fileName="${routing_filename}"
                                 filePattern="${log.path}/%d{yyyyMMdd}{GMT+0}/%d{yyyyMMddHH}{GMT+0}-${sd:type}-${hostName}.%i.log.gz">
                        <PatternLayout>
                            <Pattern>%d{yyyyMMddHH}{GMT+0},'%d{yyyy-MM-dd HH:mm:ss}{GMT+0}',%K{v}%n</Pattern>
                        </PatternLayout>
                        <Policies>
                            <FTimeBasedTriggeringPolicy interval="1"/>
                            <SizeBasedTriggeringPolicy size="64 MB"/>
                        </Policies>
                        <DefaultRolloverStrategy max="999"/>
                    </RollingFile>
                </Route>
            </Routes>
        </Routing>
    </Appenders>

    <Loggers>
        <Logger name="EventLogger" level="debug" additivity="false">
            <AppenderRef ref="Routing"/>
        </Logger>

        <Root level="warn">
            <AppenderRef ref="STDOUT"/>
        </Root>
    </Loggers>
</Configuration>

EDIT:

During debugging I understood that Routes appenders (defined by the $${sd:type} in my case) are not known during log4j2.xml parsing. Thus - their creation/initialization is delayed in time to the moment when the first message for destination $${sd:type} arrives. My next plan is to:

• add a StructuredDataFilter to the Routes appender
• provide an empty message at the system start-up to all known $${sd:type}, which on one hand should initialize Route appender and cause FTimeBasedTriggeringPolicy to register itself in the LogRotateThread, but on other - should be discarded by the StructuredDataFilter
• allow LogRotateThread to query registered FTimeBasedTriggeringPolicy and rotate logs if needed

回答1:

While debugging, it appeared that Routes appenders (defined by the $${sd:type} in my case) are not known during log4j2.xml parsing. Thus, their creation/initialization is delayed in time to the moment when the first message for the destination $${sd:type} arrives. Thus, the original subject of the post could be answered as "custom policy is registered, however not always instantly (or during the .xml parse time)".

The original problem, however, was to force .log files to roll-over at the end of the time period (an hour in my case). To address it, I have implemented following algorithm:

1. wrote a thin wrapper around TimeBasedTriggeringPolicy - FTimeBasedTriggeringPolicy that registers itself on instantiation at LogRotateThread
2. wrote a simple LogRotateThread that queries registered FTimeBasedTriggeringPolicy once every few minutes and makes them rotate .log if needed
3. added a StructuredDataFilter to the Routes appender, so that they discard specific messages (with id=SKIP in my case)
4. provide an empty message at the system start-up to all known $${sd:type}, which:
   a. instantiate Route appender and cause FTimeBasedTriggeringPolicy to register itself in the LogRotateThread
   b. are discarded by the StructuredDataFilter

Solution is published under Apache 2.0 license, and is available at github