Bug 26668 - java.util.logging bugs
Summary: java.util.logging bugs
Status: NEW
Alias: None
Product: classpath
Classification: Unclassified
Component: classpath (show other bugs)
Version: unspecified
: P3 normal
Target Milestone: ---
Assignee: Not yet assigned to anyone
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2006-03-13 18:51 UTC by Rafael H. Schloming
Modified: 2006-05-14 16:07 UTC (History)
4 users (show)

See Also:
Host:
Target:
Build:
Known to work:
Known to fail:
Last reconfirmed: 2006-03-15 12:59:11


Attachments
java.util.logging patch (3.84 KB, patch)
2006-03-13 18:52 UTC, Rafael H. Schloming
Details | Diff
updated patch (4.33 KB, patch)
2006-03-20 15:51 UTC, Rafael H. Schloming
Details | Diff
test suite (2.04 KB, text/plain)
2006-03-20 15:52 UTC, Rafael H. Schloming
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Rafael H. Schloming 2006-03-13 18:51:40 UTC
I ran into a number of bugs and incompatibilities between the classpath implementation of java.util.logging and the sun implementation while attempting to use the tomcat-juli logging manager with classpath. I've listed the issues below and have a patch that addresses each of them.

1. The LogManager only looks up classes in the system class loader. My patch modifies it to also check the context class loader if nothing is found in the system class loader. This is necessary for third party logging managers to work at all.

2. Errors occurring during instantiation of the LogManager were masked due to insuficiently granular exception handling. The patch modifies the implementation to handle all the different exceptions that can occur and report each one with a distinct error message.

3. Previously the LogManager constructor would initialize the static LogManager variable. This is not robust because a failed LogManager instantiation will can leave a half initialized LogManager instance in the static variable and this will prevent any future LogManager instantiations from succeeding. The patch moves this initialization outside the LogManager constructor where it only happens after the LogManager instance has been successfully created.

4. The LogManager constructor also used to invoke the addLogger method. This was a problem for the tomcat-jul LogManager subclass because the addLogger method was overriden and tried to access instance variables that had not been instantiated yet. The patch removes all method invocation from the LogManager constructor and instead performs the same method invocations after the LogManager has been successfully created.

5. The root logger is stored in the Logger class instead of being stored in each instance of the LogManager class. This allows multiple LogManager instantiation attempts, and also simplifies some of the cyclic dependencies between Logger and LogManager.

6. The Level class uses == instead of .equals for string comparison, but the code only guarantees that one of the strings being compared is intern()ed. The patch intern()s the other end of the string by intern()ing the name that is passed to the Level constructor.
Comment 1 Rafael H. Schloming 2006-03-13 18:52:48 UTC
Created attachment 11044 [details]
java.util.logging patch
Comment 2 Mark Wielaard 2006-03-15 12:59:11 UTC
Thanks for this Rafael.
Splitting this in smaller parts would help evaluate things quicker (as would adding a ChangeLog entry and following the coding convention).

Question about point #6. Although I agree this is a bit obscure it doesn't look actually wrong. Since String constants are interned automatically they can be compared with other interned strings (that should at least be documented in the code of course). Do you have an actual test case that shows this code failing?
Comment 3 Mark Wielaard 2006-03-15 13:35:44 UTC
Comment on 2. Errors occurring during instantiation of the LogManager were masked due to insuficiently granular exception handling. The patch modifies the
implementation to handle all the different exceptions that can occur and report
each one with a distinct error message.

This is indeed nice to have during debugging, but do you really expect these warnings to be printed to stderr? We could try to use the Logging framework, but, well, that is what we are trying to initialize... We should at least route all errors through the new warn() method. So we can turn this on/off globally (or reroute to something different than System.err).
Comment 4 Mark Wielaard 2006-03-15 13:41:04 UTC
Comment on 1. The LogManager only looks up classes in the system class loader. My patch modifies it to also check the context class loader if nothing is found in the system class loader. This is necessary for third party logging managers to work at all.

Agreed. This makes sense. But I would try the context class loader first and fall back to the system class loader if that fails. That is what other core library code also does. Also naming the method forName() is a little confusing (since there is also Class.forName). I would just inline that part into createInstance().
Comment 5 Rafael H. Schloming 2006-03-15 14:30:30 UTC
Regarding #6, I don't actually have a test case for this. It just looked suspicous so I changed it just to make sure it wasn't the source of any of my problems. I suspect you are correct that in practice this not likely to be an issue, but the code looked suspicious to me for two reasons.

1. I wasn't sure string literals were automatically interned by all JVMs. If this is in fact part of the langauge spec then this is a non issue.

2. The Level constructor is protected which means that anyone can pass a non liternal value into the name slot via subclassing. I don't know if this is intended. If not an alternative fix would be to make the Level constructor private.
Comment 6 Rafael H. Schloming 2006-03-15 14:36:20 UTC
Regarding the class lookup order, I checked the system class loader first so that it would be impossible for the context class loader to attempt to override any system classes. If this is not a concern I can reverse the order.
Comment 7 Rafael H. Schloming 2006-03-15 14:58:05 UTC
Regarding the warnings, I agree they should all go through the warn() method. I had intended that, but it looks like I missed a couple of them.

As for turning them off, I'm not sure you would ever want to do that. IMHO, it's a pretty serious condition if the logging system is going to be borked since it will be quite difficult to figure out what has gone wrong. I would even favor making a number of them fatal errors rather than warnings. I believe the sun implementation leans in that direction, for example the sun implementation will just die with a ClassCastException if java.util.logging.manager does not extend LogManager.

I'm currently working on a test case that enumerates the various failure conditions and will let me compare the logging system behavior with other implementations. I will post this along with an updated patch when I'm done.
Comment 8 Tom Tromey 2006-03-15 19:42:21 UTC
"I wasn't sure string literals were automatically interned by all JVMs. If
this is in fact part of the langauge spec then this is a non issue."

Yeah, this is required by the language specification.
Comment 9 Mark Wielaard 2006-03-16 13:55:04 UTC
Subject: Re:  java.util.logging bugs

> ------- Comment #6 from rafaels at redhat dot com  2006-03-15 14:36 -------
> Regarding the class lookup order, I checked the system class loader first so
> that it would be impossible for the context class loader to attempt to override
> any system classes. If this is not a concern I can reverse the order.

The order should be thread context class loader first, then system class
loader.

Comment 10 Mark Wielaard 2006-03-16 13:58:49 UTC
Subject: Re:  java.util.logging bugs

On Wed, 2006-03-15 at 14:30 +0000, rafaels at redhat dot com wrote:
> 
> ------- Comment #5 from rafaels at redhat dot com  2006-03-15 14:30 -------
> Regarding #6, I don't actually have a test case for this. It just looked
> suspicous so I changed it just to make sure it wasn't the source of any of my
> problems. I suspect you are correct that in practice this not likely to be an
> issue, but the code looked suspicious to me for two reasons.
> 
> 1. I wasn't sure string literals were automatically interned by all JVMs. If
> this is in fact part of the langauge spec then this is a non issue.

They should. If they do not that is a bug.

> 2. The Level constructor is protected which means that anyone can pass a non
> liternal value into the name slot via subclassing. I don't know if this is
> intended. If not an alternative fix would be to make the Level constructor
> private.

That is true. But for the parse() method only the standard log levels
matter.

We do need a comment explaining that using == is "safe" for the standard
log levels since the argument is interned and the standard log levels
are constructed with a constant (so already interned) name.

BTW. I added a Mauve test for parse to make sure things work even when
parse gets a "non-constant" name.

Comment 11 Rafael H. Schloming 2006-03-20 15:51:57 UTC
Created attachment 11072 [details]
updated patch
Comment 12 Rafael H. Schloming 2006-03-20 15:52:51 UTC
Created attachment 11073 [details]
test suite
Comment 13 cvs-commit@developer.classpath.org 2006-04-03 09:00:28 UTC
Subject: Bug 26668

CVSROOT:	/cvsroot/classpath
Module name:	classpath
Branch: 	
Changes by:	Mark Wielaard <mark@savannah.gnu.org>	06/04/03 08:59:53

Modified files:
	.              : ChangeLog 
	java/util/logging: Level.java LogManager.java Logger.java 

Log message:
	2006-04-03  Rafael H. Schloming  <rafaels@redhat.com>
	
	Fixes bug #26668
	* java/util/logging/Level.java (parse): Document.
	* java/util/logging/LogManager.java (rootLogger): Removed.
	(LogManager): Just set loggers to new HashMap.
	(getLogManager): Make synchronized. Create and init LogManager if it
	doesn't exist yet.
	(static): Removed block.
	(MANAGER_PROPERTY): New private final string.
	(makeLogManager): Use new property string, move warning to
	createInstance() method.
	(CONFIG_PROPERTY): New private final string.
	(initLogManager): New method.
	(addLogger): Use Logger.root, not rootLogger.
	(findAncestor): Likewise.
	(readConfiguration): Move warning to createInstance() method.
	Add handlers directly to Logger.root. Warn about bad level values.
	(getClassProperty): Use new locateClass() method.
	(getInstanceProperty): Only catch specific newInstance Errors.
	(createInstance): Make private and takes a string to use in warning
	messages. Use new locateClass() method and generate appropriate
	warning message.
	(warn): New methods.
	(locateClass): Locates a class through the context class loader and
	system class loader as backup.
	* java/util/logging/Logger.java (root): New static final field.
	(Logger): Set parent to root.
	(setParent): Directly check root field.

CVSWeb URLs:
http://cvs.savannah.gnu.org/viewcvs/classpath/classpath/ChangeLog.diff?tr1=1.6990&tr2=1.6991&r1=text&r2=text
http://cvs.savannah.gnu.org/viewcvs/classpath/classpath/java/util/logging/Level.java.diff?tr1=1.9&tr2=1.10&r1=text&r2=text
http://cvs.savannah.gnu.org/viewcvs/classpath/classpath/java/util/logging/LogManager.java.diff?tr1=1.18&tr2=1.19&r1=text&r2=text
http://cvs.savannah.gnu.org/viewcvs/classpath/classpath/java/util/logging/Logger.java.diff?tr1=1.12&tr2=1.13&r1=text&r2=text



Comment 14 Mark Wielaard 2006-04-03 09:07:30 UTC
Thanks so much for this and for incorporating all the suggestions. I have checked it in with some minor changes (updated copyright years, import reshuffle and usage of SystemProperties - see my classpath-patches email).

I am keeping this bug report open because I also would like to get your LoggingTest into mauve somehow. I am hoping Tony (CCed) can take a look at that since he is reworking the mauve framework.

BTW. We have 3 (out of 200+) util.logging failures in Mauve (before and after your patch). Maybe you want to take a look at those if you are into util.logging now anyway?
FAIL: gnu.testlet.java.util.logging.Logger.getLogger (number 9)
FAIL: gnu.testlet.java.util.logging.Logger.securityChecks: Logger.getAnonymousLogger() (number 7)
FAIL: gnu.testlet.java.util.logging.Logger.securityChecks: Logger.getAnonymousLogger(null) (number 7)
Comment 15 Rafael H. Schloming 2006-04-04 18:16:06 UTC
When I get a chance I'd be happy to download mauve and take a look at the bugs you mention.
Comment 16 Andrew John Hughes 2006-05-07 17:53:39 UTC
This patch means that some Mauve tests now fail as internal LogManager code trips some code that causes security exceptions:

FAIL: gnu.testlet.java.util.logging.Handler.getErrorManager: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Handler.setEncoding: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Handler.setErrorManager: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Handler.setFilter: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Handler.setLevel: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Logger.getLogger: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Logger.getName: uncaught exception: java.lang.ExceptionInInitializerError
FAIL: gnu.testlet.java.util.logging.Logger.securityChecks: uncaught exception: java.lang.ExceptionInInitializerError

I looked at the first of these, getErrorManager().  The test tries first to get the error manager without permission, and then after obtaining permission from its own test security manager.  The first test now fails with an exception, as an exception is generated in the initialisation of the log manager.  When trying to set the level of the root logger, it fails due to the security manager's restrictions.  I presume this is why the others now also fail.
Beforehand, this was obscured by the initialisation taking place in the constructor before the security manager was activated.
Comment 17 Mark Wielaard 2006-05-14 16:07:07 UTC
(In reply to comment #16)
> This patch means that some Mauve tests now fail as internal LogManager code
> trips some code that causes security exceptions:
> 
> FAIL: gnu.testlet.java.util.logging.Handler.getErrorManager: uncaught
> exception: java.lang.ExceptionInInitializerError
> [...]
> I looked at the first of these, getErrorManager().  The test tries first to get
> the error manager without permission, and then after obtaining permission from
> its own test security manager.  The first test now fails with an exception, as
> an exception is generated in the initialisation of the log manager.  When
> trying to set the level of the root logger, it fails due to the security
> manager's restrictions.  I presume this is why the others now also fail.
> Beforehand, this was obscured by the initialisation taking place in the
> constructor before the security manager was activated.

This has been fixed in CVS now.

Keeping the bug report open since we want to LoggingTest in Mauve.