QPID-3474: Use JMX notification handback data to ensure that open/close/fail events are logged with username only, rather than a complete list of pricipals.

git-svn-id: https://svn.apache.org/repos/asf/qpid/trunk/qpid@1205911 13f79535-47bb-0310-9956-ffa450edef68

3 files changed, 168 insertions, 91 deletions

diff --git a/java/broker/src/main/java/org/apache/qpid/server/management/JMXManagedObjectRegistry.java b/java/broker/src/main/java/org/apache/qpid/server/management/JMXManagedObjectRegistry.java
index b44964f176..7210b404dd 100644
--- a/java/broker/src/main/java/org/apache/qpid/server/management/JMXManagedObjectRegistry.java
+++ b/java/broker/src/main/java/org/apache/qpid/server/management/JMXManagedObjectRegistry.java
@@ -38,6 +38,8 @@ import java.rmi.server.RMIClientSocketFactory;
 import java.rmi.server.RMIServerSocketFactory;
 import java.rmi.server.UnicastRemoteObject;
 import java.util.HashMap;
+import java.util.Map;
+import java.util.concurrent.ConcurrentHashMap;
 
 import javax.management.JMException;
 import javax.management.MBeanServer;
@@ -49,11 +51,13 @@ import javax.management.remote.JMXConnectionNotification;
 import javax.management.remote.JMXConnectorServer;
 import javax.management.remote.JMXServiceURL;
 import javax.management.remote.MBeanServerForwarder;
+import javax.management.remote.rmi.RMIConnection;
 import javax.management.remote.rmi.RMIConnectorServer;
 import javax.management.remote.rmi.RMIJRMPServerImpl;
 import javax.management.remote.rmi.RMIServerImpl;
 import javax.rmi.ssl.SslRMIClientSocketFactory;
 import javax.rmi.ssl.SslRMIServerSocketFactory;
+import javax.security.auth.Subject;
 
 import org.apache.commons.configuration.ConfigurationException;
 import org.apache.log4j.Logger;
@@ -63,6 +67,7 @@ import org.apache.qpid.server.logging.messages.ManagementConsoleMessages;
 import org.apache.qpid.server.registry.ApplicationRegistry;
 import org.apache.qpid.server.registry.IApplicationRegistry;
 import org.apache.qpid.server.security.auth.rmi.RMIPasswordAuthenticator;
+import org.apache.qpid.server.security.auth.sasl.UsernamePrincipal;
 
 /**
  * This class starts up an MBeanserver. If out of the box agent has been enabled then there are no 
@@ -223,7 +228,28 @@ public class JMXManagedObjectRegistry implements ManagedObjectRegistry
          * The registry is exported on the defined management port 'port'. We will export the RMIConnectorServer
          * on 'port +1'. Use of these two well-defined ports will ease any navigation through firewall's. 
          */
-        final RMIServerImpl rmiConnectorServerStub = new RMIJRMPServerImpl(_jmxPortConnectorServer, csf, ssf, env);
+        final Map<String, String> connectionIdUsernameMap = new ConcurrentHashMap<String, String>();
+        final RMIServerImpl rmiConnectorServerStub = new RMIJRMPServerImpl(_jmxPortConnectorServer, csf, ssf, env)
+        {
+
+            /**
+             * Override makeClient so we can cache the username of the client in a Map keyed by connectionId.
+             * ConnectionId is guaranteed to be unique per client connection, according to the JMS spec.
+             *
+             * MBeanInvocationHandlerImpl#handleNotification is responsible for removing the map entry on receipt
+             * of CLOSE or FAIL notifications.
+             *
+             * @see javax.management.remote.rmi.RMIJRMPServerImpl#makeClient(java.lang.String, javax.security.auth.Subject)
+             */
+            @Override
+            protected RMIConnection makeClient(String connectionId, Subject subject) throws IOException
+            {
+                final RMIConnection makeClient = super.makeClient(connectionId, subject);
+                final UsernamePrincipal usernamePrincipalFromSubject = UsernamePrincipal.getUsernamePrincipalFromSubject(subject);
+                connectionIdUsernameMap.put(connectionId, usernamePrincipalFromSubject.getName());
+                return makeClient;
+            }
+        };
         String localHost;
         try
         {
@@ -295,13 +321,18 @@ public class JMXManagedObjectRegistry implements ManagedObjectRegistry
         MBeanServerForwarder mbsf = MBeanInvocationHandlerImpl.newProxyInstance();
         _cs.setMBeanServerForwarder(mbsf);
 
+
+        // Get the handler that is used by the above MBInvocationHandler Proxy.
+        // which is the MBeanInvocationHandlerImpl and so also a NotificationListener.
+        final NotificationListener invocationHandler = (NotificationListener) Proxy.getInvocationHandler(mbsf);
+
+        // Install a notification listener on OPENED, CLOSED, and FAIL,
+        // passing the map of connection-ids to usernames as hand-back data.
         NotificationFilterSupport filter = new NotificationFilterSupport();
         filter.enableType(JMXConnectionNotification.OPENED);
         filter.enableType(JMXConnectionNotification.CLOSED);
         filter.enableType(JMXConnectionNotification.FAILED);
-        // Get the handler that is used by the above MBInvocationHandler Proxy.
-        // which is the MBeanInvocationHandlerImpl and so also a NotificationListener
-        _cs.addNotificationListener((NotificationListener) Proxy.getInvocationHandler(mbsf), filter, null);
+        _cs.addNotificationListener(invocationHandler, filter, connectionIdUsernameMap);
 
         _cs.start();
 
diff --git a/java/broker/src/main/java/org/apache/qpid/server/management/MBeanInvocationHandlerImpl.java b/java/broker/src/main/java/org/apache/qpid/server/management/MBeanInvocationHandlerImpl.java
index 0dd8c95ef3..562b6404c3 100644
--- a/java/broker/src/main/java/org/apache/qpid/server/management/MBeanInvocationHandlerImpl.java
+++ b/java/broker/src/main/java/org/apache/qpid/server/management/MBeanInvocationHandlerImpl.java
@@ -26,6 +26,7 @@ import java.lang.reflect.Method;
 import java.lang.reflect.Proxy;
 import java.security.AccessControlContext;
 import java.security.AccessController;
+import java.util.Map;
 import java.util.Set;
 
 import javax.management.Attribute;
@@ -33,7 +34,6 @@ import javax.management.JMException;
 import javax.management.MBeanInfo;
 import javax.management.MBeanOperationInfo;
 import javax.management.MBeanServer;
-import javax.management.MalformedObjectNameException;
 import javax.management.Notification;
 import javax.management.NotificationListener;
 import javax.management.ObjectName;
@@ -320,23 +320,52 @@ public class MBeanInvocationHandlerImpl implements InvocationHandler, Notificati
         return (methodName.startsWith("query") || methodName.startsWith("get") || methodName.startsWith("is"));
     }
 
-    public void handleNotification(Notification notification, Object handback)
+    /**
+     * Receives notifications from the MBeanServer.
+     */
+    public void handleNotification(final Notification notification, final Object handback)
     {
         assert notification instanceof JMXConnectionNotification;
 
-        // only RMI Connections are serviced here, Local API atta
-        // rmi://169.24.29.116 guest 3
-        String[] connectionData = ((JMXConnectionNotification) notification).getConnectionId().split(" ");
-        String user = connectionData[1];
+        final String connectionId = ((JMXConnectionNotification) notification).getConnectionId();
+        final String type = notification.getType();
 
-        if (notification.getType().equals(JMXConnectionNotification.OPENED))
+        if (_logger.isDebugEnabled())
+        {
+            _logger.debug("Notification connectionId : " + connectionId + " type : " + type
+                    + " Notification handback : " + handback);
+        }
+
+        // Normally JMXManagedObjectRegistry provides a Map as handback data containing a map
+        // between connection id and username.
+        Map<String, String> connectionIdUsernameMap = null;
+        String user = null;
+        if (handback != null && handback instanceof Map)
+        {
+            connectionIdUsernameMap = (Map<String, String>) handback;
+            user = connectionIdUsernameMap.get(connectionId);
+        }
+
+        // If user is still null, fallback to an unordered list of Principals from the connection id.
+        if (user == null)
+        {
+            final String[] splitConnectionId = connectionId.split(" ");
+            user = splitConnectionId[1];
+        }
+
+        if (JMXConnectionNotification.OPENED.equals(type))
         {
             _logActor.message(ManagementConsoleMessages.OPEN(user));
         }
-        else if (notification.getType().equals(JMXConnectionNotification.CLOSED) ||
-                 notification.getType().equals(JMXConnectionNotification.FAILED))
+        else if (JMXConnectionNotification.CLOSED.equals(type) ||
+                 JMXConnectionNotification.FAILED.equals(type))
         {
             _logActor.message(ManagementConsoleMessages.CLOSE(user));
+            // We are responsible for removing the entry from the map
+            if (connectionIdUsernameMap != null)
+            {
+                connectionIdUsernameMap.remove(connectionId);
+            }
         }
     }
 }
diff --git a/java/systests/src/main/java/org/apache/qpid/server/logging/ManagementLoggingTest.java b/java/systests/src/main/java/org/apache/qpid/server/logging/ManagementLoggingTest.java
index 24e6aa4207..ed9109ebba 100644
--- a/java/systests/src/main/java/org/apache/qpid/server/logging/ManagementLoggingTest.java
+++ b/java/systests/src/main/java/org/apache/qpid/server/logging/ManagementLoggingTest.java
@@ -20,9 +20,9 @@
  */
 package org.apache.qpid.server.logging;
 
-import junit.framework.AssertionFailedError;
 
 import org.apache.qpid.server.configuration.ServerConfiguration;
+import org.apache.qpid.test.utils.JMXTestUtils;
 import org.apache.qpid.util.LogMonitor;
 
 import java.util.List;
@@ -41,6 +41,8 @@ import java.io.File;
  * MNG-1004 : Ready
  * MNG-1005 : Stopped
  * MNG-1006 : Using SSL Keystore : <path>
+ * MNG-1007 : Open : User <username>
+ * MNG-1008 : Close : User <username>
  */
 public class ManagementLoggingTest extends AbstractTestLogging
 {
@@ -86,33 +88,24 @@ public class ManagementLoggingTest extends AbstractTestLogging
             waitForMessage("MNG-1001");
 
             List<String> results = findMatches(MNG_PREFIX);
-            
-            try
-            {
-                // Validation
+            // Validation
 
-                assertTrue("MNGer message not logged", results.size() > 0);
+            assertTrue("MNGer message not logged", results.size() > 0);
 
-                String log = getLogMessage(results, 0);
+            String log = getLogMessage(results, 0);
 
-                //1
-                validateMessageID("MNG-1001", log);
+            //1
+            validateMessageID("MNG-1001", log);
 
-                //2
-                //There will be 2 copies of the startup message (one via SystemOut, and one via Log4J)
-                results = findMatches("MNG-1001");
-                assertEquals("Unexpected startup message count.",
-                             2, results.size());
+            //2
+            //There will be 2 copies of the startup message (one via SystemOut, and one via Log4J)
+            results = findMatches("MNG-1001");
+            assertEquals("Unexpected startup message count.",
+                         2, results.size());
 
-                //3
-                assertEquals("Startup log message is not 'Startup'.", "Startup",
-                             getMessageString(log));
-            }
-            catch (AssertionFailedError afe)
-            {
-                dumpLogs(results, _monitor);
-                throw afe;
-            }
+            //3
+            assertEquals("Startup log message is not 'Startup'.", "Startup",
+                         getMessageString(log));
         }
     }
 
@@ -135,17 +128,9 @@ public class ManagementLoggingTest extends AbstractTestLogging
             startBrokerAndCreateMonitor(false, false);
 
             List<String> results = findMatches(MNG_PREFIX);
-            try
-            {
-                // Validation
+            // Validation
 
-                assertEquals("MNGer messages logged", 0, results.size());
-            }
-            catch (AssertionFailedError afe)
-            {
-                dumpLogs(results, _monitor);
-                throw afe;
-            }
+            assertEquals("MNGer messages logged", 0, results.size());
         }
     }
 
@@ -194,39 +179,31 @@ public class ManagementLoggingTest extends AbstractTestLogging
             startBrokerAndCreateMonitor(true, false);
             
             List<String> results = waitAndFindMatches("MNG-1002");
-            try
-            {
-                // Validation
+            // Validation
 
-                //There will be 4 startup messages (two via SystemOut, and two via Log4J)
-                assertEquals("Unexpected MNG-1002 message count", 4, results.size());
+            //There will be 4 startup messages (two via SystemOut, and two via Log4J)
+            assertEquals("Unexpected MNG-1002 message count", 4, results.size());
 
-                String log = getLogMessage(results, 0);
+            String log = getLogMessage(results, 0);
 
-                //1
-                validateMessageID("MNG-1002", log);
+            //1
+            validateMessageID("MNG-1002", log);
 
-                //Check the RMI Registry port is as expected
-                int mPort = getManagementPort(getPort());
-                assertTrue("RMI Registry port not as expected(" + mPort + ").:" + getMessageString(log),
-                           getMessageString(log).endsWith(String.valueOf(mPort)));
+            //Check the RMI Registry port is as expected
+            int mPort = getManagementPort(getPort());
+            assertTrue("RMI Registry port not as expected(" + mPort + ").:" + getMessageString(log),
+                       getMessageString(log).endsWith(String.valueOf(mPort)));
 
-                log = getLogMessage(results, 2);
+            log = getLogMessage(results, 2);
 
-                //1
-                validateMessageID("MNG-1002", log);
+            //1
+            validateMessageID("MNG-1002", log);
 
-                // We expect the RMI Registry port (the defined 'management port') to be
-                // 100 lower than the JMX RMIConnector Server Port (the actual JMX server)
-                int jmxPort = mPort + ServerConfiguration.JMXPORT_CONNECTORSERVER_OFFSET;
-                assertTrue("JMX RMIConnectorServer port not as expected(" + jmxPort + ").:" + getMessageString(log),
-                           getMessageString(log).endsWith(String.valueOf(jmxPort)));
-            }
-            catch (AssertionFailedError afe)
-            {
-                dumpLogs(results, _monitor);
-                throw afe;
-            }
+            // We expect the RMI Registry port (the defined 'management port') to be
+            // 100 lower than the JMX RMIConnector Server Port (the actual JMX server)
+            int jmxPort = mPort + ServerConfiguration.JMXPORT_CONNECTORSERVER_OFFSET;
+            assertTrue("JMX RMIConnectorServer port not as expected(" + jmxPort + ").:" + getMessageString(log),
+                       getMessageString(log).endsWith(String.valueOf(jmxPort)));
         }
     }
 
@@ -251,35 +228,75 @@ public class ManagementLoggingTest extends AbstractTestLogging
             startBrokerAndCreateMonitor(true, true);
 
             List<String> results = waitAndFindMatches("MNG-1006");
-            try
-            {
-                // Validation
 
-                assertTrue("MNGer message not logged", results.size() > 0);
+            assertTrue("MNGer message not logged", results.size() > 0);
+
+            String log = getLogMessage(results, 0);
 
-                String log = getLogMessage(results, 0);
+            //1
+            validateMessageID("MNG-1006", log);
 
-                //1
-                validateMessageID("MNG-1006", log);
+            // Validate we only have two MNG-1002 (one via stdout, one via log4j)
+            results = findMatches("MNG-1006");
+            assertEquals("Upexpected SSL Keystore message count",
+                         2, results.size());
+
+            // Validate the keystore path is as expected
+            assertTrue("SSL Keystore entry expected.:" + getMessageString(log),
+                       getMessageString(log).endsWith(new File(getConfigurationStringProperty("management.ssl.keyStorePath")).getName()));
+        }
+    }
 
-                // Validate we only have two MNG-1002 (one via stdout, one via log4j)
-                results = findMatches("MNG-1006");
-                assertEquals("Upexpected SSL Keystore message count",
-                             2, results.size());
+    /**
+     * Description: Tests the management connection open/close are logged correctly.
+     *
+     * Output:
+     *
+     * <date> MESSAGE MNG-1007 : Open : User <username>
+     * <date> MESSAGE MNG-1008 : Close : User <username>
+     *
+     * Validation Steps:
+     *
+     * 1. The MNG ID is correct
+     * 2. The message and username are correct
+     */
+    public void testManagementUserOpenClose() throws Exception
+    {
+        if (isJavaBroker())
+        {
+            startBrokerAndCreateMonitor(true, false);
 
-                // Validate the keystore path is as expected
-                assertTrue("SSL Keystore entry expected.:" + getMessageString(log),
-                           getMessageString(log).endsWith(new File(getConfigurationStringProperty("management.ssl.keyStorePath")).getName()));
+            final JMXTestUtils jmxUtils = new JMXTestUtils(this);
+            List<String> openResults = null;
+            List<String> closeResults = null;
+            try
+            {
+                jmxUtils.setUp();
+                jmxUtils.open();
+                openResults = waitAndFindMatches("MNG-1007");
             }
-            catch (AssertionFailedError afe)
+            finally
             {
-                dumpLogs(results, _monitor);
-                throw afe;
+                if (jmxUtils != null)
+                {
+                    jmxUtils.close();
+                    closeResults = waitAndFindMatches("MNG-1008");
+                }
             }
-        }
 
+            assertNotNull("Management Open results null", openResults.size());
+            assertEquals("Management Open logged unexpected number of times", 1, openResults.size());
+
+            assertNotNull("Management Close results null", closeResults.size());
+            assertEquals("Management Close logged unexpected number of times", 1, closeResults.size());
+
+            final String openMessage = getMessageString(getLogMessage(openResults, 0));
+            assertTrue("Unexpected open message " + openMessage, openMessage.endsWith("Open : User admin"));
+            final String closeMessage = getMessageString(getLogMessage(closeResults, 0));
+            assertTrue("Unexpected close message " + closeMessage, closeMessage.endsWith("Close : User admin"));
+        }
     }
-    
+
     private void startBrokerAndCreateMonitor(boolean managementEnabled, boolean useManagementSSL) throws Exception
     {
         //Ensure management is on