QPID-4187: Improve operational management logging: - make ManagementActor thread-safe, stop caching of log string without context principal set, use separate instance of ManagementActor with pre-set principal for opening and closing notifications for JMX connections

Applied patch from Philip Harvey <phil@philharveyonline.com> and Oleksandr Rudyy<orudyy@gmail.com>

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

3 files changed, 95 insertions, 35 deletions

diff --git a/qpid/java/broker-plugins/management-jmx/src/main/java/org/apache/qpid/server/jmx/MBeanInvocationHandlerImpl.java b/qpid/java/broker-plugins/management-jmx/src/main/java/org/apache/qpid/server/jmx/MBeanInvocationHandlerImpl.java
index ce4e75f8c2..2dc97cef49 100644
--- a/qpid/java/broker-plugins/management-jmx/src/main/java/org/apache/qpid/server/jmx/MBeanInvocationHandlerImpl.java
+++ b/qpid/java/broker-plugins/management-jmx/src/main/java/org/apache/qpid/server/jmx/MBeanInvocationHandlerImpl.java
@@ -22,6 +22,7 @@ package org.apache.qpid.server.jmx;
 
 import org.apache.log4j.Logger;
 
+import org.apache.qpid.server.logging.LogActor;
 import org.apache.qpid.server.logging.actors.CurrentActor;
 import org.apache.qpid.server.logging.actors.ManagementActor;
 import org.apache.qpid.server.logging.messages.ManagementConsoleMessages;
@@ -366,14 +367,17 @@ public class MBeanInvocationHandlerImpl implements InvocationHandler, Notificati
             user = splitConnectionId[1];
         }
 
+        // use a separate instance of actor as subject is not set on connect/disconnect
+        // we need to pass principal name explicitly into log actor
+        LogActor logActor = new ManagementActor(_appRegistry.getRootMessageLogger(), user);
         if (JMXConnectionNotification.OPENED.equals(type))
         {
-            _logActor.message(ManagementConsoleMessages.OPEN(user));
+            logActor.message(ManagementConsoleMessages.OPEN(user));
         }
         else if (JMXConnectionNotification.CLOSED.equals(type) ||
                  JMXConnectionNotification.FAILED.equals(type))
         {
-            _logActor.message(ManagementConsoleMessages.CLOSE(user));
+            logActor.message(ManagementConsoleMessages.CLOSE(user));
         }
     }
 }
diff --git a/qpid/java/broker/src/main/java/org/apache/qpid/server/logging/actors/ManagementActor.java b/qpid/java/broker/src/main/java/org/apache/qpid/server/logging/actors/ManagementActor.java
index 9cd3c66629..a2f3506502 100644
--- a/qpid/java/broker/src/main/java/org/apache/qpid/server/logging/actors/ManagementActor.java
+++ b/qpid/java/broker/src/main/java/org/apache/qpid/server/logging/actors/ManagementActor.java
@@ -30,16 +30,7 @@ import java.text.MessageFormat;
 import java.util.Set;
 
 /**
- * NOTE: This actor is not thread safe.
- *
- * Sharing of a ManagementActor instance between threads may result in an
- * incorrect actor value being logged.
- *
- * This is due to the fact that calls to message will dynamically query the
- * thread name and use that to set the log format during each message() call.
- *
- * This is currently not an issue as each MBean operation creates a new Actor
- * that is unique for each operation.
+ * Management actor to use in {@link MBeanInvocationHandlerImpl} to log all management operational logging.
  */
 public class ManagementActor extends AbstractActor
 {
@@ -66,38 +57,45 @@ public class ManagementActor extends AbstractActor
     /**
      * The logString to be used for logging
      */
-    private String _logString;
+    private String _logStringContainingPrincipal;
+
+    /** used when the principal name cannot be discovered from the Subject */
+    private final String _fallbackPrincipalName;
 
     /** @param rootLogger The RootLogger to use for this Actor */
     public ManagementActor(RootMessageLogger rootLogger)
     {
         super(rootLogger);
+        _fallbackPrincipalName = UNKNOWN_PRINCIPAL;
+    }
+
+    public ManagementActor(RootMessageLogger rootLogger, String principalName)
+    {
+        super(rootLogger);
+        _fallbackPrincipalName = principalName;
     }
 
-    private void updateLogString()
+    private synchronized String getAndCacheLogString()
     {
         String currentName = Thread.currentThread().getName();
 
         String actor;
+        String logString = _logStringContainingPrincipal;
+
         // Record the last thread name so we don't have to recreate the log string
-        if (!currentName.equals(_lastThreadName))
+        if (_logStringContainingPrincipal == null || !currentName.equals(_lastThreadName))
         {
             _lastThreadName = currentName;
+            String principalName = getPrincipalName();
 
             // Management Thread names have this format.
             // RMI TCP Connection(2)-169.24.29.116
             // This is true for both LocalAPI and JMX Connections
             // However to be defensive lets test.
-
             String[] split = currentName.split("\\(");
             if (split.length == 2)
             {
                 String ip = currentName.split("-")[1];
-                String principalName = getPrincipalName();
-                if (principalName == null)
-                {
-                    principalName = UNKNOWN_PRINCIPAL;
-                }
                 actor = MessageFormat.format(MANAGEMENT_FORMAT, principalName, ip);
             }
             else
@@ -111,9 +109,14 @@ public class ManagementActor extends AbstractActor
                 actor = currentName;
             }
 
-            _logString = "[" + actor + "] ";
+            logString = "[" + actor + "] ";
+            if(principalName != UNKNOWN_PRINCIPAL )
+            {
+                _logStringContainingPrincipal = logString;
+            }
 
         }
+        return logString;
     }
 
     /**
@@ -121,9 +124,9 @@ public class ManagementActor extends AbstractActor
      *
      * @return principal name or null if principal can not be found
      */
-    protected String getPrincipalName()
+    private String getPrincipalName()
     {
-        String identity = null;
+        String identity = _fallbackPrincipalName;
 
         // retrieve Subject from current AccessControlContext
         final Subject subject = Subject.getSubject(AccessController.getContext());
@@ -142,8 +145,7 @@ public class ManagementActor extends AbstractActor
 
     public String getLogMessage()
     {
-        updateLogString();
-        return _logString;
+        return getAndCacheLogString();
     }
 
 }
diff --git a/qpid/java/broker/src/test/java/org/apache/qpid/server/logging/actors/ManagementActorTest.java b/qpid/java/broker/src/test/java/org/apache/qpid/server/logging/actors/ManagementActorTest.java
index b431047d66..cb866245f0 100644
--- a/qpid/java/broker/src/test/java/org/apache/qpid/server/logging/actors/ManagementActorTest.java
+++ b/qpid/java/broker/src/test/java/org/apache/qpid/server/logging/actors/ManagementActorTest.java
@@ -26,15 +26,6 @@ import java.security.PrivilegedAction;
 import java.util.Collections;
 import java.util.List;
 
-/**
- * Test : AMQPManagementActorTest
- * Validate the AMQPManagementActor class.
- *
- * The test creates a new AMQPActor and then logs a message using it.
- *
- * The test then verifies that the logged message was the only one created and
- * that the message contains the required message.
- */
 public class ManagementActorTest extends BaseActorTestCase
 {
 
@@ -131,4 +122,67 @@ public class ManagementActorTest extends BaseActorTestCase
         assertTrue("Message contains the [mng: prefix", logMessage.contains("[mng:guest(" + IP + ")"));
     }
 
+    public void testGetLogMessageWithSubject()
+    {
+        assertLogMessageInRMIThreadWithPrincipal("RMI TCP Connection(" + CONNECTION_ID + ")-" + IP, "my_principal");
+    }
+
+    public void testGetLogMessageWithoutSubjectButWithActorPrincipal()
+    {
+        String principalName = "my_principal";
+        _amqpActor = new ManagementActor(_rootLogger, principalName);
+        String message = _amqpActor.getLogMessage();
+        assertEquals("Unexpected log message", "[mng:" + principalName + "(" + IP + ")] ", message);
+    }
+
+    /** It's necessary to test successive calls because ManagementActor caches its log message based on thread and principal name */
+    public void testGetLogMessageCaching()
+    {
+        String originalThreadName = "RMI TCP Connection(1)-" + IP;
+        assertLogMessageInRMIThreadWithoutPrincipal(originalThreadName);
+        assertLogMessageInRMIThreadWithPrincipal(originalThreadName, "my_principal");
+        assertLogMessageInRMIThreadWithPrincipal("RMI TCP Connection(2)-" + IP, "my_principal");
+    }
+
+    public void testGetLogMessageAfterRemovingSubject()
+    {
+        assertLogMessageInRMIThreadWithPrincipal("RMI TCP Connection(1)-" + IP, "my_principal");
+
+        Thread.currentThread().setName("RMI TCP Connection(2)-" + IP );
+        String message = _amqpActor.getLogMessage();
+        assertEquals("Unexpected log message", "[mng:N/A(" + IP + ")] ", message);
+
+        assertLogMessageWithoutPrincipal("TEST");
+    }
+
+    private void assertLogMessageInRMIThreadWithoutPrincipal(String threadName)
+    {
+        Thread.currentThread().setName(threadName );
+        String message = _amqpActor.getLogMessage();
+        assertEquals("Unexpected log message", "[mng:N/A(" + IP + ")] ", message);
+    }
+
+    private void assertLogMessageWithoutPrincipal(String threadName)
+    {
+        Thread.currentThread().setName(threadName );
+        String message = _amqpActor.getLogMessage();
+        assertEquals("Unexpected log message", "[" + threadName +"] ", message);
+    }
+
+    private void assertLogMessageInRMIThreadWithPrincipal(String threadName, String principalName)
+    {
+        Thread.currentThread().setName(threadName);
+        Subject subject = new Subject(true, Collections.singleton(new JMXPrincipal(principalName)), Collections.EMPTY_SET,
+                Collections.EMPTY_SET);
+
+        final String message = Subject.doAs(subject, new PrivilegedAction<String>()
+        {
+            public String run()
+            {
+                return _amqpActor.getLogMessage();
+            }
+        });
+
+        assertEquals("Unexpected log message", "[mng:" + principalName + "(" + IP + ")] ", message);
+    }
 }