From 81d2ff6d2f7a98e26683f34852b434281d85258a Mon Sep 17 00:00:00 2001 From: Keith Wall Date: Thu, 22 Sep 2011 15:19:29 +0000 Subject: QPID-3501: LogMonitor can corrupt test logs files and cause tests subclassing AbstractLoggingTests to fail. git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@1174196 13f79535-47bb-0310-9956-ffa450edef68 --- .../management/jmx/ManagementActorLoggingTest.java | 22 ++-- .../apache/qpid/server/logging/AlertingTest.java | 4 +- .../qpid/server/logging/BindingLoggingTest.java | 2 +- .../logging/DerbyMessageStoreLoggingTest.java | 2 +- .../server/logging/DurableQueueLoggingTest.java | 2 +- .../qpid/server/logging/ExchangeLoggingTest.java | 6 +- .../qpid/server/logging/QueueLoggingTest.java | 2 +- .../server/logging/SubscriptionLoggingTest.java | 2 +- .../qpid/server/queue/ProducerFlowControlTest.java | 2 +- .../apache/qpid/test/utils/QpidBrokerTestCase.java | 5 + .../main/java/org/apache/qpid/util/LogMonitor.java | 115 ++++++++++++++++----- .../java/org/apache/qpid/util/LogMonitorTest.java | 23 ++--- 12 files changed, 127 insertions(+), 60 deletions(-) (limited to 'java') diff --git a/java/systests/src/main/java/org/apache/qpid/management/jmx/ManagementActorLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/management/jmx/ManagementActorLoggingTest.java index 2864d8e994..12a1682212 100644 --- a/java/systests/src/main/java/org/apache/qpid/management/jmx/ManagementActorLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/management/jmx/ManagementActorLoggingTest.java @@ -106,7 +106,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging }); //Remove the connection close from any 0-10 connections - _monitor.reset(); + _monitor.markDiscardPoint(); // Get a managedConnection ManagedConnection mangedConnection = _jmxUtils.getManagedObject(ManagedConnection.class, "org.apache.qpid:type=VirtualHost.Connection,*"); @@ -147,7 +147,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging */ public void testCreateExchangeDirectTransientViaManagementConsole() throws IOException, JMException { - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createExchange("test", getName(), "direct", false); @@ -171,7 +171,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testCreateExchangeTopicTransientViaManagementConsole() throws IOException, JMException { //Remove any previous exchange declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createExchange("test", getName(), "topic", false); @@ -196,7 +196,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testCreateExchangeFanoutTransientViaManagementConsole() throws IOException, JMException { //Remove any previous exchange declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createExchange("test", getName(), "fanout", false); @@ -221,7 +221,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testCreateExchangeHeadersTransientViaManagementConsole() throws IOException, JMException { //Remove any previous exchange declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createExchange("test", getName(), "headers", false); @@ -265,7 +265,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testCreateQueueTransientViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createQueue("test", getName(), null, false); @@ -308,7 +308,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testQueueDeleteViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createQueue("test", getName(), null, false); @@ -354,7 +354,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testBindingCreateOnDirectViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createQueue("test", getName(), null, false); @@ -381,7 +381,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testBindingCreateOnTopicViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createQueue("test", getName(), null, false); @@ -408,7 +408,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testBindingCreateOnFanoutViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createQueue("test", getName(), null, false); @@ -455,7 +455,7 @@ public class ManagementActorLoggingTest extends AbstractTestLogging public void testUnRegisterExchangeViaManagementConsole() throws IOException, JMException { //Remove any previous queue declares - _monitor.reset(); + _monitor.markDiscardPoint(); _jmxUtils.createExchange("test", getName(), "direct", false); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/AlertingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/AlertingTest.java index a2487b49bf..aef98b8a2a 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/AlertingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/AlertingTest.java @@ -136,7 +136,7 @@ public class AlertingTest extends AbstractTestLogging stopBroker(); // Rest the monitoring clearing the current output file. - _monitor.reset(); + _monitor.markDiscardPoint(); startBroker(); wasAlertFired(); } @@ -169,7 +169,7 @@ public class AlertingTest extends AbstractTestLogging stopBroker(); - _monitor.reset(); + _monitor.markDiscardPoint(); // Change max message count to 5, start broker and make sure that that's triggered at the right time setConfigurationProperty("virtualhosts.virtualhost." + VIRTUALHOST + ".queues.maximumMessageCount", "5"); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/BindingLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/BindingLoggingTest.java index 97914f84a5..be2da128bc 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/BindingLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/BindingLoggingTest.java @@ -55,7 +55,7 @@ public class BindingLoggingTest extends AbstractTestLogging { super.setUp(); //Ignore broker startup messages - _monitor.reset(); + _monitor.markDiscardPoint(); _connection = getConnection(); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/DerbyMessageStoreLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/DerbyMessageStoreLoggingTest.java index 16c529316a..d45bde2d98 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/DerbyMessageStoreLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/DerbyMessageStoreLoggingTest.java @@ -496,7 +496,7 @@ public class DerbyMessageStoreLoggingTest extends MemoryMessageStoreLoggingTest stopBroker(); // Clear our monitor - _monitor.reset(); + _monitor.markDiscardPoint(); startBroker(); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java index 32adc49521..602bdb66b5 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java @@ -58,7 +58,7 @@ public class DurableQueueLoggingTest extends AbstractTestLogging { super.setUp(); //Ensure we only have logs from our test - _monitor.reset(); + _monitor.markDiscardPoint(); _connection = getConnection(); _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java index b3c080b2e3..ec96f778f6 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java @@ -125,7 +125,7 @@ public class ExchangeLoggingTest extends AbstractTestLogging public void testExchangeCreate() throws JMSException, IOException { //Ignore broker startup messages - _monitor.reset(); + _monitor.markDiscardPoint(); _session.createConsumer(_queue); // Ensure we have received the EXH log msg. @@ -179,7 +179,7 @@ public class ExchangeLoggingTest extends AbstractTestLogging public void testExchangeDelete() throws Exception, IOException { //Ignore broker startup messages - _monitor.reset(); + _monitor.markDiscardPoint(); //create the exchange by creating a consumer _session.createConsumer(_queue); @@ -220,7 +220,7 @@ public class ExchangeLoggingTest extends AbstractTestLogging public void testDiscardedMessage() throws Exception { //Ignore broker startup messages - _monitor.reset(); + _monitor.markDiscardPoint(); if (!isBroker010()) { diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/QueueLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/QueueLoggingTest.java index b8a42c0ab3..76ebda0ebd 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/QueueLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/QueueLoggingTest.java @@ -53,7 +53,7 @@ public class QueueLoggingTest extends AbstractTestLogging { super.setUp(); //Remove broker startup logging messages - _monitor.reset(); + _monitor.markDiscardPoint(); _connection = getConnection(); _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/SubscriptionLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/SubscriptionLoggingTest.java index 6e156f091e..b6efe53580 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/logging/SubscriptionLoggingTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/logging/SubscriptionLoggingTest.java @@ -58,7 +58,7 @@ public class SubscriptionLoggingTest extends AbstractTestLogging { super.setUp(); //Remove broker startup logging messages - _monitor.reset(); + _monitor.markDiscardPoint(); _connection = getConnection(); diff --git a/java/systests/src/main/java/org/apache/qpid/server/queue/ProducerFlowControlTest.java b/java/systests/src/main/java/org/apache/qpid/server/queue/ProducerFlowControlTest.java index f78b327209..a724e6c66e 100644 --- a/java/systests/src/main/java/org/apache/qpid/server/queue/ProducerFlowControlTest.java +++ b/java/systests/src/main/java/org/apache/qpid/server/queue/ProducerFlowControlTest.java @@ -64,7 +64,7 @@ public class ProducerFlowControlTest extends AbstractTestLogging _jmxUtilConnected=false; super.setUp(); - _monitor.reset(); + _monitor.markDiscardPoint(); producerConnection = getConnection(); producerSession = producerConnection.createSession(false, Session.AUTO_ACKNOWLEDGE); diff --git a/java/systests/src/main/java/org/apache/qpid/test/utils/QpidBrokerTestCase.java b/java/systests/src/main/java/org/apache/qpid/test/utils/QpidBrokerTestCase.java index 40df024c67..455a208a3f 100644 --- a/java/systests/src/main/java/org/apache/qpid/test/utils/QpidBrokerTestCase.java +++ b/java/systests/src/main/java/org/apache/qpid/test/utils/QpidBrokerTestCase.java @@ -219,6 +219,11 @@ public class QpidBrokerTestCase extends QpidTestCase _outputFile = new File(String.format("%s/TEST-%s.out", _output, qname)); out = new PrintStream(_outputFile); err = new PrintStream(String.format("%s/TEST-%s.err", _output, qname)); + + // This is relying on behaviour specific to log4j 1.2.12. If we were to upgrade to 1.2.13 or + // beyond we must change either code (or config) to ensure that ConsoleAppender#setFollow + // is set to true otherwise log4j logging will not respect the following reassignment. + System.setOut(out); System.setErr(err); diff --git a/java/systests/src/main/java/org/apache/qpid/util/LogMonitor.java b/java/systests/src/main/java/org/apache/qpid/util/LogMonitor.java index a5e2b80f64..3b0033f2e2 100644 --- a/java/systests/src/main/java/org/apache/qpid/util/LogMonitor.java +++ b/java/systests/src/main/java/org/apache/qpid/util/LogMonitor.java @@ -27,10 +27,9 @@ import org.apache.log4j.SimpleLayout; import java.io.BufferedReader; import java.io.File; import java.io.FileNotFoundException; -import java.io.FileOutputStream; import java.io.FileReader; import java.io.IOException; -import java.io.OutputStreamWriter; +import java.io.LineNumberReader; import java.util.ArrayList; import java.util.List; import java.util.LinkedList; @@ -50,6 +49,8 @@ public class LogMonitor // The appender we added to the get messages private FileAppender _appender; + private int _linesToSkip = 0; + /** * Create a new LogMonitor that creates a new Log4j Appender and monitors * all log4j output via the current configuration. @@ -116,7 +117,9 @@ public class LogMonitor } /** - * Checks the log for instances of the search string. + * Checks the log for instances of the search string. If the caller + * has previously called {@link #markDiscardPoint()}, lines up until the discard + * point are not considered. * * The pattern parameter can take any valid argument used in String.contains() * @@ -130,17 +133,39 @@ public class LogMonitor */ public List findMatches(String pattern) throws IOException { - return FileUtils.searchFile(_logfile, pattern); + + List results = new LinkedList(); + + LineNumberReader reader = new LineNumberReader(new FileReader(_logfile)); + try + { + while (reader.ready()) + { + String line = reader.readLine(); + if (reader.getLineNumber() > _linesToSkip && line.contains(pattern)) + { + results.add(line); + } + } + } + finally + { + reader.close(); + } + + return results; } /** - * Checks the log file for a given message to appear. + * Checks the log file for a given message to appear. If the caller + * has previously called {@link #markDiscardPoint()}, lines up until the discard + * point are not considered. * * @param message the message to wait for in the log * @param wait the time in ms to wait for the message to occur * * @param printFileOnFailure should we print the contents that have been - * read if we fail ot find the message. + * read if we fail to find the message. * @return true if the message was found * * @throws java.io.FileNotFoundException if the Log file can nolonger be found @@ -151,39 +176,54 @@ public class LogMonitor { // Loop through alerts until we're done or wait ms seconds have passed, // just in case the logfile takes a while to flush. - BufferedReader reader = new BufferedReader(new FileReader(_logfile)); - boolean found = false; - long endtime = System.currentTimeMillis() + wait; - ArrayList contents = new ArrayList(); - while (!found && System.currentTimeMillis() < endtime) + LineNumberReader reader = null; + try { - while (reader.ready()) + reader = new LineNumberReader(new FileReader(_logfile)); + + boolean found = false; + long endtime = System.currentTimeMillis() + wait; + ArrayList contents = new ArrayList(); + while (!found && System.currentTimeMillis() < endtime) { - String line = reader.readLine(); - contents.add(line); - if (line.contains(message)) + while (reader.ready()) + { + String line = reader.readLine(); + + if (reader.getLineNumber() > _linesToSkip) + { + contents.add(line); + if (line.contains(message)) + { + found = true; + } + } + } + } + if (!found && printFileOnFailure) + { + for (String line : contents) { - found = true; + System.out.println(line); } } + return found; + } - if (!found && printFileOnFailure) + finally { - for (String line : contents) + if (reader != null) { - System.out.println(line); + reader.close(); } } - return found; } - public boolean waitForMessage(String message, long alertLogWaitPeriod) throws FileNotFoundException, IOException { return waitForMessage(message, alertLogWaitPeriod, true); } - /** * Read the log file in to memory as a String * @@ -208,14 +248,37 @@ public class LogMonitor } /** - * Clears the log file and writes: 'Log Monitor Reset' at the start of the file + * Marks the discard point in the log file. * - * @throws java.io.FileNotFoundException if the Log file can nolonger be found + * @throws java.io.FileNotFoundException if the Log file can no longer be found * @throws IOException thrown if there is a problem with the log file */ - public void reset() throws FileNotFoundException, IOException + public void markDiscardPoint() throws FileNotFoundException, IOException + { + _linesToSkip = countLinesInFile(); + } + + private int countLinesInFile() throws IOException { - new FileOutputStream(_logfile).getChannel().truncate(0); + int lineCount = 0; + BufferedReader br = null; + try + { + br = new BufferedReader(new FileReader(_logfile)); + while(br.readLine() != null) + { + lineCount++; + } + + return lineCount; + } + finally + { + if (br != null) + { + br.close(); + } + } } /** diff --git a/java/systests/src/main/java/org/apache/qpid/util/LogMonitorTest.java b/java/systests/src/main/java/org/apache/qpid/util/LogMonitorTest.java index a99abe4b94..032853db67 100644 --- a/java/systests/src/main/java/org/apache/qpid/util/LogMonitorTest.java +++ b/java/systests/src/main/java/org/apache/qpid/util/LogMonitorTest.java @@ -155,7 +155,7 @@ public class LogMonitorTest extends TestCase String notLogged = "This text was not logged"; - validateLogDoesNotContainsMessage(_monitor, notLogged); + validateLogDoesNotContainMessage(_monitor, notLogged); } public void testWaitForMessage_Timeout() throws IOException @@ -175,21 +175,20 @@ public class LogMonitorTest extends TestCase _monitor.waitForMessage(message, TIME_OUT)); } - public void testReset() throws IOException + public void testDiscardPoint() throws IOException { - String message = getName() + ": Test Message"; - - Logger.getRootLogger().warn(message); - - validateLogContainsMessage(_monitor, message); + String firstMessage = getName() + ": Test Message1"; + Logger.getRootLogger().warn(firstMessage); - String LOG_RESET_TEXT = "Log Monitor Reset"; + validateLogContainsMessage(_monitor, firstMessage); - validateLogDoesNotContainsMessage(_monitor, LOG_RESET_TEXT); + _monitor.markDiscardPoint(); - _monitor.reset(); + validateLogDoesNotContainMessage(_monitor, firstMessage); - assertEquals("", _monitor.readFile()); + String secondMessage = getName() + ": Test Message2"; + Logger.getRootLogger().warn(secondMessage); + validateLogContainsMessage(_monitor, secondMessage); } public void testRead() throws IOException @@ -214,7 +213,7 @@ public class LogMonitorTest extends TestCase * * @throws IOException if a problems occurs */ - protected void validateLogDoesNotContainsMessage(LogMonitor log, String message) + protected void validateLogDoesNotContainMessage(LogMonitor log, String message) throws IOException { List results = log.findMatches(message); -- cgit v1.2.1