diff --git a/src/main/java/org/apache/log4j/NewAsyncAppender.java b/src/main/java/org/apache/log4j/NewAsyncAppender.java index da4cf9c1..974ba12e 100644 --- a/src/main/java/org/apache/log4j/NewAsyncAppender.java +++ b/src/main/java/org/apache/log4j/NewAsyncAppender.java @@ -20,10 +20,13 @@ import org.apache.log4j.helpers.LogLog; import org.apache.log4j.spi.AppenderAttachable; import org.apache.log4j.spi.LoggingEvent; +import org.apache.log4j.varia.InterruptUtil; +import sun.rmi.runtime.Log; import java.util.ArrayList; import java.util.Enumeration; import java.util.List; +import java.util.concurrent.ArrayBlockingQueue; import java.util.concurrent.BlockingQueue; import java.util.concurrent.atomic.AtomicInteger; @@ -59,13 +62,23 @@ public class NewAsyncAppender extends AppenderSkeleton implements AppenderAttach boolean includeCallerData = false; public NewAsyncAppender() { + } + + @Override + public void activateOptions() { if (queueSize < 1) { LogLog.error("Invalid queue size [" + queueSize + "]"); return; } + + blockingQueue = new ArrayBlockingQueue(queueSize); + if (discardingThreshold == UNDEFINED) + discardingThreshold = queueSize / 5; + LogLog.debug("Setting discardingThreshold to " + discardingThreshold); worker.setDaemon(true); - worker.setName("AsyncSingleAppender-Worker-" + getName()); + worker.setName("NewAsyncSingleAppender-Worker-" + getName()); worker.start(); + } protected void append(LoggingEvent event) { @@ -100,6 +113,8 @@ protected void preprocess(LoggingEvent eventObject) { if (includeCallerData) { eventObject.getLocationInformation(); } + eventObject.getRenderedMessage(); + eventObject.getThrowableStrRep(); } private void put(LoggingEvent eventObject) { @@ -131,11 +146,23 @@ public void close() { return; closed = true; + worker.interrupt(); + InterruptUtil interruptUtil = new InterruptUtil(); + try { + interruptUtil.maskInterruptFlag(); worker.join(maxFlushTime); + if(worker.isAlive()) { + LogLog.warn("Max queue flush timeout (" + maxFlushTime + " ms) exceeded. Approximately " + + blockingQueue.size() + " queued events were possibly discarded."); + } else { + LogLog.debug("Queue flush finished successfully within timeout."); + } } catch (InterruptedException e) { throw new RuntimeException(e); + } finally { + interruptUtil.maskInterruptFlag(); } } @@ -149,10 +176,10 @@ public boolean requiresLayout() { public void addAppender(Appender newAppender) { if (appenderCount.compareAndSet(0, 1)) { - LogLog.debug("Attaching appender named [" + newAppender.getName() + "] to AsyncAppender."); + LogLog.debug("Attaching appender named [" + newAppender.getName() + "] to NewAsyncAppender."); appenders.addAppender(newAppender); } else { - LogLog.warn("One and only one appender may be attached to AsyncAppender."); + LogLog.warn("One and only one appender may be attached to NewAsyncAppender."); LogLog.warn("Ignoring additional appender named [" + newAppender.getName() + "]"); } } @@ -205,6 +232,13 @@ public void setMaxFlushTime(int maxFlushTime) { this.maxFlushTime = maxFlushTime; } + public void setNeverBlock(boolean neverBlock) { + this.neverBlock = neverBlock; + } + + public boolean isNeverBlock() { + return neverBlock; + } public boolean isIncludeCallerData() { return includeCallerData; diff --git a/src/main/java/org/apache/log4j/varia/InterruptUtil.java b/src/main/java/org/apache/log4j/varia/InterruptUtil.java new file mode 100644 index 00000000..34ef7d30 --- /dev/null +++ b/src/main/java/org/apache/log4j/varia/InterruptUtil.java @@ -0,0 +1,28 @@ +package org.apache.log4j.varia; + +import org.apache.log4j.helpers.LogLog; + +public class InterruptUtil { + final boolean previouslyInterrupted; + + public InterruptUtil() { + super(); + previouslyInterrupted = Thread.currentThread().isInterrupted(); + } + + public void maskInterruptFlag() { + if (previouslyInterrupted) { + Thread.interrupted(); + } + } + + public void unmaskInterruptFlag() { + if (previouslyInterrupted) { + try { + Thread.currentThread().interrupt(); + } catch (SecurityException se) { + LogLog.error("Failed to interrupt current thread", se); + } + } + } +} diff --git a/src/test/input/xml/newAsyncAppender0.xml b/src/test/input/xml/newAsyncAppender0.xml new file mode 100644 index 00000000..f5ff856e --- /dev/null +++ b/src/test/input/xml/newAsyncAppender0.xml @@ -0,0 +1,35 @@ + + + + + + + + + + + + + + + + + + + \ No newline at end of file diff --git a/src/test/java/org/apache/log4j/AsyncAppenderTestCase.java b/src/test/java/org/apache/log4j/AsyncAppenderTestCase.java index efdca4e2..33b30fd4 100644 --- a/src/test/java/org/apache/log4j/AsyncAppenderTestCase.java +++ b/src/test/java/org/apache/log4j/AsyncAppenderTestCase.java @@ -100,25 +100,6 @@ public void test3() { assertTrue(vectorAppender.isClosed()); } - private static class NullPointerAppender extends AppenderSkeleton { - public NullPointerAppender() { - } - - /** - * This method is called by the {@link org.apache.log4j.AppenderSkeleton#doAppend} method. - */ - public void append(org.apache.log4j.spi.LoggingEvent event) { - throw new NullPointerException(); - } - - public void close() { - } - - public boolean requiresLayout() { - return false; - } - } - /** * Tests that a bad appender will switch async back to sync. See bug 23021 * @@ -206,95 +187,8 @@ public void testLocationInfoFalse() { assertEquals("?:? ", discardStr.substring(0, 4)); } - /** - * Logging request runnable. - */ - private static final class Greeter implements Runnable { - /** - * Logger. - */ - private final Logger logger; - /** - * Repetitions. - */ - private final int repetitions; - - /** - * Create new instance. - * - * @param logger logger, may not be null. - * @param repetitions repetitions. - */ - public Greeter(final Logger logger, final int repetitions) { - if (logger == null) { - throw new IllegalArgumentException("logger"); - } - - this.logger = logger; - this.repetitions = repetitions; - } - /** - * {@inheritDoc} - */ - public void run() { - try { - for (int i = 0; i < repetitions; i++) { - logger.info("Hello, World"); - Thread.sleep(1); - } - } catch (InterruptedException ex) { - Thread.currentThread().interrupt(); - } - } - } - - /** - * Vector appender that can be explicitly blocked. - */ - private static final class BlockableVectorAppender extends VectorAppender { - /** - * Monitor object used to block appender. - */ - private final Object monitor = new Object(); - - /** - * Create new instance. - */ - public BlockableVectorAppender() { - super(); - } - - /** - * {@inheritDoc} - */ - public void append(final LoggingEvent event) { - synchronized (monitor) { - super.append(event); - // - // if fatal, echo messages for testLoggingInDispatcher - // - if (event.getLevel() == Level.FATAL) { - Logger logger = Logger.getLogger(event.getLoggerName()); - logger.error(event.getMessage().toString()); - logger.warn(event.getMessage().toString()); - logger.info(event.getMessage().toString()); - logger.debug(event.getMessage().toString()); - } - } - } - - /** - * Get monitor object. - * - * @return monitor. - */ - public Object getMonitor() { - return monitor; - } - - } /** * Test that a mutable message object is evaluated before being placed in the async queue. See bug 43559. diff --git a/src/test/java/org/apache/log4j/BlockableVectorAppender.java b/src/test/java/org/apache/log4j/BlockableVectorAppender.java new file mode 100644 index 00000000..de9e1ab6 --- /dev/null +++ b/src/test/java/org/apache/log4j/BlockableVectorAppender.java @@ -0,0 +1,49 @@ +package org.apache.log4j; + +import org.apache.log4j.spi.LoggingEvent; + +/** + * Vector appender that can be explicitly blocked. + */ +final class BlockableVectorAppender extends VectorAppender { + /** + * Monitor object used to block appender. + */ + private final Object monitor = new Object(); + + /** + * Create new instance. + */ + public BlockableVectorAppender() { + super(); + } + + /** + * {@inheritDoc} + */ + public void append(final LoggingEvent event) { + synchronized (monitor) { + super.append(event); + // + // if fatal, echo messages for testLoggingInDispatcher + // + if (event.getLevel() == Level.FATAL) { + Logger logger = Logger.getLogger(event.getLoggerName()); + logger.error(event.getMessage().toString()); + logger.warn(event.getMessage().toString()); + logger.info(event.getMessage().toString()); + logger.debug(event.getMessage().toString()); + } + } + } + + /** + * Get monitor object. + * + * @return monitor. + */ + public Object getMonitor() { + return monitor; + } + +} \ No newline at end of file diff --git a/src/test/java/org/apache/log4j/Greeter.java b/src/test/java/org/apache/log4j/Greeter.java new file mode 100644 index 00000000..01a58b91 --- /dev/null +++ b/src/test/java/org/apache/log4j/Greeter.java @@ -0,0 +1,45 @@ +package org.apache.log4j; + +/** + * Logging request runnable. + */ +final class Greeter implements Runnable { + /** + * Logger. + */ + private final Logger logger; + + /** + * Repetitions. + */ + private final int repetitions; + + /** + * Create new instance. + * + * @param logger logger, may not be null. + * @param repetitions repetitions. + */ + public Greeter(final Logger logger, final int repetitions) { + if (logger == null) { + throw new IllegalArgumentException("logger"); + } + + this.logger = logger; + this.repetitions = repetitions; + } + + /** + * {@inheritDoc} + */ + public void run() { + try { + for (int i = 0; i < repetitions; i++) { + logger.info("Hello, World"); + Thread.sleep(1); + } + } catch (InterruptedException ex) { + Thread.currentThread().interrupt(); + } + } +} diff --git a/src/test/java/org/apache/log4j/NewAsyncAppenderTestCase.java b/src/test/java/org/apache/log4j/NewAsyncAppenderTestCase.java new file mode 100644 index 00000000..1667fc3b --- /dev/null +++ b/src/test/java/org/apache/log4j/NewAsyncAppenderTestCase.java @@ -0,0 +1,223 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +package org.apache.log4j; + +import junit.framework.TestCase; +import org.apache.log4j.helpers.LogLog; +import org.apache.log4j.spi.LoggingEvent; + +import java.util.Vector; + +public class NewAsyncAppenderTestCase extends TestCase { + public NewAsyncAppenderTestCase(String name) { + super(name); + } + + public void setUp() { + System.setProperty(LogLog.DEBUG_KEY, "true"); + } + + public void tearDown() { + System.clearProperty(LogLog.DEBUG_KEY); + LogManager.shutdown(); + } + + // this test checks whether it is possible to write to a closed AsyncAppender + public void testClose() throws Exception { + Logger root = Logger.getRootLogger(); + VectorAppender vectorAppender = new VectorAppender(); + NewAsyncAppender newAsyncAppender = new NewAsyncAppender(); + newAsyncAppender.setName("async-CloseTest"); + newAsyncAppender.activateOptions(); + + newAsyncAppender.addAppender(vectorAppender); + root.addAppender(newAsyncAppender); + + root.debug("m1"); + newAsyncAppender.close(); + root.debug("m2"); + + Vector v = vectorAppender.getVector(); + assertEquals(v.size(), 1); + } + + // this test checks whether appenders embedded within an AsyncAppender are also + // closed + public void test2() { + Logger root = Logger.getRootLogger(); + VectorAppender vectorAppender = new VectorAppender(); + NewAsyncAppender newAsyncAppender = new NewAsyncAppender(); + newAsyncAppender.setName("async-test2"); + newAsyncAppender.activateOptions(); + newAsyncAppender.addAppender(vectorAppender); + root.addAppender(newAsyncAppender); + + root.debug("m1"); + newAsyncAppender.close(); + root.debug("m2"); + + Vector v = vectorAppender.getVector(); + assertEquals(v.size(), 1); + assertTrue(vectorAppender.isClosed()); + } + + // this test checks whether appenders embedded within an AsyncAppender are also + // closed + public void test3() { + int LEN = 200; + Logger root = Logger.getRootLogger(); + VectorAppender vectorAppender = new VectorAppender(); + vectorAppender.setDelay(0); + NewAsyncAppender newAsyncAppender = new NewAsyncAppender(); + newAsyncAppender.setName("async-test3"); + newAsyncAppender.activateOptions(); + newAsyncAppender.addAppender(vectorAppender); + root.addAppender(newAsyncAppender); + + for (int i = 0; i < LEN; i++) { + root.debug("message" + i); + } + + System.out.println("Done loop."); + + newAsyncAppender.close(); + root.debug("m2"); + + Vector v = vectorAppender.getVector(); + assertTrue(vectorAppender.isClosed()); + assertEquals(LEN, v.size()); + + } + + /** + * Tests that a bad appender will switch async back to sync. See bug 23021 + * + * @throws Exception thrown if Thread.sleep is interrupted + * @since 1.2.12 + */ + public void testBadAppender() throws Exception { + Appender nullPointerAppender = new NullPointerAppender(); + NewAsyncAppender newAsyncAppender = new NewAsyncAppender(); + newAsyncAppender.addAppender(nullPointerAppender); + newAsyncAppender.setQueueSize(5); + newAsyncAppender.activateOptions(); + Logger root = Logger.getRootLogger(); + root.addAppender(nullPointerAppender); + try { + root.info("Message"); + Thread.sleep(10); + root.info("Message"); + fail("Should have thrown exception"); + } catch (NullPointerException ex) { + + } + } + + /** + * Tests location processing when buffer is full and locationInfo=true. See bug 41186. + */ + public void testLocationInfoTrue() { + BlockableVectorAppender blockableAppender = new BlockableVectorAppender(); + NewAsyncAppender newAsyncAppender = new NewAsyncAppender(); + newAsyncAppender.addAppender(blockableAppender); + newAsyncAppender.setQueueSize(5); + newAsyncAppender.setIncludeCallerData(true); + newAsyncAppender.setNeverBlock(true); + newAsyncAppender.activateOptions(); + Logger rootLogger = Logger.getRootLogger(); + rootLogger.addAppender(newAsyncAppender); + Greeter greeter = new Greeter(rootLogger, 100); + synchronized (blockableAppender.getMonitor()) { + greeter.run(); + } + rootLogger.error("That's all folks."); + newAsyncAppender.close(); + Vector eventsVevtor = blockableAppender.getVector(); + LoggingEvent initialEvent = (LoggingEvent) eventsVevtor.get(0); + // NewAsyncAppender does not have discard events + //LoggingEvent discardEvent = (LoggingEvent) eventsVevtor.get(eventsVevtor.size() - 1); + PatternLayout layout = new PatternLayout(); + layout.setConversionPattern("%C:%L %m%n"); + layout.activateOptions(); + String initialStr = layout.format(initialEvent); + System.out.println("========"+initialStr); + assertEquals(Greeter.class.getName(), + initialStr.substring(0, Greeter.class.getName().length())); + // NewAsyncAppender does not have discard events + //String discardStr = layout.format(discardEvent); + //assertEquals("?:? ", discardStr.substring(0, 40)); + } + + /** + * Tests location processing when buffer is full and locationInfo=false. See bug 41186. + */ + public void testLocationInfoFalse() { + BlockableVectorAppender blockableAppender = new BlockableVectorAppender(); + NewAsyncAppender async = new NewAsyncAppender(); + async.addAppender(blockableAppender); + async.setQueueSize(5); + async.setIncludeCallerData(false); + async.setNeverBlock(true); + async.activateOptions(); + Logger rootLogger = Logger.getRootLogger(); + rootLogger.addAppender(async); + Greeter greeter = new Greeter(rootLogger, 100); + synchronized (blockableAppender.getMonitor()) { + greeter.run(); + rootLogger.error("That's all folks."); + } + async.close(); + Vector events = blockableAppender.getVector(); + LoggingEvent initialEvent = (LoggingEvent) events.get(0); + LoggingEvent discardEvent = (LoggingEvent) events.get(events.size() - 1); + PatternLayout layout = new PatternLayout(); + layout.setConversionPattern("%C:%L %m%n"); + layout.activateOptions(); + String initialStr = layout.format(initialEvent); + assertEquals("?:? ", initialStr.substring(0, 4)); + String discardStr = layout.format(discardEvent); + assertEquals("?:? ", discardStr.substring(0, 4)); + } + + /** + * Test that a mutable message object is evaluated before being placed in the async queue. See bug 43559. + */ + public void testMutableMessage() { + BlockableVectorAppender blockableAppender = new BlockableVectorAppender(); + NewAsyncAppender newAsync = new NewAsyncAppender(); + newAsync.addAppender(blockableAppender); + newAsync.setQueueSize(5); + newAsync.setIncludeCallerData(false); + newAsync.activateOptions(); + Logger rootLogger = Logger.getRootLogger(); + rootLogger.addAppender(newAsync); + StringBuffer buf = new StringBuffer("Hello"); + synchronized (blockableAppender.getMonitor()) { + rootLogger.info(buf); + buf.append(", World."); + } + newAsync.close(); + Vector events = blockableAppender.getVector(); + LoggingEvent event = (LoggingEvent) events.get(0); + PatternLayout layout = new PatternLayout(); + layout.setConversionPattern("%m"); + layout.activateOptions(); + String msg = layout.format(event); + assertEquals("Hello", msg); + } +} diff --git a/src/test/java/org/apache/log4j/NullPointerAppender.java b/src/test/java/org/apache/log4j/NullPointerAppender.java new file mode 100644 index 00000000..cff65632 --- /dev/null +++ b/src/test/java/org/apache/log4j/NullPointerAppender.java @@ -0,0 +1,20 @@ +package org.apache.log4j; + +class NullPointerAppender extends AppenderSkeleton { + public NullPointerAppender() { + } + + /** + * This method is called by the {@link org.apache.log4j.AppenderSkeleton#doAppend} method. + */ + public void append(org.apache.log4j.spi.LoggingEvent event) { + throw new NullPointerException(); + } + + public void close() { + } + + public boolean requiresLayout() { + return false; + } +} \ No newline at end of file diff --git a/src/test/java/org/apache/log4j/VectorAppender.java b/src/test/java/org/apache/log4j/VectorAppender.java index a460365f..726d7a12 100644 --- a/src/test/java/org/apache/log4j/VectorAppender.java +++ b/src/test/java/org/apache/log4j/VectorAppender.java @@ -29,11 +29,19 @@ public class VectorAppender extends AppenderSkeleton { public Vector vector; - + long delay = 100; public VectorAppender() { vector = new Vector(); } + public long getDelay() { + return delay; + } + + public void setDelay(long delay) { + this.delay = delay; + } + /** * Does nothing. */ @@ -48,7 +56,9 @@ public void append(LoggingEvent event) { // ["+event.getRenderedMessage()+"]."); // System.out.flush(); try { - Thread.sleep(100); + if(delay > 0) { + Thread.sleep(delay); + } } catch (Exception e) { } vector.addElement(event); diff --git a/src/test/java/org/apache/log4j/xml/DOM_NewAsyncAppenderTestCase.java b/src/test/java/org/apache/log4j/xml/DOM_NewAsyncAppenderTestCase.java new file mode 100644 index 00000000..ac5038db --- /dev/null +++ b/src/test/java/org/apache/log4j/xml/DOM_NewAsyncAppenderTestCase.java @@ -0,0 +1,41 @@ +package org.apache.log4j.xml; + +import org.apache.log4j.*; +import org.apache.log4j.util.Compare; +import org.junit.After; +import org.junit.Before; +import org.junit.Test; + +import static org.apache.log4j.TestConstants.TEST_INPUT_PREFIX; +import static org.apache.log4j.TestConstants.TEST_WITNESS_PREFIX; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertTrue; + +public class DOM_NewAsyncAppenderTestCase { + Logger root; + + @Before + public void setUp() { + root = Logger.getRootLogger(); + } + + @After + public void tearDown() { + root.getLoggerRepository().resetConfiguration(); + } + + + @Test + public void test1() throws Exception { + DOMConfigurator.configure(TEST_INPUT_PREFIX + "xml/newAsyncAppender0.xml"); + Appender appender = root.getAppender("ASYNC"); + assertTrue(appender instanceof NewAsyncAppender); + + NewAsyncAppender newAsyncAppender = (NewAsyncAppender) appender; + + VectorAppender vectorAppender = (VectorAppender) newAsyncAppender.getAppender("V1"); + assertNotNull(vectorAppender); + + + } +}