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

[Daniel Fuchs]

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