Hi,
Please find below a fix for:
8054480: Test java/util/logging/TestLoggerBundleSync.java fails:
Unexpected bundle name: null
This test has been reported to fail from time to time with the
following stack:
java.lang.RuntimeException: Unexpected bundle name: null
at TestLoggerBundleSync$GetRB.run(TestLoggerBundleSync.java:257)
The issue here is due to a race condition in the test code.
The comments in the fix explains the fix & the issue.
http://cr.openjdk.java.net/~dfuchs/webrev_8054480/webrev.00/
--
The test creates several GetRB threads which 'read' the resource
bundle that will be used by loggers. It does that by publishing
a dummy message in a child logger, and checking the resource
bundle name stored in the associated LogRecord.
The test also creates several SetRB/SetRBName threads which attempts to
set the resource bundle on loggers, in parallel with the GetRB threads.
The race condition occurs because although each GetRB thread
has its own Handler that it uses to get at the ResourceBundle in
the LogRecord, it can receive LogRecords that were emitted by
other GetRB threads - which (because of thread scheduling) might
have been prepared at an earlier time and may contain stale
information.
What it means is that the following logic from
GetRB is flawed:
a. gets ResourceBundle from parent logger
b. register handler with child logger
c. emit dummy message through child logger
d. remove handler registered in b.
f. check resource bundle that was passed in LogRecord,
comparing it with the resource bundle obtained in a.
The expectation is that if a. is not null, then
the resource bundle name obtained by the handler should
not be null, and should be equal to the name obtained
in a.
This logic is flawed and prone to race conditions, because
the following may sometime happens:
GetRB#1 logs a message, but gets interrupted after LogRecord
is created but before publish() is called. At this
point the ResourceBundle has not been set yet, so the
record has a null ResourceBundle.
SetRB#? sets resource bundle on parent logger
GetRB#2 sees the new resource bundle, emit a dummy message, but is
interrupted before it removes its handler.
At this point the handler has the correct resource bundle
and resource bundle name that it found in the LogRecord
emitted by GetRB#2 in step c.
GetRB#1 is resumed. LogRecord gets published - but since the
handler from thread #2 is still present, the 'old'
LogRecord from GetRB#1 gets forwarded to GetRB#2's handler
where it erases the information previously recorded by the
message that was emitted by GetRB#2
GetRB#2 is resumed, and sees the rbName/rb that was present in
the old LogRecord emitted by GetRB#1 instead of seeing
the newer information that was in the LogRecord emitted
by GetRB#2.
=> the exception gets raised.
The fix is relatively simple: the Handler registered by each
GetRB thread need simply to ignore messages that were not emitted by
its own thread - we do this now by passing 'this' as parameter to
the dummy logged message - and by comparing GetRB.this
with LogRecord.getParameters()[0];
best regards,
-- daniel
