diff options
Diffstat (limited to 'qpid/java/systests/src/test/java/org/apache/qpid/server/logging')
13 files changed, 3978 insertions, 0 deletions
diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AbstractTestLogging.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AbstractTestLogging.java new file mode 100644 index 0000000000..8555d9c751 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AbstractTestLogging.java @@ -0,0 +1,413 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.server.logging.subjects.AbstractTestLogSubject; +import org.apache.qpid.test.utils.QpidBrokerTestCase; +import org.apache.qpid.util.LogMonitor; + +import java.io.FileNotFoundException; +import java.io.IOException; +import java.text.NumberFormat; +import java.util.HashMap; +import java.util.Iterator; +import java.util.LinkedList; +import java.util.List; +import java.util.Locale; + +/** + * Abstract superclass for logging test set up and utility methods. + * + * So named to prevent it being selected itself as a test to run by the test suite. + */ +public class AbstractTestLogging extends QpidBrokerTestCase +{ + public static final long DEFAULT_LOG_WAIT = 2000; + public static final String TEST_LOG_PREFIX = "MESSAGE"; + protected LogMonitor _monitor; + + @Override + public void setUp() throws Exception + { + setLogMessagePrefix(); + + super.setUp(); + _monitor = new LogMonitor(_outputFile); + } + + protected void setLogMessagePrefix() + { + //set the message prefix to facilitate scraping from the munged test output. + setSystemProperty("qpid.logging.prefix", TEST_LOG_PREFIX); + } + + @Override + public void tearDown() throws Exception + { + _monitor.close(); + super.tearDown(); + } + + /** + * assert that the requested log message has not occured + * + * @param log + * + * @throws IOException + */ + public void assertLoggingNotYetOccured(String log) throws IOException + { + // Ensure the alert has not occured yet + assertEquals("Message has already occured:" + log, 0, + findMatches(log).size()); + } + + protected void validateMessageID(String id, String log) + { + assertEquals("Incorrect message", id, getMessageID(log)); + } + + protected String getMessageID(String log) + { + String message = fromMessage(log); + + return message.substring(0, message.indexOf(" ")); + } + + /** + * Return the first channel id from the log string + * ' ch;X' if there is no channel id return -1. + * + * @param log the log string to search. + * + * @return channel id or -1 if no channel id exists. + */ + protected int getChannelID(String log) + { + int start = log.indexOf("ch:") + 3; + + // If we do a check for ] as the boundary we will get cases where log + // is presented with the bounding. If we don't match a ] then we can use + // the end of the string as the boundary. + int end = log.indexOf("]", start); + if (end == -1) + { + end = log.length(); + } + return parseInt(log, start, end); + } + + protected String fromMessage(String log) + {; + int startSubject = log.indexOf("]") + 1; + int start = log.indexOf("]", startSubject) + 1; + + // If we don't have a subject then the second indexOf will return 0 + // in which case we can use the end of the actor as the index. + if (start == 0) + { + start = startSubject; + } + + return log.substring(start).trim(); + } + + /** + * Extract the Subject from the Log Message. + * + * The subject is the second block inclosed in brackets '[ ]'. + * + * If there is no Subject or the second block of brackets '[ ]' cannot be + * identified then an empty String ("") is returned. + * + * The brackets '[ ]' are not included in the returned String. + * + * @param log The log message to process + * + * @return the Subject string or the empty string ("") if the subject can't be identified. + */ + protected String fromSubject(String log) + { + int start = log.indexOf("[") + 1; + // Take the second index + start = log.indexOf("[", start) + 1; + + // There may not be a subject so in that case return nothing. + if (start == 0) + { + return ""; + } + + int end = log.indexOf("]", start); + try + { + return log.substring(start, end); + } + catch (IndexOutOfBoundsException iobe) + { + return ""; + } + } + + /** + * Extract the actor segment from the log message. + * The Actor segment is the first section enclosed in '[ ]'. + * + * No analysis is performed to ensure that the first '[ ]' section of the + * given log is really an Actor segment. + * + * The brackets '[ ]' are not included in the returned String. + * + * @param log the Log Message + * + * @return the Actor segment or "" if unable to locate '[ ]' section + */ + protected String fromActor(String log) + { + int start = log.indexOf("[") + 1; + int end = log.indexOf("]", start); + try + { + return log.substring(start, end).trim(); + } + catch (IndexOutOfBoundsException iobe) + { + return ""; + } + } + + /** + * Return the message String from the given message section + * + * @param log the Message Section + * + * @return the Message String. + */ + protected String getMessageString(String log) + { + // Remove the Log ID from the returned String + int start = log.indexOf(":") + 1; + + return log.substring(start).trim(); + } + + /** + * Given our log message extract the connection ID: + * + * The log string will contain the connectionID identified by 'con:' + * + * So extract the value shown here by X: + * + * 'con:X(' + * + * Extract the value between the ':' and '(' and process it as an Integer + * + * If we are unable to find the right index or process the substring as an + * Integer then return -1. + * + * @param log the log String to process + * + * @return the connection ID or -1. + */ + protected int getConnectionID(String log) + { + int conIDStart = log.indexOf("con:") + 4; + int conIDEnd = log.indexOf("(", conIDStart); + return parseInt(log, conIDStart, conIDEnd); + } + + /** + * Extract the log entry from the raw log line which will contain other + * log4j formatting. + * + * This formatting may impead our testing process so extract the log message + * as we know it to be formatted. + * + * This starts with the string MESSAGE + * + * @param rawLog the raw log + * + * @return the log we are expecting to be printed without the log4j prefixes + */ + protected String getLog(String rawLog) + { + int start = rawLog.indexOf(TEST_LOG_PREFIX); + return rawLog.substring(start); + } + + /** + * Extract the log entry from the result set. Positions are 0-based. + * + * @param results list of log message results to extract from + * @param position position in the list of the message to extract + * @return the message string + */ + protected String getLogMessage(List<String> results, int position) + { + return getLog(results.get(position)); + } + + /** + * Extract the nth-from-last log entry from the result set. + * + * @param results list of log message results to extract from + * @param positionFromEnd position from end of the message list to extract (eg 0 for last) + * @return the message string + */ + protected String getLogMessageFromEnd(List<String> results, int positionFromEnd) + { + int resultSize = results.size(); + return getLogMessage(results, resultSize - 1 - positionFromEnd); + } + + protected List<String> findMatches(String toFind) throws IOException + { + return _monitor.findMatches(toFind); + } + + protected List<String> waitAndFindMatches(String toFind) throws IOException + { + return waitAndFindMatches(toFind, DEFAULT_LOG_WAIT); + } + + protected List<String> waitAndFindMatches(String toFind, long wait) throws IOException + { + return _monitor.waitAndFindMatches(toFind, wait); + } + + public boolean waitForMessage(String message) throws FileNotFoundException, IOException + { + return waitForMessage(message, DEFAULT_LOG_WAIT); + } + + public boolean waitForMessage(String message, long wait) throws FileNotFoundException, IOException + { + return _monitor.waitForMessage(message, wait); + } + + /** + * Given a list of messages that have been pulled out of a log file + * Process the results splitting the log statements in to lists based on the + * actor's connection ID. + * + * So for each log entry extract the Connecition ID from the Actor of the log + * + * Then use that as a key to a HashMap storing the list of log messages for + * that connection. + * + * @param logMessages The list of mixed connection log messages + * + * @return Map indexed by connection id to a list of log messages just for that connection. + */ + protected HashMap<Integer, List<String>> splitResultsOnConnectionID(List<String> logMessages) + { + HashMap<Integer, List<String>> connectionSplitList = new HashMap<Integer, List<String>>(); + + for (String log : logMessages) + { + // Get the connectionID from the Actor in the Message Log. + int cID = getConnectionID(fromActor(getLog(log))); + + List<String> connectionData = connectionSplitList.get(cID); + + // Create the initial List if we don't have one already + if (connectionData == null) + { + connectionData = new LinkedList<String>(); + connectionSplitList.put(cID, connectionData); + } + + // Store the log + connectionData.add(log); + } + + return connectionSplitList; + } + + /** + * Filter the give result set by the specficifed virtualhost. + * This is done using the getSlice to identify the virtualhost (vh) in the + * log message + * + * @param results full list of logs + * @param virtualHostName the virtualhostName to filter on + * + * @return the list of messages only for that virtualhost + */ + protected List<String> filterResultsByVirtualHost(List<String> results, String virtualHostName) + { + List<String> filteredResults = new LinkedList<String>(); + Iterator<String> iterator = results.iterator(); + + while (iterator.hasNext()) + { + String log = iterator.next(); + + if (AbstractTestLogSubject.getSlice("vh", log).equals(virtualHostName)) + { + filteredResults.add(log); + } + } + + return filteredResults; + } + + /** + * Dump the log results. + */ + protected void dumpLogs(List<String> results) throws IOException + { + dumpLogs(results, null); + } + + /** + * Dump the log results or if there are none, the contents of the + * monitored log file if the monitor is non-null. + */ + protected void dumpLogs(List<String> results, LogMonitor monitor) throws IOException + { + System.err.println("Log Dump:"); + for (String log : results) + { + System.err.println(log); + } + + if (results.isEmpty() && monitor != null) + { + System.err.println("Monitored file contents:"); + System.err.println(monitor.readFile()); + } + } + + private int parseInt(final String logSubstring, final int start, final int end) + { + try + { + final NumberFormat format = NumberFormat.getInstance(Locale.getDefault()); + final Number number = format.parse(logSubstring.substring(start, end)); + return number.intValue(); + } + catch (Exception e) + { + return -1; + } + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AccessControlLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AccessControlLoggingTest.java new file mode 100644 index 0000000000..a0188626ee --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AccessControlLoggingTest.java @@ -0,0 +1,177 @@ +/* + * 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.qpid.server.logging; + +import org.apache.qpid.AMQException; +import org.apache.qpid.client.AMQSession; +import org.apache.qpid.framing.AMQShortString; +import org.apache.qpid.protocol.AMQConstant; +import org.apache.qpid.server.security.acl.AbstractACLTestCase; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.Session; +import java.util.List; + +/** + * ACL version 2/3 file testing to verify that ACL actor logging works correctly. + * + * This suite of tests validate that the AccessControl messages occur correctly + * and according to the following format: + * + * <pre> + * ACL-1001 : Allowed Operation Object {PROPERTIES} + * ACL-1002 : Denied Operation Object {PROPERTIES} + * </pre> + */ +public class AccessControlLoggingTest extends AbstractTestLogging +{ + private static final String ACL_LOG_PREFIX = "ACL-"; + private static final String USER = "client"; + private static final String PASS = "guest"; + + public void setUp() throws Exception + { + // Write out ACL for this test + AbstractACLTestCase.writeACLFileUtil(this, "ACL ALLOW client ACCESS VIRTUALHOST", + "ACL ALLOW client CREATE QUEUE name='allow'", + "ACL ALLOW-LOG client CREATE QUEUE name='allow-log'", + "ACL DENY client CREATE QUEUE name='deny'", + "ACL DENY-LOG client CREATE QUEUE name='deny-log'"); + + super.setUp(); + + } + + @Override + public void tearDown() throws Exception + { + try + { + super.tearDown(); + } + catch (JMSException e) + { + //we're throwing this away as it can happen in this test as the state manager remembers exceptions + //that we provoked with authentication failures, where the test passes - we can ignore on con close + } + } + + /** + * Test that {@code allow} ACL entries do not log anything. + */ + public void testAllow() throws Exception + { + Connection conn = getConnection(USER, PASS); + Session sess = conn.createSession(false, Session.AUTO_ACKNOWLEDGE); + conn.start(); + ((AMQSession<?, ?>) sess).createQueue(new AMQShortString("allow"), false, false, false); + + List<String> matches = findMatches(ACL_LOG_PREFIX); + + assertTrue("Should be no ACL log messages", matches.isEmpty()); + } + + /** + * Test that {@code allow-log} ACL entries log correctly. + */ + public void testAllowLog() throws Exception + { + Connection conn = getConnection(USER, PASS); + Session sess = conn.createSession(false, Session.AUTO_ACKNOWLEDGE); + conn.start(); + ((AMQSession<?, ?>) sess).createQueue(new AMQShortString("allow-log"), false, false, false); + + List<String> matches = findMatches(ACL_LOG_PREFIX); + + assertEquals("Should only be one ACL log message", 1, matches.size()); + + String log = getLogMessage(matches, 0); + String actor = fromActor(log); + String subject = fromSubject(log); + String message = getMessageString(fromMessage(log)); + + validateMessageID(ACL_LOG_PREFIX + 1001, log); + + assertTrue("Actor " + actor + " should contain the user identity: " + USER, actor.contains(USER)); + assertTrue("Subject should be empty", subject.length() == 0); + assertTrue("Message should start with 'Allowed'", message.startsWith("Allowed")); + assertTrue("Message should contain 'Create Queue'", message.contains("Create Queue")); + assertTrue("Message should have contained the queue name", message.contains("allow-log")); + } + + /** + * Test that {@code deny-log} ACL entries log correctly. + */ + public void testDenyLog() throws Exception + { + Connection conn = getConnection(USER, PASS); + Session sess = conn.createSession(false, Session.AUTO_ACKNOWLEDGE); + conn.start(); + try { + ((AMQSession<?, ?>) sess).createQueue(new AMQShortString("deny-log"), false, false, false); + fail("Should have denied queue creation"); + } + catch (AMQException amqe) + { + // Denied, so exception thrown + assertEquals("Expected ACCESS_REFUSED error code", AMQConstant.ACCESS_REFUSED, amqe.getErrorCode()); + } + + List<String> matches = findMatches(ACL_LOG_PREFIX); + + assertEquals("Should only be one ACL log message", 1, matches.size()); + + String log = getLogMessage(matches, 0); + String actor = fromActor(log); + String subject = fromSubject(log); + String message = getMessageString(fromMessage(log)); + + validateMessageID(ACL_LOG_PREFIX + 1002, log); + + assertTrue("Actor " + actor + " should contain the user identity: " + USER, actor.contains(USER)); + assertTrue("Subject should be empty", subject.length() == 0); + assertTrue("Message should start with 'Denied'", message.startsWith("Denied")); + assertTrue("Message should contain 'Create Queue'", message.contains("Create Queue")); + assertTrue("Message should have contained the queue name", message.contains("deny-log")); + } + + /** + * Test that {@code deny} ACL entries do not log anything. + */ + public void testDeny() throws Exception + { + Connection conn = getConnection(USER, PASS); + Session sess = conn.createSession(false, Session.AUTO_ACKNOWLEDGE); + conn.start(); + try { + ((AMQSession<?, ?>) sess).createQueue(new AMQShortString("deny"), false, false, false); + fail("Should have denied queue creation"); + } + catch (AMQException amqe) + { + // Denied, so exception thrown + assertEquals("Expected ACCESS_REFUSED error code", AMQConstant.ACCESS_REFUSED, amqe.getErrorCode()); + } + + List<String> matches = findMatches(ACL_LOG_PREFIX); + + assertTrue("Should be no ACL log messages", matches.isEmpty()); + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AlertingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AlertingTest.java new file mode 100644 index 0000000000..336dedb422 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/AlertingTest.java @@ -0,0 +1,196 @@ +/* +* +* 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.qpid.server.logging; + +import java.util.Collections; +import java.util.HashMap; +import java.util.Map; + +import javax.jms.Connection; +import javax.jms.Queue; +import javax.jms.Session; + +import org.apache.qpid.client.AMQDestination; +import org.apache.qpid.client.AMQSession; +import org.apache.qpid.server.management.plugin.HttpManagement; +import org.apache.qpid.server.model.AuthenticationProvider; +import org.apache.qpid.server.model.Plugin; +import org.apache.qpid.server.model.Port; +import org.apache.qpid.server.security.auth.manager.AnonymousAuthenticationManager; +import org.apache.qpid.systest.rest.RestTestHelper; +import org.apache.qpid.test.utils.TestBrokerConfiguration; + +public class AlertingTest extends AbstractTestLogging +{ + + private Session _session; + private Connection _connection; + private Queue _destination; + private int _numMessages; + + private static final int ALERT_LOG_WAIT_PERIOD = 5000; + private static final String MESSAGE_COUNT_ALERT = "MESSAGE_COUNT_ALERT"; + + public void setUp() throws Exception + { + _numMessages = 50; + setTestSystemProperty("virtualhost.housekeepingCheckPeriod", String.valueOf(ALERT_LOG_WAIT_PERIOD)); + setTestSystemProperty("queue.alertThresholdQueueDepthMessages", String.valueOf(_numMessages)); + + // Then we do the normal setup stuff like starting the broker, getting a connection etc. + super.setUp(); + + setupConnection(); + } + + /** + * Create a new connection and ensure that our destination queue is created + * and bound. + * + * Note that the tests here that restart the broker rely on persistence. + * However, the queue creation here is transient. So the queue will not be + * rebound on restart. Hence the consumer creation here rather than just the + * once. + * + * The persistent messages will recreate the queue but not bind it (as it + * was not a durable queue) However, the consumer creation here will ensure + * that the queue is correctly bound and can receive new messages. + * + * @throws Exception + */ + private void setupConnection() + throws Exception + { + _connection = getConnection(); + _session = _connection.createSession(true, Session.SESSION_TRANSACTED); + _destination = _session.createQueue(getTestQueueName()); + + // Consumer is only used to actually create the destination + _session.createConsumer(_destination).close(); + } + + /** + * Checks the log file for MESSAGE_COUNT_ALERT, fails() the test if it's not found and + * places the entire contents in the message to help debug cruise control failures. + * + * @throws Exception + */ + private void wasAlertFired() throws Exception + { + if (!waitForMessage(MESSAGE_COUNT_ALERT, ALERT_LOG_WAIT_PERIOD)) + { + StringBuffer message = new StringBuffer("Could not find 'MESSAGE_COUNT_ALERT' in log file: " + _monitor.getMonitoredFile().getAbsolutePath()); + fail(message.toString()); + } + } + + public void testAlertingReallyWorks() throws Exception + { + // Send 5 messages, make sure that the alert was fired properly. + sendMessage(_session, _destination, _numMessages + 1); + _session.commit(); + wasAlertFired(); + } + + public void testAlertingReallyWorksWithRestart() throws Exception + { + sendMessage(_session, _destination, _numMessages + 1); + _session.commit(); + _connection.close(); + stopBroker(); + + // Rest the monitoring clearing the current output file. + _monitor.markDiscardPoint(); + startBroker(); + wasAlertFired(); + } + + /** + * Test that if the alert value is change from the previous value we can + * still get alerts. + * + * Test sends two messages to the broker then restarts the broker with new + * configuration. + * + * Validates that we only have two messages on the queue and then sends + * enough messages to trigger the alert. + * + * The alert is then validate. + * + * + * @throws Exception + */ + public void testAlertingReallyWorksWithChanges() throws Exception + { + // send some messages and nuke the logs + sendMessage(_session, _destination, 2); + _session.commit(); + // To prevent any failover/retry/connection dropped errors + _connection.close(); + + stopBroker(); + + _monitor.markDiscardPoint(); + + RestTestHelper restTestHelper = new RestTestHelper(findFreePort()); + TestBrokerConfiguration config = getBrokerConfiguration(); + config.addHttpManagementConfiguration(); + config.setObjectAttribute(Port.class, TestBrokerConfiguration.ENTRY_NAME_HTTP_PORT, Port.PORT, restTestHelper.getHttpPort()); + config.removeObjectConfiguration(Port.class, TestBrokerConfiguration.ENTRY_NAME_JMX_PORT); + config.removeObjectConfiguration(Port.class, TestBrokerConfiguration.ENTRY_NAME_RMI_PORT); + + Map<String, Object> anonymousProviderAttributes = new HashMap<String, Object>(); + anonymousProviderAttributes.put(AuthenticationProvider.TYPE, AnonymousAuthenticationManager.PROVIDER_TYPE); + anonymousProviderAttributes.put(AuthenticationProvider.NAME, "testAnonymous"); + config.addObjectConfiguration(AuthenticationProvider.class, anonymousProviderAttributes); + + // set password authentication provider on http port for the tests + config.setObjectAttribute(Port.class, TestBrokerConfiguration.ENTRY_NAME_HTTP_PORT, Port.AUTHENTICATION_PROVIDER, + TestBrokerConfiguration.ENTRY_NAME_AUTHENTICATION_PROVIDER); + config.setObjectAttribute(Plugin.class, TestBrokerConfiguration.ENTRY_NAME_HTTP_MANAGEMENT, HttpManagement.HTTP_BASIC_AUTHENTICATION_ENABLED, true); + config.setSaved(false); + restTestHelper.setUsernameAndPassword("webadmin", "webadmin"); + + startBroker(); + + setupConnection(); + + // Validate the queue depth is as expected + long messageCount = ((AMQSession<?, ?>) _session).getQueueDepth((AMQDestination) _destination); + assertEquals("Broker has invalid message count for test", 2, messageCount); + + // Ensure the alert has not occurred yet + assertLoggingNotYetOccured(MESSAGE_COUNT_ALERT); + + // Change max message count to 5, start broker and make sure that that's triggered at the right time + TestBrokerConfiguration brokerConfiguration = getBrokerConfiguration(); + setTestSystemProperty("queue.alertThresholdQueueDepthMessages","5"); + brokerConfiguration.setSaved(false); + + restTestHelper.submitRequest("queue/test/test/" + getTestQueueName(), "PUT", Collections.<String, Object>singletonMap(org.apache.qpid.server.model.Queue.ALERT_THRESHOLD_QUEUE_DEPTH_MESSAGES, 5)); + // Trigger the new value + sendMessage(_session, _destination, 3); + _session.commit(); + + // Validate that the alert occurred. + wasAlertFired(); + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BindingLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BindingLoggingTest.java new file mode 100644 index 0000000000..646c17d1f2 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BindingLoggingTest.java @@ -0,0 +1,227 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.server.logging.subjects.AbstractTestLogSubject; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.Queue; +import javax.jms.Session; +import javax.jms.Topic; +import java.io.IOException; +import java.util.List; + +/** + * Binding + * + * The Binding test suite validates that the follow log messages as specified in the Functional Specification. + * + * This suite of tests validate that the Binding messages occur correctly and according to the following format: + * + * BND-1001 : Create [: Arguments : <key=value>] + * BND-1002 : Deleted + */ +public class BindingLoggingTest extends AbstractTestLogging +{ + + static final String BND_PREFIX = "BND-"; + + private Connection _connection; + private Session _session; + private Queue _queue; + private Topic _topic; + + @Override + public void setUp() throws Exception + { + super.setUp(); + //Ignore broker startup messages + _monitor.markDiscardPoint(); + + _connection = getConnection(); + + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + _queue = _session.createQueue(getName()); + _topic = (Topic) getInitialContext().lookup(TOPIC); + } + + private void validateLogMessage(String log, String messageID, String message, String exchange, String rkey, String queueName) + { + validateMessageID(messageID, log); + + String subject = fromSubject(log); + + assertEquals("Queue not correct.", queueName, + AbstractTestLogSubject.getSlice("qu", subject)); + assertEquals("Routing Key not correct.", rkey, + AbstractTestLogSubject.getSlice("rk", subject)); + assertEquals("Virtualhost not correct.", "/test", + AbstractTestLogSubject.getSlice("vh", subject)); + assertEquals("Exchange not correct.", exchange, + AbstractTestLogSubject.getSlice("ex", subject)); + + assertEquals("Log Message not as expected", message, getMessageString(fromMessage(log))); + } + + /** + * testBindingCreate + * + * Description: + * The binding of a Queue and an Exchange is done via a Binding. When this Binding is created a BND-1001 Create message will be logged. + * Input: + * + * 1. Running Broker + * 2. New Client requests that a Queue is bound to a new exchange. + * Output: + * + * <date> BND-1001 : Create : Arguments : {x-filter-jms-selector=} + * + * Validation Steps: + * 3. The BND ID is correct + * 4. This will be the first message for the given binding + */ + public void testBindingCreate() throws JMSException, IOException + { + _session.createConsumer(_queue).close(); + + List<String> results = waitAndFindMatches(BND_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + String messageID = "BND-1001"; + String queueName = _queue.getQueueName(); + String exchange = "direct/amq.direct"; + String message = "Create"; + validateLogMessage(getLogMessage(results, 0), messageID, message, exchange, queueName, queueName); + } + + /** + * Description: + * A Binding can be made with a set of arguments. When this occurs we logged the key,value pairs as part of the Binding log message. When the subscriber with a JMS Selector consumes from an exclusive queue such as a topic. The binding is made with the JMS Selector as an argument. + * Input: + * + * 1. Running Broker + * 2. Java Client consumes from a topic with a JMS selector. + * Output: + * + * <date> BND-1001 : Create : Arguments : {x-filter-jms-selector=<value>} + * + * Validation Steps: + * 3. The BND ID is correct + * 4. The JMS Selector argument is present in the message + * 5. This will be the first message for the given binding + */ + public void testBindingCreateWithArguments() throws JMSException, IOException + { + final String SELECTOR = "Selector='True'"; + + _session.createDurableSubscriber(_topic, getName(), SELECTOR, false).close(); + + List<String> results = waitAndFindMatches(BND_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + String messageID = "BND-1001"; + + // Perform full testing on the binding + String message = getMessageString(fromMessage(getLogMessage(results, 0))); + + validateLogMessage(getLogMessage(results, 0), messageID, message, + "topic/amq.topic", "topic", "clientid:" + getName()); + + assertTrue("JMSSelector not identified in binding:"+message, message.contains("jms-selector")); + assertTrue("Selector not part of binding.:"+message, message.contains(SELECTOR)); + + } + + /** + * Description: + * Bindings can be deleted so that a queue can be rebound with a different set of values. + * Input: + * + * 1. Running Broker + * 2. AMQP UnBind Request is made + * Output: + * + * <date> BND-1002 : Deleted + * + * Validation Steps: + * 3. The BND ID is correct + * 4. There must have been a BND-1001 Create message first. + * 5. This will be the last message for the given binding + */ + public void testBindingDelete() throws JMSException, IOException + { + //Closing a consumer on a temporary queue will cause it to autodelete + // and so unbind. + _session.createConsumer(_session.createTemporaryQueue()).close(); + + if(isBroker010()) + { + //auto-delete is at session close for 0-10 + _session.close(); + } + + //wait for the deletion messages to be logged + waitForMessage("BND-1002"); + + //gather all the BND messages + List<String> results = waitAndFindMatches(BND_PREFIX); + + // We will have two binds as we bind all queues to the default exchange + assertEquals("Result not as expected." + results, 2, results.size()); + + + String messageID = "BND-1001"; + String message = "Create"; + + String log = getLogMessage(results, 0); + validateMessageID(messageID, log); + assertEquals("Log Message not as expected", message, getMessageString(fromMessage(log))); + + String DIRECT = "direct/amq.direct"; + + messageID = "BND-1002"; + message = "Deleted"; + + log = getLogMessage(results, 1); + validateMessageID(messageID, log); + + String subject = fromSubject(log); + + validateBindingDeleteArguments(subject, "/test"); + + assertEquals("Log Message not as expected", message, getMessageString(fromMessage(log))); + + } + + private void validateBindingDeleteArguments(String subject, String vhostName) + { + String routingKey = AbstractTestLogSubject.getSlice("rk", subject); + + assertTrue("Routing Key does not start with TempQueue:"+routingKey, + routingKey.startsWith("TempQueue")); + assertEquals("Virtualhost not correct.", vhostName, + AbstractTestLogSubject.getSlice("vh", subject)); + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BrokerLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BrokerLoggingTest.java new file mode 100644 index 0000000000..4952c4e10e --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/BrokerLoggingTest.java @@ -0,0 +1,1035 @@ +/* +* +* 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.qpid.server.logging; + +import junit.framework.AssertionFailedError; + +import org.apache.qpid.server.BrokerOptions; +import org.apache.qpid.server.model.Port; +import org.apache.qpid.server.model.Transport; +import org.apache.qpid.test.utils.TestBrokerConfiguration; +import org.apache.qpid.transport.ConnectionException; +import org.apache.qpid.util.LogMonitor; + +import java.io.IOException; +import java.net.Socket; +import java.util.Collections; +import java.util.HashMap; +import java.util.List; +import java.util.Map; +import java.util.regex.Matcher; +import java.util.regex.Pattern; + +/** + * Broker Test Suite + * + * The Broker test suite validates that the follow log messages as specified in the Functional Specification. + * + * BRK-1001 : Startup : Version: <Version> Build: <Build> + * BRK-1002 : Starting : Listening on <Transport> port <Port> + * BRK-1003 : Shutting down : <Transport> port <Port> + * BRK-1004 : Ready + * BRK-1005 : Stopped + * BRK-1006 : Using configuration : <path> + * BRK-1007 : Using logging configuration : <path> + * + * These messages should only occur during startup. The tests need to verify the order of messages. In the case of the BRK-1002 and BRK-1003 the respective ports should only be available between the two log messages. + */ +public class BrokerLoggingTest extends AbstractTestLogging +{ + private static final String BROKER_MESSAGE_LOG_REG_EXP = ".*\\[\\w*\\] (BRK\\-\\d*) .*"; + private static final Pattern BROKER_MESSAGE_LOG_PATTERN = Pattern.compile(BROKER_MESSAGE_LOG_REG_EXP); + private static final String BRK_LOG_PREFIX = "BRK-"; + + public void setUp() throws Exception + { + setLogMessagePrefix(); + + // We either do this here or have a null check in tearDown. + // As when this test is run against profiles other than java it will NPE + _monitor = new LogMonitor(_outputFile); + //We explicitly do not call super.setUp as starting up the broker is + //part of the test case. + } + + /** + * Description: + * On startup the broker must report the active configuration file. The + * logging system must output this so that we can know what configuration + * is being used for this broker instance. + * + * Input: + * The value of -c specified on the command line. + * Output: + * <date> MESSAGE BRK-1006 : Using configuration : <config file> + * Constraints: + * This MUST BE the first BRK log message. + * + * Validation Steps: + * 1. This is first BRK log message. + * 2. The BRK ID is correct + * 3. The config file is the full path to the file specified on + * the commandline. + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupConfiguration() throws Exception + { + String TESTID="BRK-1006"; + + if (isJavaBroker()) + { + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + + String configFilePath = getConfigPath(); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + List<String> results = waitAndFindMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + String log = getLogMessage(results, 0); + + //1 + validateMessageID(TESTID, log); + + //2 + results = findMatches(TESTID); + assertEquals("More than one configuration message found.", + 1, results.size()); + + //3 + assertTrue("Config file details not correctly logged, got " + + log + " but expected it to end with " + configFilePath, + log.endsWith(configFilePath)); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + private String getConfigPath() + { + return getPathRelativeToWorkingDirectory(getTestConfigFile(DEFAULT_PORT)); + } + + /** + * Description: + * On startup the broker must report correctly report the log4j file in use. This is important as it can help diagnose why logging messages are not being reported. + * Input: + * No custom -l value should be provided on the command line so that the default value is correctly reported. + * Output: + * + * <date> MESSAGE BRK-1007 : Using logging configuration : <$QPID_HOME>/etc/log4j.xml + * + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs before the BRK-1001 startup message. + * 3. The log4j file is the full path to the file specified on the commandline. + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupDefaultLog4j() throws Exception + { + if (isJavaBroker() && isExternalBroker() && !isInternalBroker()) + { + String TESTID = "BRK-1007"; + + _brokerCommandHelper.removeBrokerCommandLog4JFile(); + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + // Ensure broker has fully started up. + getConnection(); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + List<String> results = waitAndFindMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + for (String rawLog : results) + { + // We don't care about messages after we have our log config + if (validation) + { + break; + } + + String log = getLog(rawLog); + + // Ensure we do not have a BRK-1001 message before + if (!getMessageID(log).equals(TESTID)) + { + assertFalse(getMessageID(log).equals("BRK-1001")); + continue; + } + + //1 + validateMessageID(TESTID, log); + + //2 + //There will be 1 copy of this startup message (via SystemOut) + assertEquals("Unexpected log4j configuration message count.", + 1, findMatches(TESTID).size()); + + //3 + String defaultLog4j = System.getProperty(QPID_HOME) + "/" + BrokerOptions.DEFAULT_LOG_CONFIG_FILE; + assertTrue("Log4j file(" + defaultLog4j + ") details not correctly logged:" + getMessageString(log), + getMessageString(log).endsWith(defaultLog4j)); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * On startup the broker must report correctly report the log4j file in use. This is important as it can help diagnose why logging messages are not being reported. The broker must also be capable of correctly recognising the command line property to specify the custom logging configuration. + * Input: + * The value of -l specified on the command line. + * Output: + * + * <date> MESSAGE BRK-1007 : Using logging configuration : <log4j file> + * + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This should occur before the BRK-1001 : Startup message + * 3. The log4j file is the full path to the file specified on the commandline. + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupCustomLog4j() throws Exception + { + // This logging startup code only occurs when you run a Java broker + if (isJavaBroker()) + { + String customLog4j = getBrokerCommandLog4JFile().getAbsolutePath(); + + String TESTID = "BRK-1007"; + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + + // Ensure broker has fully started up. + getConnection(); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + List<String> results = waitAndFindMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + for (String rawLog : results) + { + // We don't care about messages after we have our log config + if (validation) + { + break; + } + String log = getLog(rawLog); + + // Ensure we do not have a BRK-1001 message before + if (!getMessageID(log).equals(TESTID)) + { + assertFalse(getMessageID(log).equals("BRK-1001")); + continue; + } + + //1 + validateMessageID(TESTID, log); + + //2 + //There will be 1 copy of this startup message (via SystemOut) + assertEquals("Unexpected log4j configuration message count.", + 1, findMatches(TESTID).size()); + + //3 + String messageString = getMessageString(log); + assertTrue("Log4j file details not correctly logged. Message '" + + messageString + "' should contain '" +customLog4j + "'", + messageString.endsWith(customLog4j)); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: On startup the broker reports the broker version number and svn build revision. This information is retrieved from the resource 'qpidversion.properties' which is located via the classloader. + * Input: The 'qpidversion.properties' file located on the classpath. + * Output: + * + * <date> MESSAGE BRK-1001 : Startup : qpid Version: 0.6 Build: 767150 + * + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs before any BRK-1002 listening messages are reported. + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupStartup() throws Exception + { + // This logging startup code only occurs when you run a Java broker, + // that broker must be started via Main so not an InVM broker. + if (isJavaBroker()) + { + String TESTID = "BRK-1001"; + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + // Retrieve all BRK- log messages so we can check for an erroneous + // BRK-1002 message. + List<String> results = findMatches(BRK_LOG_PREFIX); + + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + for (String rawLog : results) + { + if (validation) + { + //Stop checking once we have got to our startup test + break; + } + String log = getLog(rawLog); + + // Ensure we do not have a BRK-1002 message + if (!getMessageID(log).equals(TESTID)) + { + assertFalse(getMessageID(log).equals("BRK-1002")); + continue; + } + + //1 + validateMessageID(TESTID, log); + + //2 + //There will be 2 copies of the startup message (one via SystemOut, and one via Log4J) + assertEquals("Unexpected startup message count", + 2, findMatches(TESTID).size()); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * On startup the broker may listen on a number of ports and protocols. Each of these must be reported as they are made available. + * Input: + * The default configuration with no SSL + * Output: + * + * <date> MESSAGE BRK-1002 : Starting : Listening on TCP port 5672 + * + * Constraints: + * Additional broker configuration will occur between the Startup(BRK-1001) and Starting(BRK-1002) messages depending on what VirtualHosts are configured. + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs after the BRK-1001 startup message + * 3. Using the default configuration a single BRK-1002 will be printed showing values TCP / 5672 + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupListeningTCPDefault() throws Exception + { + if (isJavaBroker()) + { + String TESTID = "BRK-1002"; + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + // Ensure broker has fully started up. + getConnection(); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + // Retrieve all BRK- log messages so we can check for an erroneous + // BRK-1002 message. + List<String> results = findMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + boolean foundBRK1001 = false; + for (String rawLog : results) + { + String log = getLog(rawLog); + + // using custom method to get id as getMessageId() fails to correctly identify id + // because of using brackets for protocols + String id = getBrokerLogId(log); + // Ensure we do not have a BRK-1002 message + if (!id.equals(TESTID)) + { + if (id.equals("BRK-1001")) + { + foundBRK1001 = true; + } + continue; + } + + assertTrue("BRK-1001 not logged before this message", foundBRK1001); + + //1 + assertEquals("Incorrect message", TESTID, id); + + //2 + //There will be 2 copies of the startup message (one via SystemOut, and one via Log4J) + assertEquals("Unexpected listen message count", + 2, findMatches(TESTID).size()); + + //3 + String message = getMessageString(log); + assertTrue("Expected Listen log not correct" + message, + message.endsWith("Listening on TCP port " + getPort())); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + private String getBrokerLogId(String log) + { + Matcher m = BROKER_MESSAGE_LOG_PATTERN.matcher(log); + if (m.matches()) + { + return m.group(1); + } + return getMessageID(log); + } + + /** + * Description: + * On startup the broker may listen on a number of ports and protocols. Each of these must be reported as they are made available. + * Input: + * The default configuration with SSL enabled + * Output: + * + * <date> MESSAGE BRK-1002 : Starting : Listening on TCP port 5672 + * <date> MESSAGE BRK-1002 : Starting : Listening on TCP/SSL port 8672 + * + * Constraints: + * Additional broker configuration will occur between the Startup(BRK-1001) and Starting(BRK-1002) messages depending on what VirtualHosts are configured. + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs after the BRK-1001 startup message + * 3. With SSL enabled in the configuration two BRK-1002 will be printed (order is not specified) + * 1. One showing values [TCP] 5672 + * 2. One showing values [SSL] 5671 + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupListeningTCPSSL() throws Exception + { + if (isJavaBroker()) + { + String TESTID = "BRK-1002"; + + // Enable SSL on the connection + Map<String, Object> sslPortAttributes = new HashMap<String, Object>(); + sslPortAttributes.put(Port.TRANSPORTS, Collections.singleton(Transport.SSL)); + sslPortAttributes.put(Port.PORT, DEFAULT_SSL_PORT); + sslPortAttributes.put(Port.NAME, TestBrokerConfiguration.ENTRY_NAME_SSL_PORT); + sslPortAttributes.put(Port.AUTHENTICATION_PROVIDER, TestBrokerConfiguration.ENTRY_NAME_AUTHENTICATION_PROVIDER); + sslPortAttributes.put(Port.KEY_STORE, TestBrokerConfiguration.ENTRY_NAME_SSL_KEYSTORE); + getBrokerConfiguration().addObjectConfiguration(Port.class, sslPortAttributes); + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + // Ensure broker has fully started up. + getConnection(); + + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + // Retrieve all BRK- log messages so we can check for an erroneous + // BRK-1002 message. + List<String> results = findMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + boolean foundBRK1001 = false; + for (String rawLog : results) + { + String log = getLog(rawLog); + + String id = getBrokerLogId(log); + // Ensure we do not have a BRK-1002 message + if (!id.equals(TESTID)) + { + if (id.equals("BRK-1001")) + { + foundBRK1001 = true; + } + continue; + } + + assertTrue("BRK-1001 not logged before this message", foundBRK1001); + + //1 + assertEquals("Incorrect message", TESTID, id); + + //2 + //There will be 4 copies of the startup message (two via SystemOut, and two via Log4J) + List<String> listenMessages = findMatches(TESTID); + assertEquals("Four listen messages should be found.", + 4, listenMessages .size()); + + int tcpStarted = 0; + int sslStarted = 0; + + for (String message : listenMessages) + { + if (message.endsWith("Listening on TCP port " + getPort())) + { + tcpStarted++; + } + if (message.endsWith("Listening on SSL port " + DEFAULT_SSL_PORT)) + { + sslStarted++; + } + } + + assertEquals("Unexpected number of logs 'Listening on TCP port'", 2, tcpStarted); + assertEquals("Unexpected number of logs 'Listening on SSL port'", 2, sslStarted); + + //4 Test ports open + testSocketOpen(getPort()); + testSocketOpen(DEFAULT_SSL_PORT); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * The final message the broker will print when it has performed all initialisation and listener startups will be to log the BRK-1004 Ready message + * Input: + * No input, all successful broker startups will show BRK-1004 messages. + * Output: + * + * 2009-07-09 15:50:20 +0100 MESSAGE BRK-1004 : Qpid Broker Ready + * + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs after the BRK-1001 startup message + * 3. This must be the last message the broker prints after startup. Currently, if there is no further interaction with the broker then there should be no more logging. + * + * @throws Exception caused by broker startup + */ + public void testBrokerStartupReady() throws Exception + { + if (isJavaBroker()) + { + String TESTID = "BRK-1004"; + + startBroker(); + + //Ensure the broker has fully started up. + getConnection(); + // Ensure we wait for TESTID to be logged + waitAndFindMatches(TESTID); + + // Retrieve all BRK- log messages so we can check for an erroneous + // BRK-1001 message. + List<String> results = findMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validationComplete = false; + boolean foundBRK1001 = false; + + for (int i=0; i < results.size(); i++) + { + String rawLog = results.get(i); + String log = getLog(rawLog); + + // Ensure we do not have a BRK-1001 message + if (!getMessageID(log).equals(TESTID)) + { + if (getMessageID(log).equals("BRK-1001")) + { + foundBRK1001 = true; + } + continue; + } + + assertTrue("BRK-1001 not logged before this message", foundBRK1001); + + //1 + validateMessageID(TESTID, log); + + //2 + assertEquals("Ready message not present", "Qpid Broker Ready", getMessageString(log)); + + //There will be 2 copies of the startup message (one via SystemOut, and one via Log4J) + assertEquals("Unexpected ready message count", + 2, findMatches(TESTID).size()); + assertEquals("The ready messages should have been the last 2 messages", results.size() - 2, i); + + validationComplete = true; + break; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validationComplete); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * On startup the broker may listen on a number of ports and protocols. Each of these must then report a shutting down message as they stop listening. + * Input: + * The default configuration with no SSL + * Output: + * + * <date> MESSAGE BRK-1003 : Shutting down : TCP port 5672 + * + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. Only TCP is reported with the default configuration with no SSL. + * 3. The default port is correct + * 4. The port is not accessible after this message + * + * @throws Exception caused by broker startup + */ + public void testBrokerShutdownListeningTCPDefault() throws Exception + { + if (isJavaBroker() && isInternalBroker()) + { + String TESTID = "BRK-1003"; + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + stopBroker(); + + //Give broker time to shutdown and flush log + checkSocketClosed(getPort()); + + List<String> results = waitAndFindMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + boolean foundBRK1001 = false; + for (String rawLog : results) + { + String log = getLog(rawLog); + + // Ensure we do not have a BRK-1002 message + if (!getMessageID(log).equals(TESTID)) + { + if (getMessageID(log).equals("BRK-1001")) + { + foundBRK1001 = true; + } + continue; + } + + assertTrue("BRK-1001 not logged before this message", foundBRK1001); + + //1 + validateMessageID(TESTID, log); + + //2 + assertEquals("More than one listen message found.", + 1, findMatches(TESTID).size()); + + //3 + String message = getMessageString(log); + assertTrue("Expected shutdown log not correct" + message, + message.endsWith("TCP port " + getPort())); + + //4 + checkSocketClosed(getPort()); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * On startup the broker may listen on a number of ports and protocols. Each of these must be reported as they are made available. + * Input: + * The default configuration with SSL enabled + * Output: + * + * <date> MESSAGE BRK-1002 : Starting : Listening on TCP port 5672 + * <date> MESSAGE BRK-1002 : Starting : Listening on TCP/SSL port 8672 + * + * Constraints: + * Additional broker configuration will occur between the Startup(BRK-1001) and Starting(BRK-1002) messages depending on what VirtualHosts are configured. + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This occurs after the BRK-1001 startup message + * 3. With SSL enabled in the configuration two BRK-1002 will be printed (order is not specified) + * 1. One showing values TCP / 5672 + * 2. One showing values TCP/SSL / 5672 + * + * @throws Exception caused by broker startup + */ + public void testBrokerShutdownListeningTCPSSL() throws Exception + { + if (isJavaBroker() && isInternalBroker()) + { + String TESTID = "BRK-1003"; + + // Enable SSL on the connection + Map<String, Object> sslPortAttributes = new HashMap<String, Object>(); + sslPortAttributes.put(Port.TRANSPORTS, Collections.singleton(Transport.SSL)); + sslPortAttributes.put(Port.PORT, DEFAULT_SSL_PORT); + sslPortAttributes.put(Port.NAME, TestBrokerConfiguration.ENTRY_NAME_SSL_PORT); + sslPortAttributes.put(Port.AUTHENTICATION_PROVIDER, TestBrokerConfiguration.ENTRY_NAME_AUTHENTICATION_PROVIDER); + sslPortAttributes.put(Port.KEY_STORE, TestBrokerConfiguration.ENTRY_NAME_SSL_KEYSTORE); + getBrokerConfiguration().addObjectConfiguration(Port.class, sslPortAttributes); + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + +// //Clear any startup messages as we don't need them for validation +// _monitor.reset(); + //Stop the broker to get the log messages for testing + stopBroker(); + + //Give broker time to shutdown and flush log + checkSocketClosed(getPort()); + + List<String> results = waitAndFindMatches(TESTID); + try + { + // Validation + + assertTrue(TESTID + " messages not logged", results.size() > 0); + + String log = getLog(results.get(0)); + + //1 + validateMessageID(TESTID, log); + + //2 + List<String> listenMessages = findMatches(TESTID); + assertEquals("Two shutdown messages should be found.", + 2, listenMessages.size()); + + int tcpShuttingDown = 0; + int sslShuttingDown = 0; + + for (String m : listenMessages) + { + if (m.endsWith("Shutting down : TCP port " + getPort())) + { + tcpShuttingDown++; + } + if (m.endsWith("Shutting down : SSL port " + DEFAULT_SSL_PORT)) + { + sslShuttingDown++; + } + } + + assertEquals("Unexpected number of logs 'Shutting down : TCP port'", 1, tcpShuttingDown); + assertEquals("Unexpected number of logs 'Shutting down : SSL port'", 1, sslShuttingDown); + + //4 + //Test Port closed + checkSocketClosed(getPort()); + //Test SSL Port closed + checkSocketClosed(DEFAULT_SSL_PORT); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Description: + * Input: + * No input, all clean broker shutdowns will show BRK-1005 messages. + * Output: + * + * <date> MESSAGE BRK-1005 : Stopped + * + * Constraints: + * This is the LAST message the broker will log. + * Validation Steps: + * + * 1. The BRK ID is correct + * 2. This is the last message the broker will log. + * + * @throws Exception caused by broker startup + */ + public void testBrokerShutdownStopped() throws Exception + { + if (isJavaBroker() && isInternalBroker()) + { + String TESTID = "BRK-1005"; + + startBroker(); + + // Now we can create the monitor as _outputFile will now be defined + _monitor = new LogMonitor(_outputFile); + + getConnection().close(); + + stopBroker(); + + // Ensure the broker has shutdown before retreving results + checkSocketClosed(getPort()); + + waitAndFindMatches(TESTID); + + List<String> results = waitAndFindMatches(BRK_LOG_PREFIX); + try + { + // Validation + + assertTrue("BRKer message not logged", results.size() > 0); + + boolean validation = false; + for (String rawLog : results) + { + assertFalse("More broker log statements present after ready message", validation); + String log = getLog(rawLog); + + // Ignore all logs until we get to the test id. + if (!getMessageID(log).equals(TESTID)) + { + continue; + } + + //1 + validateMessageID(TESTID, log); + + //2 + assertEquals("More than one ready message found.", + 1, findMatches(TESTID).size()); + + //3 + assertEquals("Stopped message not present", "Stopped", getMessageString(log)); + + validation = true; + } + + assertTrue("Validation not performed: " + TESTID + " not logged", validation); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + } + + /** + * Test that a socket on the given port is closed. + * + * Does this by attempting to connect to the port and expecting a + * ConnectionRefused IOException or a ConnectionException + * + * @param port the port number + */ + private void checkSocketClosed(int port) + { + try + { + Socket socket = new Socket((String) null, port); + fail("Socket not closed on port:" + port); + } + catch (ConnectionException e) + { + //normal path + } + catch (IOException e) + { + if (!e.getMessage().startsWith("Connection refused")) + { + fail("Socket not closed on port:" + port + ":" + e.getMessage()); + // Keep stack trace for diagnosis. + e.printStackTrace(System.err); + } + } + } + + /** + * Test that a socket on the given port is open. + * + * Does this by attempting to connect to the port and expecting a + * The connection to succeed. + * It then closes the socket and expects that to work cleanly. + * + * @param port the port number + */ + private void testSocketOpen(int port) + { + try + { + Socket socket = new Socket((String) null, port); + socket.close(); + } + catch (IOException e) + { + fail("Unable to open and close socket to port:" + port + + ". Due to:" + e.getMessage()); + } + } + +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ChannelLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ChannelLoggingTest.java new file mode 100644 index 0000000000..047151684f --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ChannelLoggingTest.java @@ -0,0 +1,417 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.AMQChannelClosedException; +import org.apache.qpid.AMQException; +import org.apache.qpid.client.AMQConnection; +import org.apache.qpid.client.AMQDestination; +import org.apache.qpid.client.AMQSession; + +import javax.jms.Connection; +import javax.jms.MessageConsumer; +import javax.jms.Queue; +import javax.jms.Session; +import java.util.List; +import java.util.regex.Pattern; + +public class ChannelLoggingTest extends AbstractTestLogging +{ + private static final String CHANNEL_CLOSE_FORCED_MESSAGE_PATTERN = "CHN-1003 : Close : \\d* - .*"; + private static final String CHANNEL_PREFIX = "CHN-"; + + // No explicit startup configuration is required for this test + // so no setUp() method + + /** + * Description: + * When a new Channel (JMS Session) is created this will be logged as a CHN-1001 Create message. The messages will contain the prefetch details about this new Channel. + * Input: + * + * 1. Running Broker + * 2. New JMS Session/Channel creation + * + * Output: + * <date> CHN-1001 : Create + * <date> CHN-1004 : Prefetch Size (bytes) {0,number} : Count {1,number} + * + * Validation Steps: + * 1. The CHN ID is correct + * 2. The prefetch value matches that defined by the requesting client. + * + * @throws Exception - if an error occurs + */ + public void testChannelCreate() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + int PREFETCH = 12; + + // Test that calling session.close gives us the expected output + ((AMQConnection)connection).createSession(false, Session.AUTO_ACKNOWLEDGE,PREFETCH); + + // Wait to ensure that the CHN-1001 message is logged + waitForMessage("CHN-1001"); + + List<String> results = findMatches("CHN-1001"); + + // Validation + assertEquals("CHN-1001 messages not logged", 1, results.size()); + + String log = getLogMessage(results, 0); + // MESSAGE [con:0(guest@anonymous(3273383)/test)/ch:1] CHN-1001 : Create + validateMessageID("CHN-1001", log); + final String fromActor = fromActor(log); + final int channelID = getChannelID(fromActor); + assertEquals("Incorrect Channel in actor:"+fromActor(log), isBroker010()? 0 : 1, channelID); + + if (!isBroker010()) + { + // Wait to ensure that the CHN-1004 message is logged + waitForMessage("CHN-1004"); + + results = findMatches("CHN-1004"); + + // Validation + assertEquals("CHN-1004 messages not logged", 1, results.size()); + log = getLogMessage(results, 0); + // MESSAGE [con:0(guest@anonymous(3273383)/test)/ch:1] CHN-1004 : Prefetch Size (bytes) {0,number} : Count {1,number} + validateMessageID("CHN-1004", log); + assertEquals("Incorrect Channel in actor:"+fromActor(log), 1, getChannelID(fromActor(log))); + assertTrue("Prefetch Count not correct",getMessageString(fromMessage(log)).endsWith("Count "+PREFETCH)); + } + + connection.close(); + } + + /** + * Description: + * The Java Broker implements consumer flow control for all ack modes except + * No-Ack. When a client connects the session's flow is initially set to + * Stopped. Verify this message appears + * + * Input: + * 1. Running broker + * 2. Create consumer + * Output: + * + * <date> CHN-1002 : Flow Stopped + * + * Validation Steps: + * 4. The CHN ID is correct + * + * @throws Exception - if an error occurs + */ + + public void testChannelStartsFlowStopped() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session to fill up + Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + Queue queue = (Queue) getInitialContext().lookup(QUEUE); + MessageConsumer consumer = session.createConsumer(queue); + + connection.start(); + + // Wait to ensure that the CHN-1002 message is logged + waitForMessage("CHN-1002"); + + List<String> results = findMatches(CHANNEL_PREFIX); + + assertTrue("No CHN messages logged", results.size() > 0); + + // The last channel message should be: + // + // INFO - MESSAGE [con:0(guest@anonymous(4205299)/test)/ch:1] [con:0(guest@anonymous(4205299)/test)/ch:1] CHN-1002 : Flow Stopped + + // Verify the last channel message is stopped + validateChannelStart(results, false); + } + + private void validateChannelStart(List<String> results, boolean flowStarted) + { + String log = getLogMessageFromEnd(results, 0); + + String flow = flowStarted ? "Started" : "Stopped"; + validateMessageID("CHN-1002", log); + assertEquals("Message should be Flow " + flow, "Flow " + flow, getMessageString(fromMessage(log))); + } + + /** + * Description: + * The Java Broker implements consumer flow control for all ack modes except + * No-Ack. When the client first attempts to receive a message then the Flow + * status of the Session is set to Started. + * + * Input: + * 1. Running broker + * 2. Create a consumer + * 3. Attempt to receive a message + * Output: + * + * <date> CHN-1002 : Flow Started + * + * Validation Steps: + * 4. The CHN ID is correct + * + * @throws Exception - if an error occurs + */ + + public void testChannelStartConsumerFlowStarted() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session to fill up + Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + Queue queue = (Queue) getInitialContext().lookup(QUEUE); + MessageConsumer consumer = session.createConsumer(queue); + + connection.start(); + + //Call receive to send the Flow On message + consumer.receiveNoWait(); + + //Wait for up to 2 seconds for message to appear + // ignore response as we will use the findMatches afterwards just + // incase it did take more than 2 seconds to log. + _monitor.waitForMessage(CHANNEL_PREFIX, 2000); + + // Wait to ensure that the CHN-1002 message is logged + waitForMessage("CHN-1002"); + + List<String> results = findMatches(CHANNEL_PREFIX); + + assertTrue("No CHN messages logged", results.size() > 0); + + // The last two channel messages(before the close) should be: + // + // INFO [qpid.message] MESSAGE [con:1(guest@/127.0.0.1:49869/test)/ch:1] [con:1(guest@/127.0.0.1:49869/test)/ch:1] CHN-1002 : Flow Stopped + // INFO [qpid.message] MESSAGE [con:1(guest@/127.0.0.1:49869/test)/ch:1] [con:1(guest@/127.0.0.1:49869/test)/ch:1] CHN-1002 : Flow Started + + // Verify the last channel msg is Started. + validateChannelStart(results, true); + } + + /** + * Description: + * When the client gracefully closes the Connection then a CHN-1003 Close + * message will be issued. This must be the last message logged for this + * Channel. + * Input: + * 1. Running Broker + * 2. Connected Client + * 3. Client then requests that the Connection is closed + * Output: + * + * <date> CHN-1003 : Close + * + * Validation Steps: + * 4. The MST ID is correct + * 5. This must be the last message logged for this Channel. + * + * @throws Exception - if an error occurs + */ + public void testChannelCloseViaConnectionClose() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session + connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + // Close the connection to verify the created session closing is logged. + connection.close(); + + // Wait to ensure that the CHN-1003 message is logged + waitForMessage("CHN-1003"); + + List<String> results = findMatches(CHANNEL_PREFIX); + + assertTrue("No CHN messages logged", results.size() > 0); + + // The last two channel messages should be: + // + // INFO - MESSAGE [con:0(guest@anonymous(4205299)/test)/ch:1] [con:0(guest@anonymous(4205299)/test)/ch:1] CHN-1002 : Flow On + + // Verify + validateChannelClose(results); + } + + /** + * Description: + * When the client gracefully closes the Connection then a CHN-1003 Close + * message will be issued. This must be the last message logged for this + * Channel. + * Input: + * 1. Running Broker + * 2. Connected Client + * 3. Client then requests that the Channel is closed + * Output: + * + * <date> CHN-1003 : Close + * + * Validation Steps: + * 4. The MST ID is correct + * 5. This must be the last message logged for this Channel. + * + * @throws Exception - if an error occurs + */ + public void testChannelCloseViaChannelClose() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session and then close it + Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + waitForMessage("CHN-1001"); + + // Wait to ensure that the CHN-1003 message is logged + session.close(); + waitForMessage("CHN-1003"); + + List<String> results = findMatches(CHANNEL_PREFIX); + + assertTrue("No CHN messages logged", results.size() > 0); + + // Verify + validateChannelClose(results); + } + + public void testChannelClosedOnQueueArgumentsMismatch() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session and then close it + Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + waitForMessage("CHN-1001"); + + String testQueueName = getTestQueueName(); + + Queue nonDurableQueue = (Queue) session.createQueue("direct://amq.direct/" + testQueueName + "/" + testQueueName + + "?durable='false'"); + + ((AMQSession<?,?>)session).declareAndBind((AMQDestination)nonDurableQueue); + + Queue durableQueue = (Queue) session.createQueue("direct://amq.direct/" + testQueueName + "/" + testQueueName + + "?durable='true'"); + try + { + ((AMQSession<?,?>)session).declareAndBind((AMQDestination) durableQueue); + fail("Exception not thrown"); + } + catch (AMQChannelClosedException acce) + { + // pass + } + catch (Exception e) + { + fail("Wrong exception thrown " + e); + } + waitForMessage("CHN-1003"); + + List<String> results = findMatches(CHANNEL_PREFIX); + assertTrue("No CHN messages logged", results.size() > 0); + + String closeLog = results.get(results.size() -1); + int closeMessageID = closeLog.indexOf("CHN-1003"); + assertFalse("CHN-1003 is not found", closeMessageID == -1); + + String closeMessage = closeLog.substring(closeMessageID); + assertTrue("Unexpected close channel message :" + closeMessage, Pattern.matches(CHANNEL_CLOSE_FORCED_MESSAGE_PATTERN, closeMessage)); + + session.close(); + connection.close(); + } + + public void testChannelClosedOnExclusiveQueueDeclaredOnDifferentSession() throws Exception + { + assertLoggingNotYetOccured(CHANNEL_PREFIX); + + Connection connection = getConnection(); + + // Create a session and then close it + Session session = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + waitForMessage("CHN-1001"); + + Session session2 = connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + waitForMessage("CHN-1001"); + + String testQueueName = getTestQueueName(); + + Queue queue = (Queue) session.createQueue("direct://amq.direct/" + testQueueName + "/" + testQueueName + + "?exclusive='true'"); + + ((AMQSession<?,?>)session).declareAndBind((AMQDestination)queue); + + try + { + ((AMQSession<?,?>)session2).declareAndBind((AMQDestination) queue); + fail("Exception not thrown"); + } + catch (AMQException acce) + { + // pass + } + catch (Exception e) + { + fail("Wrong exception thrown " + e); + } + waitForMessage("CHN-1003"); + + List<String> results = findMatches(CHANNEL_PREFIX); + assertTrue("No CHN messages logged", results.size() > 0); + + String closeLog = results.get(results.size() -1); + int closeMessageID = closeLog.indexOf("CHN-1003"); + assertFalse("CHN-1003 is not found", closeMessageID == -1); + + String closeMessage = closeLog.substring(closeMessageID); + assertTrue("Unexpected close channel message :" + closeMessage, Pattern.matches(CHANNEL_CLOSE_FORCED_MESSAGE_PATTERN, closeMessage)); + + session.close(); + connection.close(); + } + private void validateChannelClose(List<String> results) + { + String open = getLogMessage(results, 0); + String close = getLogMessageFromEnd(results, 0); + + validateMessageID("CHN-1001", open); + validateMessageID("CHN-1003", close); + assertEquals("Message should be Close", "Close", getMessageString(fromMessage(close))); + assertEquals("Incorrect Channel ID closed", isBroker010()? 0 : 1, getChannelID(fromSubject(close))); + assertEquals("Channel IDs should be the same", getChannelID(fromActor(open)), getChannelID(fromSubject(close))); + assertEquals("Connection IDs should be the same", getConnectionID(fromActor(open)), getConnectionID(fromSubject(close))); + } +}
\ No newline at end of file diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConnectionLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConnectionLoggingTest.java new file mode 100644 index 0000000000..0be1f69948 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConnectionLoggingTest.java @@ -0,0 +1,198 @@ +/* +* +* 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.qpid.server.logging; + +import javax.jms.Connection; + +import org.apache.qpid.common.QpidProperties; + +import java.util.HashMap; +import java.util.List; +import java.util.TreeSet; + +public class ConnectionLoggingTest extends AbstractTestLogging +{ + private static final String CONNECTION_PREFIX = "CON-"; + + // No explicit startup configuration is required for this test + // so no setUp() method + + /** + * Description: + * When a new connection is made to the broker this must be logged. + * + * Input: + * 1. Running Broker + * 2. Connecting client + * Output: + * <date> CON-1001 : Open : Client ID {0}[ : Protocol Version : {1}] <version> + * + * Validation Steps: + * 1. The CON ID is correct + * 2. This is the first CON message for that Connection + * + * @throws Exception - if an error occurs + */ + public void testConnectionOpen() throws Exception + { + assertLoggingNotYetOccured(CONNECTION_PREFIX); + + Connection connection = getConnection(); + String clientid = connection.getClientID(); + + // Wait until opened + waitForMessage("CON-1001"); + + // Close the connection + connection.close(); + + // Wait to ensure that the desired message is logged + waitForMessage("CON-1002"); + + List<String> results = waitAndFindMatches("CON-1001"); + + // MESSAGE [con:1(/127.0.0.1:46927)] CON-1001 : Open + // MESSAGE [con:1(/127.0.0.1:46927)] CON-1001 : Open : Protocol Version : 0-9 + // MESSAGE [con:1(/127.0.0.1:46927)] CON-1001 : Open : Client ID : clientid : Protocol Version : 0-9 : Client Version : 1.2.3_4 + // MESSAGE [con:0(/127.0.0.1:46927)] CON-1002 : Close + + HashMap<Integer, List<String>> connectionData = splitResultsOnConnectionID(results); + + // Get the last Integer from keySet of the ConnectionData + int connectionID = new TreeSet<Integer>(connectionData.keySet()).last(); + + //Use just the data from the last connection for the test + results = connectionData.get(connectionID); + + assertEquals("Unexpected CON-1001 messages count", 3, results.size()); + + String log = getLogMessage(results, 0); + // MESSAGE [con:1(/127.0.0.1:52540)] CON-1001 : Open + //1 & 2 + validateMessageID("CON-1001",log); + + // validate the last three CON-1001 messages. + // MESSAGE [con:1(/127.0.0.1:52540)] CON-1001 : Open : Client ID : clientid : Protocol Version : 0-9 : Client Version : 1.2.3_4 : Client Product : product + validateConnectionOpen(results, 0, true, true, clientid, true, QpidProperties.getReleaseVersion(), true, QpidProperties.getProductName()); + + // MESSAGE [con:1(/127.0.0.1:52540)] CON-1001 : Open : Protocol Version : 0-9 + validateConnectionOpen(results, 1, true, false, null, false, null, false, null); + + // MESSAGE [con:1(/127.0.0.1:52540)] CON-1001 : Open + validateConnectionOpen(results, 2, false, false, null, false, null, false, null); + } + + private void validateConnectionOpen(List<String> results, int positionFromEnd, + boolean protocolVersionPresent, boolean clientIdOptionPresent, String clientIdValue, + boolean clientVersionPresent, String clientVersionValue, boolean clientProductPresent, String clientProductValue) + { + String log = getLogMessageFromEnd(results, positionFromEnd); + + validateMessageID("CON-1001",log); + + assertEquals("unexpected Client ID option state", clientIdOptionPresent, fromMessage(log).contains("Client ID :")); + + if(clientIdOptionPresent && clientIdValue != null) + { + assertTrue("Client ID value is not present: " + clientIdValue, fromMessage(log).contains(clientIdValue)); + } + + assertEquals("unexpected Protocol Version option state", + protocolVersionPresent, fromMessage(log).contains("Protocol Version :")); + //fixme there is no way currently to find out the negotiated protocol version + // The delegate is the versioned class ((AMQConnection)connection)._delegate + + assertEquals("unexpected Client Version option state", clientVersionPresent, fromMessage(log).contains("Client Version :")); + + if(clientVersionPresent && clientVersionValue != null) + { + assertTrue("Client version value is not present: " + clientVersionValue, fromMessage(log).contains(clientVersionValue)); + } + + assertEquals("unexpected Client Product option state", clientVersionPresent, fromMessage(log).contains("Client Product :")); + + if(clientProductPresent && clientProductValue != null) + { + assertTrue("Client product value is not present: " + clientProductValue, fromMessage(log).contains(clientProductValue)); + } + } + + /** + * Description: + * When a connected client closes the connection this will be logged as a CON-1002 message. + * Input: + * + * 1. Running Broker + * 2. Connected Client + * Output: + * + * <date> CON-1002 : Close + * + * Validation Steps: + * 3. The CON ID is correct + * 4. This must be the last CON message for the Connection + * 5. It must be preceded by a CON-1001 for this Connection + */ + public void testConnectionClose() throws Exception + { + assertLoggingNotYetOccured(CONNECTION_PREFIX); + + Connection connection = getConnection(); + + // Wait until opened + waitForMessage("CON-1001"); + + // Close the conneciton + connection.close(); + + // Wait to ensure that the desired message is logged + waitForMessage("CON-1002"); + + List<String> results = findMatches(CONNECTION_PREFIX); + + // Validation + + // We should have at least four messages + assertTrue("CON messages not logged:" + results.size(), results.size() >= 4); + + // Validate Close message occurs + String log = getLogMessageFromEnd(results, 0); + validateMessageID("CON-1002",log); + assertTrue("Message does not end with close:" + log, log.endsWith("Close")); + + // Extract connection ID to validate there is a CON-1001 messasge for it + final String logSubject = fromSubject(log); + int closeConnectionID = getConnectionID(logSubject); + assertTrue("Could not get the connection id from CLOSE message: " + logSubject, closeConnectionID != -1); + + //Previous log message should be the open + log = getLogMessageFromEnd(results, 1); + // MESSAGE [con:1(/127.0.0.1:52540)] CON-1001 : Open : Client ID : clientid : Protocol Version : 0-9 + validateMessageID("CON-1001",log); + + // Extract connection ID to validate it matches the CON-1002 messasge + int openConnectionID = getConnectionID(fromActor(log)); + assertTrue("Could not find connection id in OPEN", openConnectionID != -1); + + // Check connection ids match + assertEquals("Connection IDs do not match", closeConnectionID, openConnectionID); + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConsumerLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConsumerLoggingTest.java new file mode 100644 index 0000000000..f321b4e8e0 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ConsumerLoggingTest.java @@ -0,0 +1,407 @@ +/* + * + * 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.qpid.server.logging; + +import javax.jms.QueueBrowser; +import junit.framework.AssertionFailedError; + +import org.apache.qpid.client.AMQConnection; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.Message; +import javax.jms.MessageConsumer; +import javax.jms.Queue; +import javax.jms.Session; +import javax.jms.Topic; +import java.io.IOException; +import java.util.List; + +/** + * Subscription + * + * The Subscription test suite validates that the follow log messages as specified in the Functional Specification. + * + * This suite of tests validate that the Subscription messages occur correctly and according to the following format: + * + * SUB-1001 : Create : [Durable] [Arguments : <key=value>] + * SUB-1002 : Close + * SUB-1003 : State : <state> + */ +public class ConsumerLoggingTest extends AbstractTestLogging +{ + static final String SUB_PREFIX = "SUB-"; + + private Connection _connection; + private Session _session; + private Queue _queue; + private Topic _topic; + + @Override + public void setUp() throws Exception + { + super.setUp(); + //Remove broker startup logging messages + _monitor.markDiscardPoint(); + + _connection = getConnection(); + + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + _queue = _session.createQueue(getTestQueueName() + "Queue"); + _topic = _session.createTopic(getTestQueueName() + "Topic"); + } + + /** + * Description: + * When a Subscription is created it will be logged. This test validates that Subscribing to a transient queue is correctly logged. + * Input: + * + * 1. Running Broker + * 2. Create a new Subscription to a transient queue/topic. + * Output: 6 + * + * <date> SUB-1001 : Create + * + * Validation Steps: + * 3. The SUB ID is correct + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionCreate() throws JMSException, IOException + { + _session.createConsumer(_queue); + + //Validate + + //Ensure that we wait for the SUB log message + waitAndFindMatches("SUB-1001"); + + List<String> results = findMatches(SUB_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + String log = getLogMessage(results, 0); + + validateMessageID("SUB-1001", log); + + assertEquals("Log Message not as expected", "Create", getMessageString(fromMessage(log))); + } + + /** + * Description: + * The creation of a Durable Subscription, such as a JMS DurableTopicSubscriber will result in an extra Durable tag being included in the Create log message + * Input: + * + * 1. Running Broker + * 2. Creation of a JMS DurableTopicSubiber + * Output: + * + * <date> SUB-1001 : Create : Durable + * + * Validation Steps: + * 3. The SUB ID is correct + * 4. The Durable tag is present in the message + * NOTE: A Subscription is not Durable, the queue it consumes from is. + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionCreateDurable() throws JMSException, IOException + { + _session.createDurableSubscriber(_topic, getName()); + + //Validate + //Ensure that we wait for the SUB log message + waitAndFindMatches("SUB-1001"); + + List<String> results = findMatches(SUB_PREFIX); + + assertEquals("Result set not as expected.", 1, results.size()); + + String log = getLogMessage(results, 0); + + validateMessageID("SUB-1001", log); + + String message = getMessageString(fromMessage(log)); + assertTrue("Durable not on log message:" + message, message.contains("Durable")); + } + + /** + * Description: + * The creation of a Subscriber with a JMS Selector will result in the Argument field being populated. These argument key/value pairs are then shown in the log message. + * Input: + * + * 1. Running Broker + * 2. Subscriber created with a JMS Selector. + * Output: + * + * <date> SUB-1001 : Create : Arguments : <key=value> + * + * Validation Steps: + * 3. The SUB ID is correct + * 4. Argument tag is present in the message + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionCreateWithArguments() throws JMSException, IOException + { + final String SELECTOR = "Selector='True'"; + _session.createConsumer(_queue, SELECTOR); + + //Validate + + //Ensure that we wait for the SUB log message + waitAndFindMatches("SUB-1001"); + + List<String> results = findMatches(SUB_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + String log = getLogMessage(results, 0); + + validateMessageID("SUB-1001", log); + + String message = getMessageString(fromMessage(log)); + assertTrue("Selector not on log message:" + message, message.contains(SELECTOR)); + } + + /** + * Description: + * The final combination of SUB-1001 Create messages involves the creation of a Durable Subscription that also contains a set of Arguments, such as those provided via a JMS Selector. + * Input: + * + * 1. Running Broker + * 2. Java Client creates a Durable Subscription with Selector + * Output: + * + * <date> SUB-1001 : Create : Durable Arguments : <key=value> + * + * Validation Steps: + * 3. The SUB ID is correct + * 4. The tag Durable is present in the message + * 5. The Arguments are present in the message + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionCreateDurableWithArguments() throws JMSException, IOException + { + final String SELECTOR = "Selector='True'"; + _session.createDurableSubscriber(_topic, getName(), SELECTOR, false); + + //Validate + + //Ensure that we wait for the SUB log message + waitAndFindMatches("SUB-1001"); + + List<String> results = findMatches(SUB_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + String log = getLogMessage(results, 0); + + validateMessageID("SUB-1001", log); + + String message = getMessageString(fromMessage(log)); + assertTrue("Durable not on log message:" + message, message.contains("Durable")); + assertTrue("Selector not on log message:" + message, message.contains(SELECTOR)); + } + + /** + * Description: + * When a Subscription is closed it will log this so that it can be correlated with the Create. + * Input: + * + * 1. Running Broker + * 2. Client with a subscription. + * 3. The subscription is then closed. + * Output: + * + * <date> SUB-1002 : Close + * + * Validation Steps: + * 1. The SUB ID is correct + * 2. There must be a SUB-1001 Create message preceding this message + * 3. This must be the last message from the given Subscription + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionClose() throws JMSException, IOException + { + _session.createConsumer(_queue).close(); + + //Validate + //Ensure that we wait for the SUB log message + waitAndFindMatches("SUB-1002"); + + List<String> results = findMatches(SUB_PREFIX); + + //3 + assertEquals("Result set larger than expected.", 2, results.size()); + + // 2 + String log = getLogMessage(results, 0); + validateMessageID("SUB-1001", log); + // 1 + log = getLogMessage(results, 1); + validateMessageID("SUB-1002", log); + + String message = getMessageString(fromMessage(log)); + assertEquals("Log message is not close", "Close", message); + + } + + /** + * Description: + * When a Subscription fills its prefetch it will become suspended. This + * will be logged as a SUB-1003 message. + * Input: + * + * 1. Running broker + * 2. Message Producer to put more data on the queue than the client's prefetch + * 3. Client that ensures that its prefetch becomes full + * Output: + * + * <date> SUB-1003 : State : <state> + * + * Validation Steps: + * 1. The SUB ID is correct + * 2. The state is correct + * + * @throws java.io.IOException - if there is a problem getting the matches + * @throws javax.jms.JMSException - if there is a problem creating the consumer + */ + public void testSubscriptionSuspend() throws Exception, IOException + { + //Close session with large prefetch + _connection.createSession(false, Session.AUTO_ACKNOWLEDGE).close(); + + int PREFETCH = 15; + + //Create new session with small prefetch + _session = ((AMQConnection) _connection).createSession(true, Session.SESSION_TRANSACTED, PREFETCH); + + MessageConsumer consumer = _session.createConsumer(_queue); + + _connection.start(); + + //Start the dispatcher & Unflow the channel. + consumer.receiveNoWait(); + + //Fill the prefetch and two extra so that our receive bellow allows the + // subscription to become active + // Previously we set this to 17 so that it would return to a suspended + // state. However, testing has shown that the state change can occur + // sufficiently quickly that logging does not occur consistently enough + // for testing. + int SEND_COUNT = 16; + sendMessage(_session, _queue, SEND_COUNT); + _session.commit(); + // Retreive the first message, and start the flow of messages + Message msg = consumer.receive(1000); + assertNotNull("First message not retreived", msg); + _session.commit(); + + // Drain the queue to ensure there is time for the ACTIVE log message + // Check that we can received all the messages + int receivedCount = 0; + while (msg != null) + { + receivedCount++; + msg = consumer.receive(1000); + _session.commit(); + } + + //Validate we received all the messages + assertEquals("Not all sent messages received.", SEND_COUNT, receivedCount); + + // Fill the queue again to suspend the consumer + sendMessage(_session, _queue, SEND_COUNT); + _session.commit(); + + //Validate + List<String> results = waitAndFindMatches("SUB-1003"); + + try + { + // Validation expects three messages. + // The Actor can be any one of the following depending on the exactly what is going on on the broker. + // Ideally we would test that we can get all of them but setting up + // the timing to do this in a consistent way is not benefitial. + // Ensuring the State is as expected is sufficient. +// INFO - MESSAGE [vh(/test)/qu(example.queue)] [sub:6(qu(example.queue))] SUB-1003 : State : +// INFO - MESSAGE [con:6(guest@anonymous(26562441)/test)/ch:3] [sub:6(qu(example.queue))] SUB-1003 : State : +// INFO - MESSAGE [sub:6(vh(test)/qu(example.queue))] [sub:6(qu(example.queue))] SUB-1003 : State : + + assertEquals("Result set not expected size:", 3, results.size()); + + // Validate Initial Suspension + String expectedState = "SUSPENDED"; + String log = getLogMessage(results, 0); + validateSubscriptionState(log, expectedState); + + // After being suspended the subscription should become active. + expectedState = "ACTIVE"; + log = getLogMessage(results, 1); + validateSubscriptionState(log, expectedState); + + // Validate that it was re-suspended + expectedState = "SUSPENDED"; + log = getLogMessage(results, 2); + validateSubscriptionState(log, expectedState); + // We only need validate the state. + } + catch (AssertionFailedError afe) + { + System.err.println("Log Dump:"); + for (String log : results) + { + System.err.println(log); + } + throw afe; + } + _connection.close(); + } + + /** + * Validate that the given log statement is a well formatted SUB-1003 + * message. That means the ID and expected state are correct. + * + * @param log the log to test + * @param expectedState the state that should be logged. + */ + private void validateSubscriptionState(String log, String expectedState) + { + validateMessageID("SUB-1003", log); + String logMessage = getMessageString(fromMessage(log)); + assertTrue("Log Message does not start with 'State'" + logMessage, + logMessage.startsWith("State")); + + assertTrue("Log Message does not have expected State of '" + + expectedState + "'" + logMessage, + logMessage.endsWith(expectedState)); + } + +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java new file mode 100644 index 0000000000..dcc1837c5b --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/DurableQueueLoggingTest.java @@ -0,0 +1,311 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.AMQException; +import org.apache.qpid.client.AMQSession; +import org.apache.qpid.framing.AMQShortString; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.Queue; +import javax.jms.Session; +import javax.naming.NamingException; +import java.io.IOException; +import java.util.HashMap; +import java.util.List; +import java.util.Map; + +/** + * The Queue test suite validates that the follow log messages as specified in + * the Functional Specification. + * + * This suite of tests validate that the Queue messages occur correctly and + * according to the following format: + * + * QUE-1001 : Create : [AutoDelete] [Durable|Transient] [Priority:<levels>] [Owner:<name>] + */ +public class DurableQueueLoggingTest extends AbstractTestLogging +{ + protected String DURABLE = "Durable"; + protected String TRANSIENT = "Transient"; + protected boolean _durable; + + protected Connection _connection; + protected Session _session; + private static final String QUEUE_PREFIX = "QUE-"; + private static int PRIORITIES = 6; + + public void setUp() throws Exception + { + super.setUp(); + //Ensure we only have logs from our test + _monitor.markDiscardPoint(); + + _connection = getConnection(); + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + _durable = true; + } + + /** + * Description: + * When a simple transient queue is created then a QUE-1001 create message + * is expected to be logged. + * Input: + * 1. Running broker + * 2. Persistent Queue is created from a client + * Output: + * + * <date> QUE-1001 : Create : Owner: '<name>' Durable + * + * Validation Steps: + * 3. The QUE ID is correct + * 4. The Durable tag is present in the message + * 5. The Owner is as expected + * + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + * @throws java.io.IOException + */ + public void testQueueCreateDurableExclusive() throws NamingException, JMSException, IOException + { + String queueName= getTestQueueName(); + // To force a queue Creation Event we need to create a consumer. + Queue queue = (Queue) _session.createQueue("direct://amq.direct/" + queueName + "/" + queueName + "?durable='" + _durable + "'&exclusive='true'"); + + _session.createConsumer(queue); + + List<String> results = waitForMesssage(); + + String clientID = _connection.getClientID(); + assertNotNull("clientID should not be null", clientID); + + // in 0-8/9/9-1 an exclusive queue will be deleted when the connection is closed, so auto-delete is true. + // in 0-10 an exclusive queue outlasts the creating connection and so is not auto-delete + // the queue only has owner as the client-id in 0-8/9/91 where exclusivity is taken to mean exclusive to the + // client-id in perpetuity. For 0-10 exclusive means exclusive to a session. + validateQueueProperties(results, false, !(isBroker010() || _durable), (_durable && !isBroker010()) ? clientID : null); + } + + /** + * Description: + * When a simple transient queue is created then a QUE-1001 create message + * is expected to be logged. + * Input: + * 1. Running broker + * 2. Persistent Queue is created from a client + * Output: + * + * <date> QUE-1001 : Create : Owner: '<name>' Durable + * + * Validation Steps: + * 3. The QUE ID is correct + * 4. The Durable tag is present in the message + * 5. The Owner is as expected + * + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + * @throws java.io.IOException + */ + public void testQueueCreateDurable() throws NamingException, JMSException, IOException + { + String queueName = getTestQueueName(); + + // To force a queue Creation Event we need to create a consumer. + Queue queue = (Queue) _session.createQueue("direct://amq.direct/" + queueName + "/" + queueName + "?durable='" + _durable + "'"); + + _session.createConsumer(queue); + + List<String> results = waitForMesssage(); + + validateQueueProperties(results, false, false, null); + } + + /** + * Description: + * When a simple transient queue is created then a QUE-1001 create message + * is expected to be logged. + * Input: + * 1. Running broker + * 2. AutoDelete Persistent Queue is created from a client + * Output: + * + * <date> QUE-1001 : Create : Owner: '<name>' AutoDelete Durable + * + * Validation Steps: + * 3. The QUE ID is correct + * 4. The Durable tag is present in the message + * 5. The Owner is as expected + * 6. The AutoDelete tag is present in the message + * + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + * @throws java.io.IOException + */ + public void testQueueCreatePersistentAutoDelete() throws NamingException, JMSException, IOException + { + String queueName = getTestQueueName(); + // To force a queue Creation Event we need to create a consumer. + Queue queue = (Queue) _session.createQueue("direct://amq.direct/"+queueName+"/"+queueName+"?durable='"+_durable+"'&autodelete='true'"); + + _session.createConsumer(queue); + + List<String> results = waitForMesssage(); + + validateQueueProperties(results, false, true, null); + } + + /** + * Description: + * When a simple transient queue is created then a QUE-1001 create message + * is expected to be logged. + * Input: + * 1. Running broker + * 2. Persistent Queue is created from a client + * Output: + * + * <date> QUE-1001 : Create : Owner: '<name>' Durable Priority:<levels> + * + * Validation Steps: + * 3. The QUE ID is correct + * 4. The Durable tag is present in the message + * 5. The Owner is as expected + * 6. The Priority level is correctly set + * + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + * @throws java.io.IOException + */ + public void testCreateQueuePersistentPriority() throws NamingException, JMSException, IOException, AMQException + { + // To Create a Priority queue we need to use AMQSession specific code + final Map<String, Object> arguments = new HashMap<String, Object>(); + arguments.put("x-qpid-priorities", PRIORITIES); + // Need to create a queue that does not exist so use test name + final String queueName = getTestQueueName(); + ((AMQSession) _session).createQueue(new AMQShortString(queueName), false, _durable, false, arguments); + + Queue queue = (Queue) _session.createQueue("direct://amq.direct/"+queueName+"/"+queueName+"?durable='"+_durable+"'&autodelete='false'"); + + + //Need to create a Consumer to ensure that the log has had time to write + // as the above Create is Asynchronous + _session.createConsumer(queue); + + List<String> results = waitForMesssage(); + + // Only 1 Queue message should hav been logged + assertEquals("Result set size not as expected", 1, results.size()); + + validateQueueProperties(results, true, false, null); + } + + /** + * Description: + * When a simple transient queue is created then a QUE-1001 create message + * is expected to be logged. + * Input: + * 1. Running broker + * 2. AutoDelete Persistent Queue is created from a client + * Output: + * + * <date> QUE-1001 : Create : Owner: '<name>' Durable Priority:<levels> + * + * Validation Steps: + * 3. The QUE ID is correct + * 4. The Durable tag is present in the message + * 5. The Owner is as expected + * 6. The AutoDelete tag is present in the message + * 7. The Priority level is correctly set + * + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + * @throws java.io.IOException + */ + public void testCreateQueuePersistentAutoDeletePriority() throws NamingException, JMSException, IOException, AMQException + { + // To Create a Priority queue we need to use AMQSession specific code + final Map<String, Object> arguments = new HashMap<String, Object>(); + arguments.put("x-qpid-priorities", PRIORITIES); + // Need to create a queue that does not exist so use test name + final String queueName = getTestQueueName() + "-autoDeletePriority"; + ((AMQSession) _session).createQueue(new AMQShortString(queueName), true, _durable, false, arguments); + + Queue queue = (Queue) _session.createQueue("direct://amq.direct/"+queueName+"/"+queueName+"?durable='"+_durable+"'&autodelete='true'"); + + + //Need to create a Consumer to ensure that the log has had time to write + // as the above Create is Asynchronous + _session.createConsumer(queue); + + List<String> results = waitForMesssage(); + + validateQueueProperties(results, true, true, null); + } + + private List<String> waitForMesssage() throws IOException + { + // Validation + // Ensure we have received the QUE log msg. + waitForMessage("QUE-1001"); + + List<String> results = findMatches(QUEUE_PREFIX); + + // Only 1 Queue message should hav been logged + assertEquals("Result set size not as expected", 1, results.size()); + + return results; + } + + public void validateQueueProperties(List<String> results, boolean hasPriority, boolean hasAutodelete, String clientID) + { + String log = getLogMessage(results, 0); + + // Message Should be a QUE-1001 + validateMessageID("QUE-1001", log); + + // Queue is Durable + assertEquals(DURABLE + " keyword not correct in log entry", + _durable, fromMessage(log).contains(DURABLE)); + + assertEquals(TRANSIENT + " keyword not correct in log entry.", + !_durable, fromMessage(log).contains(TRANSIENT)); + + // Queue is Priority + assertEquals("Unexpected priority status:" + fromMessage(log), hasPriority, + fromMessage(log).contains("Priority: " + PRIORITIES)); + + // Queue is AutoDelete + assertEquals("Unexpected AutoDelete status:" + fromMessage(log), hasAutodelete, + fromMessage(log).contains("AutoDelete")); + + if(clientID != null) + { + assertTrue("Queue does not have correct owner value:" + fromMessage(log), + fromMessage(log).contains("Owner: " + clientID)); + } + else + { + assertFalse("Queue should not contain Owner tag:" + fromMessage(log), + fromMessage(log).contains("Owner")); + } + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java new file mode 100644 index 0000000000..edffa7c0c0 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/ExchangeLoggingTest.java @@ -0,0 +1,254 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.client.AMQConnection; +import org.apache.qpid.client.AMQSession; +import org.apache.qpid.client.AMQSession_0_10; +import org.apache.qpid.framing.AMQFrame; +import org.apache.qpid.framing.AMQShortString; +import org.apache.qpid.framing.ExchangeDeleteBody; +import org.apache.qpid.framing.ExchangeDeleteOkBody; +import org.apache.qpid.framing.amqp_8_0.MethodRegistry_8_0; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.MessageProducer; +import javax.jms.Queue; +import javax.jms.Session; +import javax.jms.TextMessage; +import java.io.IOException; +import java.util.List; + +/** + * Exchange + * + * The Exchange test suite validates that the follow log messages as specified in the Functional Specification. + * + * This suite of tests validate that the Exchange messages occur correctly and according to the following format: + * + * EXH-1001 : Create : [Durable] Type:<value> Name:<value> + * EXH-1002 : Deleted + */ +public class ExchangeLoggingTest extends AbstractTestLogging +{ + + static final String EXH_PREFIX = "EXH-"; + + private Connection _connection; + private Session _session; + private Queue _queue; + private String _name; + private String _type; + + @Override + public void setUp() throws Exception + { + super.setUp(); + + _connection = getConnection(); + + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + _type = "direct"; + _name = getTestQueueName()+ "-exchange"; + + _queue = _session.createQueue(_type + "://" + _name + "/queue/queue"); + + } + + /** + * Description: + * When a durable exchange is created an EXH-1001 message is logged with the Durable tag. This will be the first message from this exchange. + * Input: + * + * 1. Running broker + * 2. Client requests a durable exchange be created. + * Output: + * + * <date> EXH-1001 : Create : Durable Type:<value> Name:<value> + * + * Validation Steps: + * 3. The EXH ID is correct + * 4. The Durable tag is present in the message + */ + + public void testExchangeCreateDurable() throws JMSException, IOException + { + // The client cannot create durable exchanges lets just look at the + // ones the broker creates at startup. + + // They should all be durable + + // Ensure we have received the EXH log msg. + waitForMessage("EXH-1001"); + + List<String> results = findMatches(EXH_PREFIX); + + assertTrue("No Results found for Exchange.", results.size()>0); + + validateExchangeCreate(results, true, false); + } + + /** + * Description: + * When an exchange is created an EXH-1001 message is logged. This will be the first message from this exchange. + * Input: + * + * 1. Running broker + * 2. Client requests an exchange be created. + * Output: + * + * <date> EXH-1001 : Create : Type:<value> Name:<value> + * + * Validation Steps: + * 3. The EXH ID is correct + */ + public void testExchangeCreate() throws JMSException, IOException + { + //Ignore broker startup messages + _monitor.markDiscardPoint(); + + _session.createConsumer(_queue); + // Ensure we have received the EXH log msg. + waitForMessage("EXH-1001"); + + List<String> results = findMatches(EXH_PREFIX); + + assertEquals("Result set larger than expected.", 1, results.size()); + + validateExchangeCreate(results, false, true); + } + + private void validateExchangeCreate(List<String> results, boolean durable, boolean checkNameAndType) + { + String log = getLogMessage(results, 0); + String message = getMessageString(fromMessage(log)); + + validateMessageID("EXH-1001", log); + + assertTrue("Log Message does not start with create:" + message, + message.startsWith("Create")); + + assertEquals("Unexpected Durable state:" + message, durable, + message.contains("Durable")); + + if(checkNameAndType) + { + assertTrue("Log Message does not contain Type:" + message, + message.contains("Type: " + _type)); + assertTrue("Log Message does not contain Name:" + message, + message.contains("Name: " + _name)); + } + } + + /** + * Description: + * An Exchange can be deleted through an AMQP ExchangeDelete method. When this is successful an EXH-1002 Delete message will be logged. This will be the last message from this exchange. + * Input: + * + * 1. Running broker + * 2. A new Exchange has been created + * 3. Client requests that the new exchange be deleted. + * Output: + * + * <date> EXH-1002 : Deleted + * + * Validation Steps: + * 4. The EXH ID is correct + * 5. There is a corresponding EXH-1001 Create message logged. + */ + public void testExchangeDelete() throws Exception, IOException + { + //Ignore broker startup messages + _monitor.markDiscardPoint(); + + //create the exchange by creating a consumer + _session.createConsumer(_queue); + + //now delete the exchange + if(isBroker010()) + { + ((AMQSession_0_10) _session).sendExchangeDelete(_name, false); + } + else + { + MethodRegistry_8_0 registry = new MethodRegistry_8_0(); + + ExchangeDeleteBody body = registry.createExchangeDeleteBody(0, new AMQShortString(_name), false, true); + + AMQFrame exchangeDeclare = body.generateFrame(((AMQSession)_session).getChannelId()); + + ((AMQConnection) _connection).getProtocolHandler().syncWrite(exchangeDeclare, ExchangeDeleteOkBody.class); + } + + //Wait and ensure we get our last EXH-1002 msg + waitForMessage("EXH-1002"); + + List<String> results = findMatches(EXH_PREFIX); + + assertEquals("Result set larger than expected.", 2, results.size()); + + validateExchangeCreate(results, false, false); + + String log = getLogMessage(results, 1); + validateMessageID("EXH-1002", log); + + String message = getMessageString(fromMessage(log)); + assertEquals("Log Message not as expected", "Deleted", message); + + } + + public void testDiscardedMessage() throws Exception + { + //Ignore broker startup messages + _monitor.markDiscardPoint(); + + if (!isBroker010()) + { + // Default 0-8..-0-9-1 behaviour is for messages to be rejected (returned to client). + setTestClientSystemProperty("qpid.default_mandatory", "false"); + } + + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + + // Do not create consumer so queue is not created and message will be discarded. + final MessageProducer producer = _session.createProducer(_queue); + + // Sending message + final TextMessage msg = _session.createTextMessage("msg"); + producer.send(msg); + + final String expectedMessageBody = "Discarded Message : Name: " + _name + " Routing Key: " + _queue.getQueueName(); + + // Ensure we have received the EXH log msg. + waitForMessage("EXH-1003"); + + List<String> results = findMatches(EXH_PREFIX); + assertEquals("Result set larger than expected.", 2, results.size()); + + final String log = getLogMessage(results, 1); + validateMessageID("EXH-1003", log); + + final String message = getMessageString(fromMessage(log)); + assertEquals("Log Message not as expected", expectedMessageBody, message); + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/QueueLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/QueueLoggingTest.java new file mode 100644 index 0000000000..1c7b4c6be8 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/QueueLoggingTest.java @@ -0,0 +1,183 @@ +/* + * + * 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.qpid.server.logging; + +import org.apache.qpid.AMQException; +import org.apache.qpid.client.AMQSession; +import org.apache.qpid.client.failover.FailoverException; +import org.apache.qpid.framing.AMQShortString; +import org.apache.qpid.server.logging.subjects.AbstractTestLogSubject; + +import javax.jms.Connection; +import javax.jms.JMSException; +import javax.jms.Queue; +import javax.jms.Session; +import javax.naming.NamingException; +import java.io.IOException; +import java.util.List; + +/** + * The Queue test suite validates that the follow log messages as specified in + * the Functional Specification. + * + * This suite of tests validate that the Queue messages occur correctly and + * according to the following format: + * + * QUE-1002 : Deleted + */ +public class QueueLoggingTest extends AbstractTestLogging +{ + protected Connection _connection; + protected Session _session; + private static final String QUEUE_PREFIX = "QUE-"; + + public void setUp() throws Exception + { + super.setUp(); + //Remove broker startup logging messages + _monitor.markDiscardPoint(); + + _connection = getConnection(); + _session = _connection.createSession(false, Session.AUTO_ACKNOWLEDGE); + } + + /** + * Description: + * An explict QueueDelete request must result in a QUE-1002 Deleted message + * being logged. This can be done via an explict AMQP QueueDelete method. + * Input: + * + * 1. Running Broker + * 2. Queue created on the broker with no subscribers + * 3. Client requests the queue be deleted via a QueueDelete + * Output: + * + * <date> QUE-1002 : Deleted + * + * Validation Steps: + * + * 4. The QUE ID is correct + * + * @throws java.io.IOException + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + */ + public void testQueueDelete() throws NamingException, JMSException, IOException, FailoverException, AMQException + { + // To force a queue Creation Event we need to create a consumer. + Queue queue = _session.createQueue(getTestQueueName()); + + _session.createConsumer(queue); + + // Delete Queue + ((AMQSession)_session).sendQueueDelete(new AMQShortString(queue.getQueueName())); + + //Perform a synchronous action to ensure that the above log will be on disk + _session.close(); + + // Validation + //Ensure that we wait for the QUE log message + waitAndFindMatches("QUE-1002"); + + List<String> results = findMatches(QUEUE_PREFIX); + + // Only 1 Queue message should hav been logged + assertEquals("Result set size not as expected", 2, results.size()); + + String log = getLogMessage(results, 0); + + // Message Should be a QUE-1001 + validateMessageID("QUE-1001", log); + + String createdQueueName = AbstractTestLogSubject.getSlice("qu", fromSubject(log)); + + log = getLogMessage(results, 1); + // Message Should be a QUE-1002 + validateMessageID("QUE-1002", log); + + assertEquals("Log Message is incorrect ", "Deleted", getMessageString(fromMessage(log))); + + assertEquals("Queue Delete not for created queue:", createdQueueName, + AbstractTestLogSubject.getSlice("qu", fromSubject(log))); + } + + + /** + * Description: + * An explict QueueDelete request must result in a QUE-1002 Deleted message + * being logged. This can be done via an explict AMQP QueueDelete method. + * Input: + * + * 1. Running Broker + * 2. Queue created on the broker with no subscribers + * 3. Client creates a temporary queue then disconnects + * Output: + * + * <date> QUE-1002 : Deleted + * + * Validation Steps: + * + * 4. The QUE ID is correct + * + * @throws java.io.IOException + * @throws javax.jms.JMSException + * @throws javax.naming.NamingException + */ + public void testQueueAutoDelete() throws NamingException, JMSException, IOException + { + // Create a temporary queue so that when we consume from it and + // then close the consumer it will be autoDeleted. + _session.createConsumer(_session.createTemporaryQueue()).close(); + + if(isBroker010()) + { + //auto-delete is at session close for 0-10 + _session.close(); + } + + // Validation + //Ensure that we wait for the QUE log message + waitAndFindMatches("QUE-1002"); + + List<String> results = findMatches(QUEUE_PREFIX); + + // Only 1 Queue message should hav been logged + assertEquals("Result set size not as expected", 2, results.size()); + + String log = getLogMessage(results, 0); + + // Message Should be a QUE-1001 + validateMessageID("QUE-1001", log); + + String createdQueueName = AbstractTestLogSubject.getSlice("qu", fromSubject(log)); + + log = getLogMessage(results, 1); + // Message Should be a QUE-1002 + validateMessageID("QUE-1002", log); + + assertEquals("Log Message is incorrect ", "Deleted", getMessageString(fromMessage(log))); + + assertEquals("Queue Delete not for created queue:", createdQueueName, + AbstractTestLogSubject.getSlice("qu", fromSubject(log))); + + } + +}
\ No newline at end of file diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/TransientQueueLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/TransientQueueLoggingTest.java new file mode 100644 index 0000000000..29f74c5818 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/TransientQueueLoggingTest.java @@ -0,0 +1,30 @@ +/* + * + * 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.qpid.server.logging; + +public class TransientQueueLoggingTest extends DurableQueueLoggingTest +{ + public void setUp() throws Exception + { + super.setUp(); + _durable = false; + } +} diff --git a/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/VirtualHostLoggingTest.java b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/VirtualHostLoggingTest.java new file mode 100644 index 0000000000..25dd5fd2f8 --- /dev/null +++ b/qpid/java/systests/src/test/java/org/apache/qpid/server/logging/VirtualHostLoggingTest.java @@ -0,0 +1,130 @@ +/* + * 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.qpid.server.logging; + +import junit.framework.AssertionFailedError; + + +import java.util.Arrays; +import java.util.List; + +/** + * Virtualhost Test Cases + * The virtualhost test suite validates that the follow log messages as specified in the Functional Specification. + * <p/> + * This suite of tests validate that the management console messages occur correctly and according to the following format: + * <p/> + * VHT-1001 : Created : <name> + * VHT-1002 : Work directory : <path> + * VHT-1003 : Closed + */ +public class VirtualHostLoggingTest extends AbstractTestLogging +{ + private static final String VHT_PREFIX = "VHT-"; + + /** + * Description: + * Testing can be performed using the default configuration. The goal is to validate that for each virtualhost defined in the configuration file a VHT-1001 Created message is provided. + * Input: + * The default configuration file + * Output: + * <p/> + * <date> VHT-1001 : Created : <name> + * Validation Steps: + * <p/> + * The VHT ID is correct + * A VHT-1001 is printed for each virtualhost defined in the configuration file. + * This must be the first message for the specified virtualhost. + * + * @throws Exception caused by broker startup + */ + public void testVirtualhostCreation() throws Exception + { + //Wait for the correct VHT message to arrive. + waitForMessage(VHT_PREFIX + "1001"); + + //Validate each vhost logs a creation + List<String> results = findMatches(VHT_PREFIX + "1001"); + + try + { + List<String> vhosts = Arrays.asList("test"); + + assertEquals("Each vhost did not create a store.", vhosts.size(), results.size()); + + for (int index = 0; index < results.size(); index++) + { + // Retrieve the vhostname from the log entry message 'Created : <vhostname>' + String result = getLogMessage(results, index); + String vhostName = getMessageString(fromMessage(result)).split(" ")[2]; + + assertTrue("Virtualhost named in log not found in config file:" + vhostName + ":" + vhosts, vhosts.contains(vhostName)); + } + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + + throw afe; + } + } + + /** + * Description: + * Testing can be performed using the default configuration. During broker shutdown a VHT-1002 Closed message will be printed for each of the configured virtualhosts. For every virtualhost that was started a close must be logged. After the close message has been printed no further logging will be performed by this virtualhost. + * Input: + * The default configuration file + * Output: + * <p/> + * <date> VHT-1002 : Closed + * Validation Steps: + * <p/> + * The VHT ID is correct + * This is the last VHT message for the given virtualhost. + * + * @throws Exception caused by broker startup + */ + public void testVirtualhostClosure() throws Exception + { + if (isJavaBroker() && isInternalBroker()) + { + stopBroker(); + + // Wait for the correct VHT message to arrive. + waitForMessage(VHT_PREFIX + "1002"); + + // Validate each vhost logs a closure + List<String> results = findMatches(VHT_PREFIX + "1002"); + + try + { + assertEquals("Each vhost did not close their store.", 1, results.size()); + } + catch (AssertionFailedError afe) + { + dumpLogs(results, _monitor); + throw afe; + } + } + } + +} |