new: ThreadInspector - functionality to trace locks owned by thread

fix: EventDispatcher and subclasses logs locked mutexes in at "trace" level

fix: AdvLogger - use official "isEnabledFor" instead of custom function

src/main/java/net/ranides/assira/events/EventDispatcher.java

@@ -13,6 +13,8 @@ import java.util.Collections;
 import java.util.List;
 import net.ranides.assira.trace.AdvLogger;
 import net.ranides.assira.trace.LoggerUtils;
+import net.ranides.assira.trace.ThreadInspector;
+import org.apache.log4j.Level;
 
 /**
  * Beznarzutowy EventRouter, nie kolejkuje zdarzeń.
@@ -163,6 +165,7 @@ public class EventDispatcher implements EventRouter {
      */
     @Override
     public boolean signalEvent(Event event) {
+        ThreadInspector.logLocks(Level.TRACE, LOGGER);
         dispatchEvent(event);
         return true;
     }

src/main/java/net/ranides/assira/events/EventReactor.java

@@ -9,6 +9,10 @@ package net.ranides.assira.events;
 
 import java.util.concurrent.ArrayBlockingQueue;
 import java.util.concurrent.TimeUnit;
+import net.ranides.assira.trace.AdvLogger;
+import net.ranides.assira.trace.LoggerUtils;
+import net.ranides.assira.trace.ThreadInspector;
+import org.apache.log4j.Level;
 
 /**
  * EventRouter kolejkujący zdarzenia. Wywołuje procedury obsługi w bliżej
@@ -27,6 +31,8 @@ import java.util.concurrent.TimeUnit;
     "DLS_DEAD_LOCAL_STORE" // w klasie mamy kilka świadomie ignorowanych wartości catch(InterruptedException _ )
 })
 public class EventReactor extends EventDispatcher {
+    
+    private static final AdvLogger LOGGER = LoggerUtils.getLogger();
 
     private final ArrayBlockingQueue<Event> events;
     private final long maxtime;
@@ -171,6 +177,7 @@ public class EventReactor extends EventDispatcher {
      */
     @Override
     public boolean signalEvent(Event event) {
+        ThreadInspector.logLocks(Level.TRACE, LOGGER);
         if(0 == maxtime) {
             return events.offer(event);
         }

src/main/java/net/ranides/assira/trace/AdvLogger.java

@@ -31,37 +31,37 @@ public class AdvLogger extends org.apache.log4j.Logger {
 /* ************************************************************************** */
     
     public void ftrace(String format, Object... args) {
-        if( check(Level.TRACE) ) {
+        if( isEnabledFor(Level.TRACE) ) {
             forcedLog(ADV_FQCN, Level.TRACE, Strings.sprintf(format, args), null);
         }
     }
     
     public void fdebug(String format, Object... args) {
-        if( check(Level.DEBUG) ) {
+        if( isEnabledFor(Level.DEBUG) ) {
             forcedLog(ADV_FQCN, Level.DEBUG, Strings.sprintf(format, args), null);
         }
     }
     
     public void finfo(String format, Object... args) {
-        if( check(Level.INFO) ) {
+        if( isEnabledFor(Level.INFO) ) {
             forcedLog(ADV_FQCN, Level.INFO, Strings.sprintf(format, args), null);
         }
     }
     
     public void ferror(String format, Object... args) {
-        if( check(Level.ERROR) ) {
+        if( isEnabledFor(Level.ERROR) ) {
             forcedLog(ADV_FQCN, Level.ERROR, Strings.sprintf(format, args), null);
         }
     }
     
     public void ffatal(String format, Object... args) {
-        if( check(Level.FATAL) ) {
+        if( isEnabledFor(Level.FATAL) ) {
             forcedLog(ADV_FQCN, Level.FATAL, Strings.sprintf(format, args), null);
         }
     }
     
     public void fwarn(String format, Object... args) {
-        if( check(Level.WARN) ) {
+        if( isEnabledFor(Level.WARN) ) {
             forcedLog(ADV_FQCN, Level.WARN, Strings.sprintf(format, args), null);
         }
     }
@@ -69,37 +69,37 @@ public class AdvLogger extends org.apache.log4j.Logger {
 /* ************************************************************************** */
     
     public void xtrace(String format, Throwable cause, Object... args) {
-        if( check(Level.TRACE) ) {
+        if( isEnabledFor(Level.TRACE) ) {
             forcedLog(ADV_FQCN, Level.TRACE, Strings.sprintf(format, args), cause);
         }
     }
     
     public void xdebug(String format, Throwable cause, Object... args) {
-        if( check(Level.DEBUG) ) {
+        if( isEnabledFor(Level.DEBUG) ) {
             forcedLog(ADV_FQCN, Level.DEBUG, Strings.sprintf(format, args), cause);
         }
     }
     
     public void xinfo(String format, Throwable cause, Object... args) {
-        if( check(Level.INFO) ) {
+        if( isEnabledFor(Level.INFO) ) {
             forcedLog(ADV_FQCN, Level.INFO, Strings.sprintf(format, args), cause);
         }
     }
     
     public void xerror(String format, Throwable cause, Object... args) {
-        if( check(Level.ERROR) ) {
+        if( isEnabledFor(Level.ERROR) ) {
             forcedLog(ADV_FQCN, Level.ERROR, Strings.sprintf(format, args), cause);
         }
     }
     
     public void xfatal(String format, Throwable cause, Object... args) {
-        if( check(Level.FATAL) ) {
+        if( isEnabledFor(Level.FATAL) ) {
             forcedLog(ADV_FQCN, Level.FATAL, Strings.sprintf(format, args), cause);
         }
     }
     
     public void xwarn(String format, Throwable cause, Object... args) {
-        if( check(Level.WARN) ) {
+        if( isEnabledFor(Level.WARN) ) {
             forcedLog(ADV_FQCN, Level.WARN, Strings.sprintf(format, args), cause);
         }
     }
@@ -159,9 +159,9 @@ public class AdvLogger extends org.apache.log4j.Logger {
     public void warn(Object message) {
         logex(Level.WARN, message);
     }
-    
+  
     private void logex(Level level, Object message) {
-        if( check(level) ) {
+        if( isEnabledFor(level) ) {
             if(message instanceof Throwable) {
                 forcedLog(ADV_FQCN, level, TEXT_FOR_EXCEPTION, (Throwable)message);
             } else {
@@ -170,10 +170,6 @@ public class AdvLogger extends org.apache.log4j.Logger {
         }
     }
     
-    private boolean check(Level level) {
-        return !repository.isDisabled(level.toInt()) && level.isGreaterOrEqual(getEffectiveLevel());
-    }
-    
 /* ************************************************************************** */
     
     public void trace() {

src/main/java/net/ranides/assira/trace/ThreadInspector.java

@@ -0,0 +1,100 @@
+/*
+ * @author Ranides Atterwim <ranides@gmail.com>
+ * @copyright Ranides Atterwim
+ * @license WTFPL
+ * @url http://ranides.net/projects/assira
+ */
+package net.ranides.assira.trace;
+
+import java.io.PrintStream;
+import java.lang.management.LockInfo;
+import java.lang.management.ManagementFactory;
+import java.lang.management.MonitorInfo;
+import java.lang.management.ThreadInfo;
+import java.lang.management.ThreadMXBean;
+import org.apache.log4j.Level;
+
+/**
+ *
+ * @author Ranides Atterwim <ranides@gmail.com>
+ */
+public final class ThreadInspector {
+    
+    private static final String FQCN = ThreadInspector.class.getName();
+    
+    private ThreadInspector() {
+        // utility class
+    }
+    
+    public static ThreadInfo currentInfo() {
+        long[] cid = new long[]{ Thread.currentThread().getId() };
+        return Li.THREAD_INFO.getThreadInfo(cid, true, true)[0];
+    }
+    
+    public static void printLocks(PrintStream stream) {
+        ThreadInfo info = currentInfo();
+        stream.format("THREAD: %s 0x%08X%n", 
+            info.getThreadName(), 
+            info.getThreadId()
+        );
+        for(MonitorInfo item : info.getLockedMonitors()) {
+            stream.format(" - MONITOR : %s 0x%08X @ %s%n",
+                item.getClassName(),
+                item.getIdentityHashCode(),
+                item.getLockedStackFrame()
+            );
+        }
+        
+        for(LockInfo item : info.getLockedSynchronizers()) {
+            stream.format(" - LOCK : %s 0x%08X%n", 
+                item.getClassName(), 
+                item.getIdentityHashCode()
+            );
+        }
+        
+    }
+    
+    public static void logLocks(Level level, AdvLogger logger) {
+        if( !logger.isEnabledFor(level) ) {
+            return;
+        }
+        ThreadInfo info = currentInfo();
+        
+        if( 0 == info.getLockedMonitors().length && 0 == info.getLockedSynchronizers().length ) {
+            return;
+        }
+
+        logger.log(FQCN, level, String.format("THREAD: %s 0x%08X", 
+            info.getThreadName(), 
+            info.getThreadId()
+        ),null);
+        for(MonitorInfo item : info.getLockedMonitors()) {
+            logger.log(FQCN, level, String.format("MONITOR : %s 0x%08X @ %s",
+                item.getClassName(),
+                item.getIdentityHashCode(),
+                item.getLockedStackFrame()
+            ),null);
+        }
+        
+        for(LockInfo item : info.getLockedSynchronizers()) {
+            logger.log(FQCN, level, String.format("LOCK : %s 0x%08X", 
+                item.getClassName(), 
+                item.getIdentityHashCode()
+            ),null);
+        }
+        
+    }
+    
+    public static int countLocks() {
+        ThreadInfo info = currentInfo();
+        return
+            info.getLockedMonitors().length +
+            info.getLockedSynchronizers().length;
+    }
+    
+    private static final class Li { // NOPMD lazy init idiom 
+        
+        public static final ThreadMXBean THREAD_INFO = ManagementFactory.getThreadMXBean();
+    }
+    
+}

src/test/java/net/ranides/assira/trace/ThreadInspectorTest.java

@@ -0,0 +1,84 @@
+/*
+ * @author Ranides Atterwim <ranides@gmail.com>
+ * @copyright Ranides Atterwim
+ * @license WTFPL
+ * @url http://ranides.net/projects/assira
+ */
+package net.ranides.assira.trace;
+
+import org.apache.log4j.Level;
+import org.junit.Test;
+import static org.junit.Assert.*;
+import org.junit.Ignore;
+
+/**
+ *
+ * @author Ranides Atterwim <ranides@gmail.com>
+ */
+@SuppressWarnings({
+    "all",
+    "PMD",
+    "NestedSynchronizedStatement"
+})
+public class ThreadInspectorTest {
+    
+    private static final AdvLogger LOGGER = LoggerUtils.getLogger();
+    
+    public ThreadInspectorTest() {
+        LoggerUtils.initTest();
+    }
+    
+    @Test
+    public void testCount() {
+        synchronized(new Lock1()) {
+            synchronized(new Lock2()) {
+                assertEquals(3,itestCount());
+            }
+        }
+    }
+    
+    private int itestCount() {
+        synchronized(new Lock3()) {
+            return ThreadInspector.countLocks();
+        }
+    }
+
+    @Ignore("manual")
+    @Test
+    public void testDump() {
+        synchronized(new Lock1()) {
+            synchronized(new Lock2()) {
+                itestDump();
+            }
+        }
+        assertTrue(true);
+    }
+    
+    private void itestDump() {
+        synchronized(new Lock3()) {
+            ThreadInspector.printLocks(System.out);
+        }
+    }
+    
+    @Ignore("manual")
+    @Test
+    public void testTrace() {
+        synchronized(new Lock1()) {
+            synchronized(new Lock2()) {
+                itestTrace();
+            }
+        }
+        assertTrue(true);
+    }
+    
+    private void itestTrace() {
+        synchronized(new Lock3()) {
+            ThreadInspector.logLocks(Level.DEBUG, LOGGER);
+        }
+    }
+    
+    private static class Lock1 { }
+    private static class Lock2 { }
+    private static class Lock3 { }
+    
+}