Bug 42085

Summary: java.util.Logging duplicated since 5.5.23. 5.5.20 is OK
Product: Tomcat 5 Reporter: Klaus Halfmann <klaus.halfmann>
Component: Catalina:ModulesAssignee: Tomcat Developers Mailing List <dev>
Status: RESOLVED FIXED    
Severity: regression CC: richardfearn
Priority: P3    
Version: 5.5.23   
Target Milestone: ---   
Hardware: All   
OS: All   

Description Klaus Halfmann 2007-04-10 23:13:02 UTC
We use the followwing logging.properties in our WebApplication:

----------%<--------------------%<----------------
handlers = 1tivoli.java.util.logging.FileHandler,
2product.java.util.logging.FileHandler

# Handlers for the root logger
.handlers = 1tivoli.java.util.logging.FileHandler,
2product.java.util.logging.FileHandler

1tivoli.java.util.logging.FileHandler.level = INFO
1tivoli.java.util.logging.FileHandler.pattern = /var/log/product/tivoli%g.log
# limit Output to 1MB
1tivoli.java.util.logging.FileHandler.limit=1048576
# Limit rotation to 10 Logs ...
1tivoli.java.util.logging.FileHandler.count=10
1tivoli.java.util.logging.FileHandler.append=true
1tivoli.java.util.logging.FileHandler.formatter=de.customer.product.tivoli.TivoliFormatter

2product.java.util.logging.FileHandler.level = FINEST
2product.java.util.logging.FileHandler.pattern = /var/log/product/product%g.log
# limit Output to 1MB
2product.java.util.logging.FileHandler.limit=1048576
# Limit rotation to 5 Logs ...
2product.java.util.logging.FileHandler.count=5
2product.java.util.logging.FileHandler.append=true
2product.java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter
----------%<--------------------%<----------------

When using apache-tomcat-5.5.23 every Line in the Logfiles
is duplicated. Debugging I found that the TivoliFormatter 
is actually created twice. And the root-logger has actually
4 Handlers and not two as intended. This does not allow us an
upgrade beyond 5.5.20.

Found on Linux64Bit and Windows-XP, both with JDK 1.5_R11
Comment 1 Richard Fearn 2007-04-11 12:13:48 UTC
java.util.logging.FileHandler extends java.util.logging.StreamHandler. The
no-args constructors for these two classes both make a call to the configure()
method, which is why you see two TivoliFormatters created when the tivoli
handler is set up. This shouldn't cause duplication, though; the first formatter
to be created is simply discarded, and only the second is used.

Could you give more information about your setup? I can't duplicate this
problem. Is that your entire logging.properties file? How does your code use the
logger?

If I put these lines into a test servlet:

    Logger logger = Logger.getLogger("");
    logger.severe("Handlers: " + Arrays.asList(logger.getHandlers()));

and make a request to it (using your logging.properties file), the console shows
that the root logger has two handlers (both FileHandlers).
Comment 2 Klaus Halfmann 2007-04-11 23:19:52 UTC
More Infos:
* The bug does not appear when all our classes are in the bootclasspath
  (as we do for testing via eclipse)
  but only when deployed as war/jar

* We use a root context and deploy it as ROOT.war
  (although this is not really documented as beeing supported this way)

* The TivoliFormatter has only a default Constructor

The first usage that was duplicated works as follows:

public class ProductContextListener implements ServletContextListener {

  private static Logger log = Logger.getLogger(ProductContextListener
.class.getName());

  ...
  public void contextInitialized(ServletContextEvent anEvent) {
    ...
    log.info("Starting Product Version " + version);
    ...
  }
}

Our global logging.properties is as follows:

--------------%<---------------%<-----------------
handlers = 1catalina.java.util.logging.FileHandler

# Handlers for the root logger
.handlers = 1catalina.java.util.logging.FileHandler

1catalina.java.util.logging.FileHandler.level = INFO
1catalina.java.util.logging.FileHandler.pattern = /var/log/ucs/catalina%g.log
# limit Output to 1MB
1catalina.java.util.logging.FileHandler.limit=1048576
# Limit rotation to 10 Logs ...
1catalina.java.util.logging.FileHandler.count=10
# 1catalina.java.util.logging.FileHandler.append=true
1catalina.java.util.logging.FileHandler.formatter=java.util.logging.SimpleFormatter
--------------%<---------------%<-----------------

Our server XML is as follows:

--------------%<---------------%<-----------------
<Server port="8005" shutdown="****">
  <!-- server.xml for deployed tomcat 5 -->
  <Service name="Product">
 	<Connector port="8080" 
		       maxKeepAliveRequests="100000"
               maxThreads="200" minSpareThreads="20" maxSpareThreads="100"
               enableLookups="false"  acceptCount="20" />
    <Engine name="Product" defaultHost="localhost">
      <Host name="localhost" appBase="webapps" >
        <Context path=""
                 cookies="false"
                 docBase="ROOT.war"
                 cachingAllowed="false"
                 processTlds="false"
                 unpackWAR="true"
                 reloadable="false">
             <Manager pathname="" />
         </Context>
      </Host>
    </Engine>
  </Service>
</Server>

--------------%<---------------%<-----------------

Hmm, perhaps the Problem happens when using a 
ROOT <Context path="" ../> only ?

web.xml was copied from tomcat 5.5.20

We use the following properties (in eclipse)
to start tomcat. 

---------------%<-----------------%<-----------------------
-Dcatalina.home="${TOMCAT5}"
-Dcatalina.base="${workspace_loc:de.customer.product}/ext/tomcat5" 
-Djava.endorsed.dirs="${TOMCAT5}}/common/endorsed"
-Djava.io.tmpdir="${TOMCAT5}/temp"
-Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
-Djava.util.logging.config.file="${workspace_loc:de.customer.product}/ext/tomcat5/conf/logging.properties"
---------------%<-----------------%<-----------------------

On linux we use a similar init.d script:

---------------%<-----------------%<-----------------------

On linux we use a similar init.d script:

#!/bin/sh
#
# Startup script for product UserConfigurationSystem
# $Id: product,v 1.7 2007/04/10 08:53:50 kha Exp $
#          
# /etc/init.d/product
#
### BEGIN INIT INFO
# Provides:          product
# Required-Start:    mysql
# Default-Start:     3 5
# Default-Stop:      0 1 2 6
# Short-Description: product - Our super duper product
# Description:       A Small tomcat based web-app as XML-RPCProvider
# 	against a fat MySQL Database
### END INIT INFO
# 
# Check for missing binaries (stale symlinks should not happen)
# Note: Special treatment of stop for LSB conformance
CATALINA_HOME=/opt/app/product/apache-tomcat
CATALINA_BASE=/opt/app/product/service
CATALINA_BIN=$CATALINA_HOME/bin/catalina.sh
test -x $FOO_BIN || { echo "$CATALINA_BIN not installed"; 
	if [ "$1" = "stop" ]; then exit 0;
	else exit 5; fi; }

JAVA_HOME=/usr/java/jdk1.5.0_11
JRE_HOME=$JAVA_HOME/jre
CATALINA_OPTS=
USER=product
CATALINA_OPTS=-Dde.customer.product.confDir=/etc/product
CATALINA_OPTS="$CATALINA_OPTS
-Xbootclasspath/a:/opt/app/product/service/lib/product-tivoli.jar"
# CATALINA_OPTS="$CATALINA_OPTS -ea -esa -Xdebug
-Xrunjdwp:transport=dt_socket,address=9099,server=y,suspend=n"
CATALINA_TMPDIR=/var/opt/app/product/tmp

su - $USER -c "export JAVA_HOME=$JAVA_HOME;\
	       export JRE_HOME=$JRE_HOME;\
	       export CATALINA_OPTS='$CATALINA_OPTS';\
	       export JAVA_OPTS='$JAVA_OPTS';\
	       export CATALINA_HOME=$CATALINA_HOME;\
	       export CATALINA_BASE=$CATALINA_BASE;\
	       export CATALINA_TMPDIR=$CATALINA_TMPDIR;\
	       $CATALINA_HOME/bin/catalina.sh $1"
---------------%<-----------------%<-----------------------

Thats all I can give you so far, as we must 
deliver the product next week ;-)





    
Comment 3 Remy Maucherat 2007-04-12 08:38:46 UTC
The problem was trivial (handlers for the root logger are added twice if they
are specified using .handlers). Workaround: remove .handlers (what's the purpose
exactly if it's the same as handlers; of course, I suppose it has the same
purpose as that Context element in the server.xml).
Comment 4 Klaus Halfmann 2007-04-13 00:17:42 UTC
Thanks for the Workaround:

As I Understand it:

handlers - configures all availeable Handlers
.handlers - are the Handlers for the root-logger

e.g.
org.apache.tomcat.handlers 
  - would be handlers for theses packages only

Feels like the root context is silently used
as parking area for the handlers ;-)

Thanks again
Comment 5 Richard Fearn 2007-04-14 12:14:39 UTC
> Feels like the root context is silently used
> as parking area for the handlers ;-)

That's how Java Logging works, so JULI is consistent with that - all handlers
defined in the "handlers" property are automatically added to the root logger.
If you want a subset just add a ".handlers" property listing the subset.