zyMu created LOG4J2-3185:
----------------------------
Summary: DefaultErrorHandler can not share values across threads
Key: LOG4J2-3185
URL: https://issues.apache.org/jira/browse/LOG4J2-3185
Project: Log4j 2
Issue Type: Bug
Components: Appenders, Core
Affects Versions: 2.14.1
Reporter: zyMu
My application used a logger with AsyncAppender and set the blocking attribute
to false. The example code as following.
{code:java}
// 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);
}
{code}
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.
{code:java}
// 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);
}
}
}
{code}
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.
{code:java}
// 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;
}
{code}
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
