Failover Appender logic is not working properly

[sadmanmd]

Description

While working on Log4j2 Failover appender, I saw the failovers appenders not executing properly. if you check the public start method of 'FailoverAppender' class, the logic says if the primary appender is null then it logs an error message and the error counter is increased by one. For that condition the super class 'start' method never executes and the FailoverAppender remains a non started appender. Because of this logic, for some reason primary Failover appender not initiated [like, file path not correct for RollingFile/File], the whole Failover appender will stop working and throw an non started appender error.

Configuration

Version: [Log4j version 2.17.0 - 2.24.3]

Operating system: [Windows/Mac/Linux]

JDK: [1.8,17]

Logs

Exception in thread "main" org.apache.logging.log4j.core.appender.AppenderLoggingException: Attempted to append to non-started appender MyFailoverAppender
	at org.apache.logging.log4j.core.config.AppenderControl.handleError(AppenderControl.java:147)
	at org.apache.logging.log4j.core.config.AppenderControl.ensureAppenderStarted(AppenderControl.java:140)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:132)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:125)
	at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:89)
	at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:683)
	at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:641)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:624)
	at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:560)
	at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:82)
	at org.apache.logging.log4j.core.Logger.log(Logger.java:163)
	at org.apache.logging.log4j.spi.AbstractLogger.tryLogMessage(AbstractLogger.java:2168)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageTrackRecursion(AbstractLogger.java:2122)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessageSafely(AbstractLogger.java:2105)
	at org.apache.logging.log4j.spi.AbstractLogger.logMessage(AbstractLogger.java:1980)
	at org.apache.logging.log4j.spi.AbstractLogger.logIfEnabled(AbstractLogger.java:1946)
	at org.apache.logging.log4j.spi.AbstractLogger.info(AbstractLogger.java:1283)

Reproduction

This config file could be use for reproduction, simply pul an invalid path at the primary appender it will not add to the base config.getAppenders list, because of this the primary appender become null and the FailoverAppender eventually never start for primary appender failure.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="DEBUG">
    <Appenders>
        <File name="PrimaryFileAppender" fileName="[USE AN INVALID PATH]/log/primary.log"
              ignoreExceptions="false">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </File>

        <Console name="BackupConsoleAppender" target="SYSTEM_OUT">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
        </Console>

        <RollingFile name="BackupRollingFileAppender"
                     append="true"
                     fileName="./log/backup.log"
                     filePattern="backup-%d{yyyy-MM-dd}-%i.log.gz"
                     ignoreExceptions="false">
            <PatternLayout pattern="%d{HH:mm:ss.SSS} [%t] %-5level %logger{36} - %msg%n"/>
            <TimeBasedTriggeringPolicy interval="24" modulate="true"/>
            <SizeBasedTriggeringPolicy size="100 MB"/>
        </RollingFile>

        <Failover name="MyFailoverAppender" primary="PrimaryFileAppender" ignoreExceptions="false">
            <Failovers>
                <!-- THIS APPENDERS NEVER EXECUTE -->
                <AppenderRef ref="BackupConsoleAppender"/>
                <AppenderRef ref="BackupRollingFileAppender"/>
            </Failovers>
        </Failover>
    </Appenders>

    <Loggers>
        <Root level="INFO">
            <AppenderRef ref="MyFailoverAppender"/>
        </Root>
    </Loggers>
</Configuration>

[ppkarwasz]

@sadmanmd,

How to handle partial configuration startup failures is currently a grey area in Log4j Core. We discussed this recently on dev@logging and the consensus is that in cases like yours the whole Configuration object should be discarded and the old configuration should be used (or the default configuration if the first configuration fails). Would this be an acceptable solution?

The configuration problem you present in this issue is not a temporary problem accessing a resource, but a permanent one. IMHO it should either prevent the configuration from being used at all or propagate an exception to the caller (we can create a configuration property for this).

[mdsadman-git]

@ppkarwasz,

Thank you for your reply.

Actually, While working on Log4j version update from v1 to v2, a Failover Appender was necessary for my requirement.
While testing the Failover Appender, I tried with some approaches, like

1. Put wrong path in Primary Appender path variable
2. Throw an error at Primary Appender
3. Lock the log file [The appender I was using, was a RollingFile]
   so on...

But I couldn't find a test case to call the secondary appenders.
So I started checking the Log4j2 source and found the logic below.

I updated the logic like this, and it works without any issue.
[*] Please let me know if this could cause any other issue.

Actually what I understand from the name 'Failover Appender' is that,

• It is something that will invoke appenders as an optional element, starts with primary appender
• No matter what happened to the Primary Appender and other Appenders try to run until the last one
• If last one also fails then an exception might throw or some error log will show in the console

---

How to handle partial configuration startup failures is currently a grey area in Log4j Core. We discussed this recently on dev@logging and the consensus is that in cases like yours the whole Configuration object should be discarded and the old configuration should be used (or the default configuration if the first configuration fails). Would this be an acceptable solution?

I understand the idea of default configuration but since there is Secondary Appenders already provided in the configuration, so those could be use as optional appenders. These optional appenders are actually default appender when fails.

The configuration problem you present in this issue is not a temporary problem accessing a resource, but a permanent one. IMHO it should either prevent the configuration from being used at all or propagate an exception to the caller (we can create a configuration property for this).

I think it is better to prevent the configuration from being used at all.
Cause, propagating an exception might stop the application from running.

• If there is a case like an application is relying on Failover Appender to just skip to next Appender scenario,
  Then that application might stop running for that exception.
• But it is a good idea to add an optional parameter for throwing or logging the exception.

Thank you.

[ppkarwasz]

While testing the Failover Appender, I tried with some approaches, like

1. Put wrong path in Primary Appender path variable
2. Throw an error at Primary Appender
3. Lock the log file [The appender I was using, was a RollingFile]
   so on...

What do you mean by "wrong path"? I think that the behavior of Log4j Core should be different, depending on the type of error:

1. If this is an invalid path in your OS (e.g. a path containing : or other forbidden characters on Windows), then Log4j Core should refuse to start such a configuration.
2. If the path is valid, but an error occurs while creating it, the behavior should depend on the createOnDemand option. If it is false, then the whole configuration shouldn't start, otherwise the appender should be created and try to open the file at each log event.

How to handle partial configuration startup failures is currently a grey area in Log4j Core. We discussed this recently on dev@logging and the consensus is that in cases like yours the whole Configuration object should be discarded and the old configuration should be used (or the default configuration if the first configuration fails). Would this be an acceptable solution?

I understand the idea of default configuration but since there is Secondary Appenders already provided in the configuration, so those could be use as optional appenders. These optional appenders are actually default appender when fails.

In my understanding, users of FailoverAppender want to use the primary appender most of the time. The secondary appenders are there to temporarily relief the primary appender if it fails, but most of the time the primary appender should be used.

Therefore I think that the problem is:

• RollingFileAppender should not fail in its constructor if a temporary problem is detected. If it fails the whole configuration should fail with it.
• RollingFileAppender should try to open the log file in its start method, not the constructor. Until start is called, the appender should not use any resources.