Why does a java.util.Logger in a ShutdownHook within JBoss 5.1 not always prints to server.log?

Question

I have a EJB3-Timer within a JBoss 5.1. edit: The ShutdownHook should set a flag, that the doTimeOut() can terminate graceful (otherwise it would complete the job, and the shutdown is stopped until this timer has finished).

@Stateless
class Timer {
    private static Thread hook;
    static {
       hook = new ShutdownHook();
    }
    @Timeout
    public void doTimeOut(){
       //some code
    }

    private class ShutdownHook implements Runnable(){

        Logger.getLogger(ShutdownHook.class.getName()).log(Level.INFO, "MyBEAN.ShutdownHook execute hook " + hook); // Not always printed to log
        Logger.getAnonymousLogger().log(Level.INFO, "MyBEAN.ShutdownHook execute hook " + hook); // throwns Exception
        System.out.println("MyBEAN.ShutdownHook execute hook " + hook);
        [...] // some code
    }
}

I've found this two posts, but they are from 2005 and the bug is marked as CLOSED:

http://www.pankaj-k.net/archives/2005/08/jboss_shutdown.html

http://jira.jboss.com/jira/browse/JBAS-2087

The Exception thrown by the anonymousLogger is a NullPointer:

2011-02-02 09:16:33,120 ERROR [STDERR] Exception in thread "Thread-33" 
2011-02-02 09:16:33,122 ERROR [STDERR] java.lang.NullPointerException
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.apache.log4j.CategoryKey.<init>(CategoryKey.java:31)
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:261)
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.apache.log4j.Hierarchy.getLogger(Hierarchy.java:242)
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.apache.log4j.LogManager.getLogger(LogManager.java:188)
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.apache.log4j.Logger.getLogger(Logger.java:104)
2011-02-02 09:16:33,122 ERROR [STDERR]  at org.jboss.logbridge.LogBridgeHandler.publish(LogBridgeHandler.java:71)
2011-02-02 09:16:33,122 ERROR [STDERR]  at java.util.logging.Logger.log(Unknown Source)
2011-02-02 09:16:33,122 ERROR [STDERR]  at java.util.logging.Logger.doLog(Unknown Source)
2011-02-02 09:16:33,122 ERROR [STDERR]  at java.util.logging.Logger.log(Unknown Source)
2011-02-02 09:16:33,122 ERROR [STDERR]  at com.demo.MyBEAN$ShutdownHook.run(MyBEAN.java:202)

Any ideas?

Answer 1

The logger might not be available since Log4j has shut down, which obviously happens before the JVM shutdown hook is run. If you need to log something at shutdown, I suggest you hook into the JBoss mechanisms , for instance using @PreDestroy.

Your code then becomes

@Stateless
class Timer {

    @Timeout
    public void doTimeOut(){
       //some code
    }

    @PreDestroy
    public void onShutdown() {

        Logger.getLogger(Timer.class.getName()).log(Level.INFO, "MyBEAN.ShutdownHook execute hook " + hook);
        [...] // some code
    }
}