[LOG4J2-1049] AsyncAppender eats my Interrupt

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.2, 2.3
• Fix Version/s: 2.4
• Component/s: Appenders
• Labels: Async

Environment

Java 7, Windows

• Flags: Patch
• Assignee: Remko Popma
• Reporter: Robert Schaft
• Created: 10/Jun/15 13:46
• Updated: 11/Jun/15 08:21
• Resolved: 10/Jun/15 16:14

Description

I wrote a LoggingThread that will be stopped by sending loggingThread.interrupt() from another Thread.

LoggingThread.java

class LoggingThread extends Thread {
  private final static Logger LOGGER = LoggerFactory.getLogger(LoggingThread .class);
  public void run() {
    while (!Thread.currentThread().isInterrupted()) {
      LOGGER.debug("{} is logging {}", this, "nothing");
    }
  }
}

Unfortunately, loggingThread.interrupt() is sometimes set before AsyncAppender.append() or at the beginning of that.

AsyncAppender#append() line 153

try {
  // wait for free slots in the queue
  queue.put(Log4jLogEvent.serialize(coreEvent, includeLocation));
  appendSuccessful = true;
} catch (final InterruptedException e) {
  LOGGER.warn("Interrupted while waiting for a free slot in the AsyncAppender LogEvent-queue {}",
  getName());
}

This will make queue.put throw an InterruptedException and remove the interrupted flag of the current flag.

I suggest a simple bugfix: Call Thread by Thread.currentThread().interrupt() in the catch clause. This will reset the interrupted flag of the current Thread.

A more complex bugfix which doesn't loose a message:

AsyncAppender#append() line 153

Serializable serialized = Log4jLogEvent.serialize(coreEvent, includeLocation);
try {
  // wait for free slots in the queue
  queue.put(serialized);
  appendSuccessful = true;
} catch (final InterruptedException e) {
  try {
    // The interrupt is catched and the interrupted flag is unset.
    // Therefore offer() won't return with an InterruptedException
    // unless another Thread sends again an interrupt.
    // Use a timeout to handle the case where the Interrupt e
    // was really meant for a hanging put() and not just 
    // coincidently sent at the same time.
    // If the put() was really hanging,
    // offer() would return with false after 10ms and no second
    // external interrupt() is required
    appendSuccessful = queue.offer(serialized, 10L, TimeUnit.MILLISECONDS);
  } catch (final InterruptedException e2) {
    // queue.put is really hanging and someone 
  }
  if (!appendSuccessful) {
    LOGGER.warn("Interrupted while waiting for a free slot in the AsyncAppender LogEvent-queue {}",
    getName());
  }
  // set the interrupted flag again.
  Thread.currentThread().interrupt();
}