Logging problems encountered

[si...@insession.com]

I have been experiencing some problems with the geronimo.log file losing 
data. 

I tracked it down to be a combination of me customising 
server-log4j.properties so that  log4j.appender.FILE.append=false was 
specified, and an EJB application that uses log4j.  I have included my 
observations below for future reference and comment. 

1) Geronimo is started.  The static initialisation in the Daemon class 
causes a console logger to be set up.

2) org.apache.geronimo.system.logging.log4j.Log4jService.doStart() is 
called that:

a) starts a timer that will be schedules every 60 seconds for checking 
changes to the server-log4j.properties file.
b) calls 
org.apache.geronimo.system.logging.log4j.Log4jService.reconfigure() which 
causes the server-log4j.properties to be read and the geronimo.log file to 
be opened.

3) An EJB that is loaded from the configuration has its static initialiser 
invoked, which in turn in the application code calls 
org.apache.log4j.PropertyConfigurator.configure(java.util.Properties). 
This results in all log appenders being removed, therefore geronimo.log 
gets closed.  The EJB's static initialisation added its own appender / log 
file, e.g. myApp.log.  At this point it appears we are not logging to 
geronimo.log.

Thread [main] (Suspended (breakpoint at line 171 in 
org.apache.log4j.FileAppender))
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.FileAppender).closeFile() 
line: 171
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.FileAppender).reset() 
line: 302
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.WriterAppender).close() 
line: 195
 org.apache.log4j.helpers.AppenderAttachableImpl.removeAllAppenders() 
line: 132
 
org.apache.log4j.spi.RootCategory(org.apache.log4j.Category).removeAllAppenders() 
line: 879
 org.apache.log4j.PropertyConfigurator.parseCategory(java.util.Properties, 
org.apache.log4j.Logger, java.lang.String, java.lang.String, 
java.lang.String) line: 594
 
org.apache.log4j.PropertyConfigurator.configureRootCategory(java.util.Properties, 
org.apache.log4j.spi.LoggerRepository) line: 500
 org.apache.log4j.PropertyConfigurator.doConfigure(java.util.Properties, 
org.apache.log4j.spi.LoggerRepository) line: 406
 org.apache.log4j.PropertyConfigurator.configure(java.util.Properties) 
line: 340
        <snip>
        com.blah.server.ejb.ServerConfigPvtBean.<clinit>() line: not 
available
        java.io.ObjectStreamClass.hasStaticInitializer(java.lang.Class) 
line: not available [native method]
        java.io.ObjectStreamClass.computeDefaultSUID(java.lang.Class) 
line: 1557
        java.io.ObjectStreamClass.access$100(java.lang.Class) line: 47
        java.io.ObjectStreamClass$1.run() line: 173
 
java.security.AccessController.doPrivileged(java.security.PrivilegedAction) 
line: not available [native method]
        java.io.ObjectStreamClass.getSerialVersionUID() line: 170
        java.io.ObjectStreamClass.initNonProxy(java.io.ObjectStreamClass, 
java.lang.Class, java.lang.ClassNotFoundException, 
java.io.ObjectStreamClass) line: 459
                <snip>
 
org.apache.geronimo.kernel.ObjectInputStreamExt(java.io.ObjectInputStream).readObject() 
line: 324
 org.apache.geronimo.gbean.GBeanData.readExternal(java.io.ObjectInput) 
line: 169
        org.apache.geronimo.kernel.config.Configuration.loadGBeans(byte[], 
java.lang.ClassLoader) line: 388
        org.apache.geronimo.kernel.config.Configuration.<init>(...) line: 
208
 
sun.reflect.NativeConstructorAccessorImpl.newInstance0(java.lang.reflect.Constructor, 
java.lang.Object[]) line: not available [native method]
 sun.reflect.NativeConstructorAccessorImpl.newInstance(java.lang.Object[]) 
line: 39
 
sun.reflect.DelegatingConstructorAccessorImpl.newInstance(java.lang.Object[]) 
line: 27
        java.lang.reflect.Constructor.newInstance(java.lang.Object[]) 
line: 274
        org.apache.geronimo.gbean.runtime.GBeanInstance.createInstance() 
line: 806
 org.apache.geronimo.gbean.runtime.GBeanInstanceState.attemptFullStart() 
line: 331
        org.apache.geronimo.gbean.runtime.GBeanInstanceState.start() line: 
111
 org.apache.geronimo.gbean.runtime.GBeanInstanceState.startRecursive() 
line: 133
        org.apache.geronimo.gbean.runtime.GBeanInstance.startRecursive() 
line: 494
 
org.apache.geronimo.kernel.Kernel.startRecursiveGBean(javax.management.ObjectName) 
line: 339
        org.apache.geronimo.system.main.Daemon.main(java.lang.String[]) 
line: 185

4) The Timer started by the Log4jService earlier, is executed and 
reconfigures log4j, causing all appenders to be removed, therefore 
myApp.log is closed.  Then geronimo.log will be reopened.  If 
log4j.appender.FILE.append=false was specified in server-log4j.properties, 
then any existing data in geronimo.log is erased.

Thread [Thread-1] (Suspended (breakpoint at line 171 in 
org.apache.log4j.FileAppender))
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.FileAppender).closeFile() 
line: 171
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.FileAppender).reset() 
line: 302
 
org.apache.log4j.RollingFileAppender(org.apache.log4j.WriterAppender).close() 
line: 195
 org.apache.log4j.helpers.AppenderAttachableImpl.removeAllAppenders() 
line: 132
 
org.apache.log4j.spi.RootCategory(org.apache.log4j.Category).removeAllAppenders() 
line: 879
 org.apache.log4j.PropertyConfigurator.parseCategory(java.util.Properties, 
org.apache.log4j.Logger, java.lang.String, java.lang.String, 
java.lang.String) line: 594
 
org.apache.log4j.PropertyConfigurator.configureRootCategory(java.util.Properties, 
org.apache.log4j.spi.LoggerRepository) line: 500
 org.apache.log4j.PropertyConfigurator.doConfigure(java.util.Properties, 
org.apache.log4j.spi.LoggerRepository) line: 406
        org.apache.log4j.PropertyConfigurator.doConfigure(java.net.URL, 
org.apache.log4j.spi.LoggerRepository) line: 432
 
org.apache.geronimo.system.logging.log4j.URLConfigurator.doConfigure(java.net.URL, 
org.apache.log4j.spi.LoggerRepository) line: 117
 
org.apache.geronimo.system.logging.log4j.URLConfigurator.configure(java.net.URL) 
line: 44
 org.apache.geronimo.system.logging.log4j.Log4jService.reconfigure() line: 
306
 
org.apache.geronimo.system.logging.log4j.Log4jService$URLMonitorTask.run() 
line: 411
        java.util.TimerThread.mainLoop() line: 432
        java.util.TimerThread.run() line: 382

John

The preceding e-mail message (including any attachments) contains 
information that may be confidential or constitute non-public information. 
 The information is intended only for the designated recipient(s).  If an 
addressing or transmission error has misdirected this e-mail, please 
notify the sender immediately and destroy this e-mail.  Any review, 
dissemination, use or reliance upon this information by unintended 
recipients is prohibited.  Any opinions expressed in this e-mail are those 
of the author personally.