From d7f70837b7e80d41e45362c1327f4d9af25335e1 Mon Sep 17 00:00:00 2001 From: gtully Date: Mon, 10 Jul 2017 14:10:05 +0100 Subject: [PATCH] [AMQ-6764] add logging of exit of jmx ops such that overlaps and delays are visible in the audit. fix and test --- .../activemq/broker/jmx/AnnotatedMBean.java | 39 ++++++++++++++++--- .../broker/util/JMXAuditLogEntry.java | 9 ++++- .../apache/activemq/jmx/JmxAuditLogTest.java | 16 +++++++- 3 files changed, 56 insertions(+), 8 deletions(-) diff --git a/activemq-broker/src/main/java/org/apache/activemq/broker/jmx/AnnotatedMBean.java b/activemq-broker/src/main/java/org/apache/activemq/broker/jmx/AnnotatedMBean.java index aa8e8ab3a3..c75d8a81bb 100644 --- a/activemq-broker/src/main/java/org/apache/activemq/broker/jmx/AnnotatedMBean.java +++ b/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")); - if (audit) { + audit = byteFromProperty("org.apache.activemq.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); + } + } + Object result = super.invoke(s, objects, strings); + if ((audit&EXIT) == EXIT) { + entry.complete(); auditLog.log(entry); } - return super.invoke(s, objects, strings); + return result; } private Method getMBeanMethod(Class clazz, String methodName, String[] signature) throws ReflectiveOperationException { diff --git a/activemq-broker/src/main/java/org/apache/activemq/broker/util/JMXAuditLogEntry.java b/activemq-broker/src/main/java/org/apache/activemq/broker/util/JMXAuditLogEntry.java index 42517569c4..7e0e0e3da5 100644 --- a/activemq-broker/src/main/java/org/apache/activemq/broker/util/JMXAuditLogEntry.java +++ b/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(); } } diff --git a/activemq-unit-tests/src/test/java/org/apache/activemq/jmx/JmxAuditLogTest.java b/activemq-unit-tests/src/test/java/org/apache/activemq/jmx/JmxAuditLogTest.java index 0f2695c6da..e6f1083013 100644 --- a/activemq-unit-tests/src/test/java/org/apache/activemq/jmx/JmxAuditLogTest.java +++ b/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,11 +127,16 @@ 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()); + } }