Unit Test for Threaded Logging

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;

  protected void setUp() throws Exception {
    threadMXBean = ManagementFactory.getThreadMXBean();
    logger.info("Thread contention monitoring supported: "
        + threadMXBean.isThreadContentionMonitoringSupported());
    logger.info("Thread contention monitoring enabled: "
        + threadMXBean.isThreadContentionMonitoringEnabled());
    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();
    Appender fileAppender = rootLogger.getAppender("FILE");
    ThrottlingFilter throttlingFilter = (ThrottlingFilter) fileAppender.getFilter();

    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");

    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())

  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 {
        } 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!");

  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++) {

The log4j.xml test file.








Enabling Trace Level Debugging in JBoss

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.


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


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.

Log4j levels

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

static Level ALL
The ALL has the lowest possible rank and is intended to turn on all logging.
static Level DEBUG
The DEBUG Level designates fine-grained informational events that are most useful to debug an application.
static Level ERROR
The ERROR level designates error events that might still allow the application to continue running.
static Level FATAL
The FATAL level designates very severe error events that will presumably lead the application to abort.
static Level INFO
The INFO level designates informational messages that highlight the progress of the application at coarse-grained level.
static Level OFF
The OFF has the highest possible rank and is intended to turn off logging.
static Level TRACE
The TRACE Level designates finer-grained informational events than the DEBUG
static Level WARN
The WARN level designates potentially harmful situations.

How to Log SQL on JBoss

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 ****




--- 61,79 ----




If you want to log Hibernate SQL statements:


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