Bug 9750

Summary: Using AsynchAppender in logging configuration prevents virtual machine from exiting
Product: Log4j - Now in Jira Reporter: Sean Reilly <sreilly>
Component: AppenderAssignee: log4j-dev <log4j-dev>
Status: RESOLVED FIXED    
Severity: minor    
Priority: P3    
Version: 1.2   
Target Milestone: ---   
Hardware: PC   
OS: All   
Attachments: java source code that reproduces the issue
log4j config that causes the console to hang
log4j config that causes the console not to hand
log4j jar file used in test case (log4j.jar from v 1.2.3)
log4j.dtd used in test runs (from v 1.2.3)

Description Sean Reilly 2002-06-10 17:38:09 UTC
I am using log4j to provide logging for a tomcat web application.
I am initializing log4j as described in 
http://jakarta.apache.org/log4j/docs/manual.html :

I am placing log4j.jar in WEB-INF/lib
I am placing log4jconfig.xml in WEB-INF/classes
and I am specifing the system property log4j.configuration=log4jconfig.xml
when starting the servlet container.

Normally I can start tomcat, perform a few simple operations that create log 
entries, and shutdown tomcat properly (remote connection triggers process end).

However, when I use a configuration that includes an AsynchAppender, different 
behaviour occurs.  Tomcat starts as normal, the program progress and log 
entries happen as normal, but when tomcat is shut down, the virtual machine 
does not end.

I have been able to reproduce this problem with a very simple test case, which 
I will attach shortly.
Comment 1 Sean Reilly 2002-06-10 17:39:06 UTC
Created attachment 2049 [details]
java source code that reproduces the issue
Comment 2 Sean Reilly 2002-06-10 17:39:41 UTC
Created attachment 2050 [details]
log4j config that causes the console to hang
Comment 3 Sean Reilly 2002-06-10 17:40:05 UTC
Created attachment 2051 [details]
log4j config that causes the console not to hand
Comment 4 Sean Reilly 2002-06-10 17:41:06 UTC
Created attachment 2052 [details]
log4j jar file used in test case (log4j.jar from v 1.2.3)
Comment 5 Sean Reilly 2002-06-10 17:41:42 UTC
Created attachment 2053 [details]
log4j.dtd used in test runs (from v 1.2.3)
Comment 6 Sean Reilly 2002-06-10 17:45:29 UTC
This test case was compiled and run using JDK1.4
It should run in earlier versions with the addition of an xml parser.

compiled with "javac -classpath log4j.jar Test.java"
the nohang case is run with "%JAVA_HOME_14%\bin\java -cp log4j.jar;. -
Dlog4j.configuration=log4jconfig_nohang.xml Test"

it generated the following output:
2002-06-10 11:36:59,874: DEBUG (test)  - starting
2002-06-10 11:36:59,889: DEBUG (test)  - finishing

the hanging case is run with "C:\log4j_case>%JAVA_HOME_14%\bin\java -cp 
log4j.jar;. -Dlog4j.configuration=log4jconfig_hang.xml Test"

it generates the same output:
2002-06-10 11:37:04,670: DEBUG (test)  - starting
2002-06-10 11:37:04,670: DEBUG (test)  - finishing

except that execution does not stop.  The process continues until forcibly 
terminated (Ctrl-C on the console, for example).

If you need any other test cases, or if I have missed any information you would 
like to have, please let me know.

Sean Reilly

Comment 7 Sean Reilly 2002-06-10 17:53:50 UTC
Potential solution:

I believe that the VM is continuing execution because the thread created by 
AsyncAppender is not a daemon thread.  If this thread were to be set as a 
Daemon thread then the VM should be able to exit properly.

Here is a change to the constructor of Dispatcher (internal class in 
AsyncAppender) that would accomplish this:

Before:

Dispatcher(BoundedFIFO bf, AsyncAppender container) {
    this.bf = bf;
    this.container = container;
    this.aai = container.aai;
    // set the dispatcher priority to lowest possible value
    this.setPriority(Thread.MIN_PRIORITY);
    this.setName("Dispatcher-"+getName());
    // set the dispatcher priority to MIN_PRIORITY plus or minus 2
    // depending on the direction of MIN to MAX_PRIORITY.
    //+ (Thread.MAX_PRIORITY > Thread.MIN_PRIORITY ? 1 : -1)*2);

  }

After:
Dispatcher(BoundedFIFO bf, AsyncAppender container) {
    this.bf = bf;
    this.container = container;
    this.aai = container.aai;
    this.setDaemon(true);
    // set the dispatcher priority to lowest possible value
    this.setPriority(Thread.MIN_PRIORITY);
    this.setName("Dispatcher-"+getName());
    // set the dispatcher priority to MIN_PRIORITY plus or minus 2
    // depending on the direction of MIN to MAX_PRIORITY.
    //+ (Thread.MAX_PRIORITY > Thread.MIN_PRIORITY ? 1 : -1)*2);

  }

This of course leaves the appender vunerable to the possibility of a VM 
shutdown resulting in logging message loss.  If this is an issue, then perhaps 
a finalizer could be added that would call the dispatcher's close() method?
Comment 8 Ceki Gulcu 2002-07-05 10:43:58 UTC
Log4j 1.2.4 fixes this bug.
Comment 9 Jesse Aalberg 2002-09-16 18:05:48 UTC
Is this bug only fixed if you call AsyncAppender.close()?  

I'm experiencing the same issue with 1.2.6, but I'm not calling the close method
explicitly (the app using the Appender causes application shutdown, so I have
little control over 'when' the app is done with the Appender.