RFR: 8054480: Test java/util/logging/TestLoggerBundleSync.java fails: Unexpected bundle name: null
david.holmes at oracle.com
Thu Aug 14 10:44:13 UTC 2014
This change seems quite reasonable to me.
On 13/08/2014 3:01 AM, Daniel Fuchs wrote:
> 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.
> 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
> 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();
> best regards,
> -- daniel
More information about the core-libs-dev