Critical Description
My application used a logger with AsyncAppender and set the blocking attribute to false. The example code as following.
// Some example logger usage for catching all throwables and log it to disk file try { // my application code, which may throw an exception } catch (Throwable t) { logger.error("", t); }
If there was too much throwable generated, then the the blocking queue in the async appender will be full, and will never enqueue any more. Thus, it will execute DefaultErrorHandler#error(String) method.
// org.apache.logging.log4j.core.appender.AsyncAppender
@Override
public void append(final LogEvent logEvent) {
if (!isStarted()) {
throw new IllegalStateException("AsyncAppender " + getName() + " is not active");
}
final Log4jLogEvent memento = Log4jLogEvent.createMemento(logEvent, includeLocation);
InternalAsyncUtil.makeMessageImmutable(logEvent.getMessage());
if (!transfer(memento)) {
if (blocking) {
if (AbstractLogger.getRecursionDepth() > 1) { // LOG4J2-1518, LOG4J2-2031
// If queue is full AND we are in a recursive call, call appender directly to prevent deadlock
AsyncQueueFullMessageUtil.logWarningToStatusLogger();
logMessageInCurrentThread(logEvent);
} else {
// delegate to the event router (which may discard, enqueue and block, or log in current thread)
final EventRoute route = asyncQueueFullPolicy.getRoute(dispatcher.getId(), memento.getLevel());
route.logMessage(this, memento);
}
} else {
error("Appender " + getName() + " is unable to write primary appenders. queue is full");
logToErrorAppenderIfNecessary(false, memento);
}
}
}
Application usually runs with multi threads, if the AsyncAppender inner queue was full, then the DefaultErrorHandler may be executed across threads. However, the exceptionCount filed and lastException fields were not volatile variables, it may cause their value were not shared across threads.
// org.apache.logging.log4j.core.appender.DefaultErrorHandler
private static final int MAX_EXCEPTIONS = 3;
private static final long EXCEPTION_INTERVAL = TimeUnit.MINUTES.toNanos(5);
private int exceptionCount = 0;
private long lastException = System.nanoTime() - EXCEPTION_INTERVAL - 1;
@Override
public void error(final String msg) {
final long current = System.nanoTime();
if (current - lastException > EXCEPTION_INTERVAL || exceptionCount++ < MAX_EXCEPTIONS) {
LOGGER.error(msg);
}
lastException = current;
}