RFR: 8054480: Test java/util/logging/TestLoggerBundleSync.java fails: Unexpected bundle name: null

[David Holmes]

Hi Daniel,

This change seems quite reasonable to me.

Thanks,
David

On 13/08/2014 3:01 AM, Daniel Fuchs wrote:
> 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