Logging on a Per-Thread Basis

As far as I know, most of the logging facility configurations enable you to specify the maximum size of a log file, how many will roll, where data is fed to and eventually dispatching multiple destinations in function of the log level. I've found nothing (apart from a couple of discussions on java.net forums) about splitting logs in function of the thread - that is, all the logging from a thread goes in a file and the logging from another thread goes in another file.

Why should one do that? I'm not thinking of production, but about testing - precisely parallel testing, and now I think you've got the point. Well-written tests are completely independent of each other, thus there's no point in looking at a global sequence of events - instead, you want to consider each one as an independent sequence of events.

So, here is my solution: a custom java.util.logging.Handler that dispatches to multiple FileHandlers in function of the ThreadGroup.

package it.tidalwave.thesefoolishthings.junit;

import javax.annotation.Nonnull;
import java.util.HashMap;
import java.util.Map;
import java.util.logging.FileHandler;
import java.util.logging.Handler;
import java.util.logging.LogRecord;
import java.io.IOException;

public class MultiThreadHandler extends Handler
  {
    private static final Handler VOID_HANDLER = new Handler()
      {
        @Override
        public void publish (final LogRecord logRecord)
          {
          }

        @Override
        public void flush()
          {
          }

        @Override
        public void close()
          {
          }
      };
    
    private static final Map<ThreadGroup, String> LOG_NAME_MAP = new HashMap<ThreadGroup, String>();
    
    private final Map<String, Handler> handlerMap = new HashMap<String, Handler>();

    protected String directory = "target/logs";

    public static void setLogName (final @Nonnull String name)
      {
        LOG_NAME_MAP.put(Thread.currentThread().getThreadGroup(), name);
      }

    public static void resetLogName()
      {
        LOG_NAME_MAP.remove(Thread.currentThread().getThreadGroup());
      }

    public void setDirectory (final String directory)
      {
        this.directory = directory;
      }

    public String getDirectory()
      {
        return directory;
      }

    @Override
    public void publish (final @Nonnull LogRecord logRecord)
      {
        getHandler().publish(logRecord);
      }

    @Override
    public void flush()
      {
        getHandler().flush();
      }

    @Override
    public void close() 
      throws SecurityException
      {
        getHandler().close();
      }

    @Nonnull
    private synchronized Handler getHandler()
      {
        final String id = LOG_NAME_MAP.get(Thread.currentThread().getThreadGroup());

        if (id == null)
          {
            return VOID_HANDLER;
          }

        Handler handler = handlerMap.get(id);

        if (handler == null)
          {
            try
              {
                final String fileName = id.replace(':', '_').replace('/', '_').replace('[', '_').replace(']', '_').replace(' ', '_');
                handler = new FileHandler(String.format("%s/log-%s.log", directory, fileName));
                handler.setFormatter(getFormatter());
                handlerMap.put(id, handler);
              }
            catch (IOException e)
              {
                e.printStackTrace();
              }
            catch (SecurityException e)
              {
                e.printStackTrace();
              }
          }

        return (handler != null) ? handler : VOID_HANDLER;
      }
  }

The test (or the facility running the tests) should call the static method setTestName() which will be associated to the current ThreadGroup; from now on, all the logging generated by the current thread and its children (hence the need for the ThreadGroup) will go to that file. The ThreadGroup association to the file name is done by hand - I think I've sometimes seen a ThreadGroupLocal class, but I couldn't find anything with Google. A real ThreadGroupLocal would be more sophisticated, but a simple Map is good for my purpose.

It can be used, for instance, with this configuration file:

handlers=java.util.logging.FileHandler, it.tidalwave.thesefoolishthings.junit.MultiThreadHandler

java.util.logging.FileHandler.level = ALL
java.util.logging.FileHandler.pattern = target/logs/jrawio.log
java.util.logging.FileHandler.limit = 10000000
java.util.logging.FileHandler.count = 20
java.util.logging.FileHandler.formatter = it.tidalwave.imageio.SingleLineLogFormatter

java.util.logging.ConsoleHandler.level = ALL
java.util.logging.ConsoleHandler.formatter = it.tidalwave.imageio.SingleLineLogFormatter

it.tidalwave.thesefoolishthings.junit.MultiThreadHandler.level = ALL
it.tidalwave.thesefoolishthings.junit.MultiThreadHandler.directory = target/logs
it.tidalwave.thesefoolishthings.junit.MultiThreadHandler.formatter = it.tidalwave.imageio.SingleLineLogFormatter

For the record, I wasn't able to have the 'directory' property actually set by the configuration file - frankly I just supposed that one could set properties by standard JavaBean conventions, but I'm not sure. There are a few things to finish, but it can be used - actually, I've tried with a home-made JUnit parallel test runner and seems to work. I'll blog later about the parallel test runner as there are still issues and I'm not sure whether they are due to the parallel runner or to some code under test with a few not-thread-safe sections.