betweenGo

Brian Ploetz sent me this great unit test for threaded logging.  In it we are trying to find if a deadlock occurs.

import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;

import junit.framework.TestCase;

import org.apache.commons.logging.Log;
import org.apache.commons.logging.LogFactory;
import org.apache.log4j.Appender;
import org.apache.log4j.Logger;

/**
 * Unit test for the ThrottlingFilter in a multi-threaded environment
 */
public class ThrottlingFilterThreadUTest extends TestCase {

  private static final Log logger = LogFactory.getLog(ThrottlingFilterThreadUTest.class);

  private static ThreadMXBean threadMXBean;

  @Override
  protected void setUp() throws Exception {
    super.setUp();
    threadMXBean = ManagementFactory.getThreadMXBean();
    logger.info("Thread contention monitoring supported: "
        + threadMXBean.isThreadContentionMonitoringSupported());
    logger.info("Thread contention monitoring enabled: "
        + threadMXBean.isThreadContentionMonitoringEnabled());
    threadMXBean.setThreadContentionMonitoringEnabled(true);
    logger.info("Thread contention monitoring enabled: "
        + threadMXBean.isThreadContentionMonitoringEnabled());
  }

  /**
   * Tests multiple threads using the same filter instance at the same time
   */
  public void testThreads() {
    Logger rootLogger = Logger.getRootLogger();
    assertNotNull(rootLogger);
    Appender fileAppender = rootLogger.getAppender("FILE");
    assertNotNull(fileAppender);
    ThrottlingFilter throttlingFilter = (ThrottlingFilter) fileAppender.getFilter();
    assertNotNull(throttlingFilter);

    ThreadGroup infoThreadGroup = new ThreadGroup("info-group");
    ThreadGroup errorThreadGroup = new ThreadGroup("error-group");
    Thread errorThread1 = new ErrorThread(errorThreadGroup, "error-thread-1");
    Thread infoThread1 = new InfoThread(infoThreadGroup, "info-thread-1");
    Thread errorThread2 = new ErrorThread(errorThreadGroup, "error-thread-2");
    Thread infoThread2 = new InfoThread(infoThreadGroup, "info-thread-2");
    infoThread1.start();
    errorThread1.start();
    errorThread2.start();
    infoThread2.start();

    while (true) {
      ThreadInfo[] threadInfos = threadMXBean.getThreadInfo(threadMXBean.getAllThreadIds());
      for (int i = 0; i < threadInfos.length; i++) {
        ThreadInfo threadInfo = threadInfos[i];
        if (threadInfo != null && threadInfo.getThreadState() == Thread.State.BLOCKED) {
          System.out.println("Thread '" + threadInfo.getThreadName()
              + "' is blocked on the monitor lock '" + threadInfo.getLockName()
              + "' held by thread '" + threadInfo.getLockOwnerName() + "'");
        }
      }

      if (!infoThread1.isAlive() && !errorThread1.isAlive() && !infoThread2.isAlive()
          && !errorThread2.isAlive())
        break;
    }
  }

  public static class ErrorThread extends Thread {

    private static final Log logger = LogFactory.getLog(ErrorThread.class);

    public ErrorThread(ThreadGroup tg, String name) {
      super(tg, name);
    }

    public void run() {
      for (int i = 0; i < 10; i++) {
        try {
          test(0);
        } catch (Exception e) {
          long start = System.currentTimeMillis();
          logger.error("Error!", e);
          long end = System.currentTimeMillis();
          System.out.println("Took " + (end-start) + "ms to log error");
        }
      }
    }

    // simulate large stack traces
    private void test(int i) {
      if (i >= 500)
        throw new RuntimeException("D'OH!");
      test(i+1);
    }
  }

  public static class InfoThread extends Thread {

    private static final Log logger = LogFactory.getLog(InfoThread.class);

    public InfoThread(ThreadGroup tg, String name) {
      super(tg, name);
    }

    public void run() {
      for (int i = 0; i < 100; i++) {
        logger.info("Hi!");
      }
    }
  }
}

The log4j.xml test file.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/"
    debug="false">

    <!-- ================================= -->
    <!--           Appenders               -->
    <!-- ================================= -->

    <!-- A time/date based rolling file appender -->
    <appender name="FILE"
        class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="server.log" />
        <param name="Append" value="true" />

        <!-- Rollover at midnight each day -->
        <param name="DatePattern" value="'.'yyyy-MM-dd" />

        <layout class="org.apache.log4j.PatternLayout">
            <!-- The default pattern: Date Priority [Category] Message\n -->
            <param name="ConversionPattern" value="%d %-5p [%c] %m%n" />
        </layout>

        <filter class="com.betweengo.log4j.ThrottlingFilter">
          <param name="maxCountSameMessage" value="100"/>
          <param name="maxCountSavedMessages" value="100"/>
          <param name="waitInterval" value="60"/>
        </filter>
    </appender>

    <!-- ======================= -->
    <!-- Setup the Root category -->
    <!-- ======================= -->

    <root>
        <level value="INFO" />
        <appender-ref ref="FILE" />
    </root>

</log4j:configuration>

In JBoss 4.0.4.GA it took me awhile to figure out how to enable trace level debugging.

Typically you could do something like this to enable trace level debugging for a category of classes.

<category  name="com.betweengo.app">
  <priority  value="TRACE"/>
</category>

However JBoss 4.0.4.GA has an older log4j implementation so you need to use JBoss’s custom TRACE level.

<category  name="com.betweengo.app">
  <priority  value="TRACE" class="org.jboss.logging.XLevel"/>
</category>

This is documented in the release notes for JBoss-4.2.1.GA.

Since the latest log4j includes a trace level, there is no need to reference the custom jboss TRACE level in conf/jboss-log4j.xml configs, JBAS-4163.

There is additional information on trace level debugging in the articles Enabling TRACE logging on server and Using Logging.

I always forget which level is which in Log4j so I copied this from the JavaDoc for the Level class.

Edit the log4j.xml in the conf directory as shown below to turn on SQL debugging of the JDBC CMP plugin.

/apps/jboss/server/default/conf :->diff -c log4j.xml~ log4j.xml
*** log4j.xml~  Mon Sep 30 18:09:27 2002
--- log4j.xml   Tue Apr  4 20:41:18 2006
***************
*** 61,73 ****
    <!-- ============================== -->

    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
!     <param name="Threshold" value="INFO"/>
      <param name="Target" value="System.out"/>

      <layout class="org.apache.log4j.PatternLayout">
        <!-- The default pattern: Date Priority [Category] Message\\n -->
        <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>

      </layout>
    </appender>

--- 61,79 ----
    <!-- ============================== -->

    <appender name="CONSOLE" class="org.apache.log4j.ConsoleAppender">
!     <!--<param name="Threshold" value="INFO"/>-->
!     <param name="Threshold" value="DEBUG"/>
      <param name="Target" value="System.out"/>

      <layout class="org.apache.log4j.PatternLayout">
        <!-- The default pattern: Date Priority [Category] Message\\n -->
        <param name="ConversionPattern" value="%d{ABSOLUTE} %-5p [%c{1}] %m%n"/>

      </layout>
+
+     <category name="org.jboss.ejb.plugins.cmp.jdbc">
+       <priority value="DEBUG"/>
+     </category>
+
    </appender>

If you want to log Hibernate SQL statements:

    <category name="org.hibernate.SQL">
      <priority value="DEBUG"/>
    </category>

If you want to log everything Hibernate’s doing, including SQL statements, schema export, transactions, etc.:

    <category name="org.hibernate.SQL">
      <priority value="DEBUG"/>
    </category>