Log4j configureAndWatch() spawning thousands of threads

Question

So we have our J2EE application using Log4j like this

public class CustomerController 
{
    private static Logger logger = Logger.getLogger(CustomerController.class);

     public CustomerService customerservice = null;

     public CustomerController() throws Exception 
     {
        PropertyConfigurator.configureAndWatch("c:\log4j.property", 50000);

         customerservice = ServiceManagerSingleton.getCustomerServiceInstance();
     }
}

This way we can change the log-level realtime. Very handy. Most of our classes are set up just like this controller. We use the singleton-pattern so that we only have one instance of eash class; one call to PropertyConfigurator.configureAndWatch() for each class, once.

The problem: About twice a week our appserver dies and creates a heapdump. Using Heap Analyzer from IBM we can see that there seems to be alot of threads related to Log4j:

 808 (0%) [200] 9 org/apache/log4j/PropertyWatchdog 0x14282ad8

About 30,000 in total. So this is probably the reason for the sudden crash.

1. Are we setting this up correctly?
2. What happens to all those threads when the EAR is redeployed?

Answer 1

Really what you need to do here is use the startup procedure of your application server (they are all different) to initialize the log4j system. Because Log4j relies on static variables, it can't really work independently in its own ear (it kind of can, but that will really depend on the application server). In most cases the configuration is really going to be global for the whole application server.

You need to be sure that the PropertyConfigurator.configureAndWatch method is only called once. One way to do that is to put something in JNDI.

A lot of this is going to depend on what the application server is giving you. For example, we use JBoss, and Log4J is configured as part of it, and you just change the log4j.xml file to include what your classes need. JBoss ensures that it is done dynamically.

EDIT: Here are the instructions for Websphere to create a custom service, and inside that you would create your log4J configuration, and do your monitoring of the file. A couple of caveats. You are going to have to add the log4j.jar to the classpath of the application server itself, so that it is available to the war or ear (I'm pretty sure that will work, anyway), and the custom service will likely not work inside the ear.

Here is an alternative that will keep everything in the war or ear, but at the expense of dynamically loading log changes.

Answer 2

How often are CustomerController instances created? Once per request? Because I believe that configureAndWatch() will spawn a new thread with each call.

Also, if you are not aware, the log4j docs caution against using this feature in a J2EE environment:

Because the configureAndWatch launches a separate wathdog thread, and because there is no way to stop this thread in log4j 1.2, the configureAndWatch method is unsafe for use in J2EE environments where applications are recycled.

I know you are not using Spring but in my opinion the Spring class Log4jWebConfigurer has a better explanation about why this feature is dangerous in J2EE:

WARNING: Log4j's watchdog thread does not terminate until VM shutdown; in particular, it does not terminate on LogManager shutdown. Therefore, it is recommended to not use config file refreshing in a production J2EE environment; the watchdog thread would not stop on application shutdown there.

Update: Looking at log4j source, each call to configureAndWatch() does indeed create a new thread.

Answer 3

Have you looked at logback, log4j successor? It deals with reloading its configuration either in thread or via JMX. Both approaches avoid the headaches caused by calling PropertyConfigurator.configureandWatch() or DOMConfigurator.configurator. Just as interestingly, the in thread approach enabled via a configuration file (no custom code needed).

Answer 4

All Loggers share the same configuration file, so if every class that uses a logger contains this intialization code, each configureAndWatch() call will likely spawn a new watcher thread. (IMHO, Log4j should know better and allow for at most one watcher Thread per configuration file, but apparently it doesn't)