[AMQ-6764] add logging of exit of jmx ops such that overlaps and delays are visible in the audit. fix and test

activemq-broker/src/main/java/org/apache/activemq/broker/jmx/AnnotatedMBean.java

@@ -21,6 +21,7 @@ import java.lang.reflect.Method;
 import java.security.AccessController;
 import java.security.Principal;
 import java.util.HashMap;
+import java.util.Locale;
 import java.util.Map;
 
 import javax.management.MBeanAttributeInfo;
@@ -48,7 +49,12 @@ public class AnnotatedMBean extends StandardMBean {
 
     private static final Logger LOG = LoggerFactory.getLogger("org.apache.activemq.audit");
 
-    private static boolean audit;
+    private static final byte OFF = 0b00;
+    private static final byte ENTRY = 0b01;
+    private static final byte EXIT = 0b10;
+    private static final byte ALL = 0b11;
+
+    private static byte audit = OFF;
     private static AuditLogService auditLog;
 
     static {
@@ -56,12 +62,25 @@ public class AnnotatedMBean extends StandardMBean {
         for (Class<?> c : p) {
             primitives.put(c.getName(), c);
         }
-        audit = "true".equalsIgnoreCase(System.getProperty("org.apache.activemq.audit"));
+        audit = byteFromProperty("org.apache.activemq.audit");
-        if (audit) {
+        if (audit != OFF) {
             auditLog = AuditLogService.getAuditLog();
         }
     }
 
+    private static byte byteFromProperty(String s) {
+        byte val = OFF;
+        String config = System.getProperty(s, "").toLowerCase(Locale.ENGLISH);
+        if ("true".equals(config) || "entry".equals(config)) {
+            val = ENTRY;
+        } else if ("exit".equals(config)) {
+            val = EXIT;
+        } else if ("all".equals(config)) {
+            val = ALL;
+        }
+        return val;
+    }
+
     @SuppressWarnings({ "unchecked", "rawtypes" })
     public static void registerMBean(ManagementContext context, Object object, ObjectName objectName) throws Exception {
 
@@ -179,7 +198,8 @@ public class AnnotatedMBean extends StandardMBean {
 
     @Override
     public Object invoke(String s, Object[] objects, String[] strings) throws MBeanException, ReflectionException {
-        if (audit) {
+        JMXAuditLogEntry entry = null;
+        if (audit != OFF) {
             Subject subject = Subject.getSubject(AccessController.getContext());
             String caller = "anonymous";
             if (subject != null) {
@@ -189,7 +209,7 @@ public class AnnotatedMBean extends StandardMBean {
                 }
             }
 
-            AuditLogEntry entry = new JMXAuditLogEntry();
+            entry = new JMXAuditLogEntry();
             entry.setUser(caller);
             entry.setTimestamp(System.currentTimeMillis());
             entry.setOperation(this.getMBeanInfo().getClassName() + "." + s);
@@ -213,9 +233,16 @@ public class AnnotatedMBean extends StandardMBean {
                entry.getParameters().put("arguments", objects);
             }
 
+            if ((audit&ENTRY) == ENTRY) {
                 auditLog.log(entry);
             }
-        return super.invoke(s, objects, strings);
+        }
+        Object result = super.invoke(s, objects, strings);
+        if ((audit&EXIT) == EXIT) {
+            entry.complete();
+            auditLog.log(entry);
+        }
+        return result;
     }
 
     private Method getMBeanMethod(Class clazz, String methodName, String[] signature) throws ReflectiveOperationException {

activemq-broker/src/main/java/org/apache/activemq/broker/util/JMXAuditLogEntry.java

@@ -19,9 +19,16 @@ package org.apache.activemq.broker.util;
 import java.util.Arrays;
 
 public class JMXAuditLogEntry extends AuditLogEntry {
+    public static final String[] VERBS = new String[] {" called ", " ended "};
+    private int state = 0;
+
+    public void complete() {
+        setTimestamp(System.currentTimeMillis());
+        state = 1;
+    }
 
     @Override
     public String toString() {
-        return user.trim() + " called " + operation + Arrays.toString((Object[])parameters.get("arguments")) + " at " + getFormattedTime();
+        return user.trim() + VERBS[state] + operation + Arrays.toString((Object[])parameters.get("arguments")) + " at " + getFormattedTime();
     }
 }

activemq-unit-tests/src/test/java/org/apache/activemq/jmx/JmxAuditLogTest.java

@@ -25,6 +25,8 @@ import javax.management.remote.JMXServiceURL;
 import java.util.HashMap;
 import java.util.Map;
 import java.util.concurrent.TimeUnit;
+import java.util.concurrent.atomic.AtomicBoolean;
+import java.util.concurrent.atomic.AtomicInteger;
 
 import org.apache.activemq.TestSupport;
 import org.apache.activemq.broker.BrokerService;
@@ -38,6 +40,7 @@ import org.apache.log4j.Logger;
 import org.apache.log4j.spi.LoggingEvent;
 import org.junit.Test;
 
+import static org.apache.activemq.broker.util.JMXAuditLogEntry.VERBS;
 import static org.apache.activemq.util.TestUtils.findOpenPort;
 
 public class JmxAuditLogTest extends TestSupport
@@ -55,7 +58,7 @@ public class JmxAuditLogTest extends TestSupport
       setMaxTestTime(TimeUnit.MINUTES.toMillis(10));
       setAutoFail(true);
 
-      System.setProperty("org.apache.activemq.audit", "true");
+      System.setProperty("org.apache.activemq.audit", "all");
 
       broker = new BrokerService();
       broker.setUseJmx(true);
@@ -113,6 +116,8 @@ public class JmxAuditLogTest extends TestSupport
    {
       Logger log4jLogger = Logger.getLogger("org.apache.activemq.audit");
       log4jLogger.setLevel(Level.INFO);
+      final AtomicInteger logCount = new AtomicInteger(0);
+      final AtomicBoolean gotEnded = new AtomicBoolean(false);
 
       Appender appender = new DefaultTestAppender()
       {
@@ -122,12 +127,17 @@ public class JmxAuditLogTest extends TestSupport
             if (event.getMessage() instanceof String)
             {
                String message = (String) event.getMessage();
+               System.out.println(message);
                if (message.contains("testPassword"))
                {
                   fail("Password should not appear in log file");
                }
+               if (message.contains(VERBS[1])) {
+                  gotEnded.set(true);
                }
             }
+            logCount.incrementAndGet();
+         }
       };
       log4jLogger.addAppender(appender);
 
@@ -139,5 +149,9 @@ public class JmxAuditLogTest extends TestSupport
 
       conn.invoke(queueObjName, "sendTextMessage", params, signature);
       log4jLogger.removeAppender(appender);
+
+      assertTrue("got ended statement", gotEnded.get());
+      assertEquals("got two messages", 2, logCount.get());
+
    }
 }