JDK-8029347 : sun/rmi/runtime/Log/checkLogging/CheckLogging.java fails in nightly intermittently
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.rmi
  • Affected Version: 8
  • Priority: P3
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2013-11-29
  • Updated: 2013-12-16
  • Resolved: 2013-12-04
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 8
8 b120Fixed
Related Reports
Relates :  
JDK-8029595 - Avoid cases of Logger being GC'ed in tests
Description
TESTFAIL:sun/rmi/runtime/Log/checkLogging/CheckLogging.java

sun/rmi/runtime/Log/checkLogging/CheckLogging.java

The tes fails several times on multiple platforms, it should be stabilized. see details:
Nov 27, 2013 5:50:00 PM sun.rmi.server.UnicastRef logClientCall
FINER: MainThread: outbound call: [endpoint:[localhost:51934](remote),objID:[0:0:0, 0]] : sun.rmi.registry.RegistryImpl_Stub[0:0:0, 0]: java.lang.String list()[]
call stream should be null and it is
Nov 27, 2013 5:50:00 PM sun.rmi.server.UnicastRef logClientCall
FINER: MainThread: outbound call: [endpoint:[localhost:51934](remote),objID:[0:0:0, 0]] : sun.rmi.registry.RegistryImpl_Stub[0:0:0, 0]: java.lang.String list()[]
Nov 27, 2013 5:50:00 PM sun.rmi.server.UnicastRef logClientCall
FINER: MainThread: outbound call: [endpoint:[localhost:51934](remote),objID:[0:0:0, 0]] : sun.rmi.registry.RegistryImpl_Stub[0:0:0, 0]: java.rmi.Remote lookup(java.lang.String)
Nov 27, 2013 5:50:00 PM sun.rmi.transport.StreamRemoteCall exceptionReceivedFromServer
FINE: MainThread: outbound call received exception: [localhost:51934] exception: 
java.rmi.NotBoundException: notthere
	at sun.rmi.registry.RegistryImpl.lookup(RegistryImpl.java:136)
	at sun.rmi.registry.RegistryImpl_Skel.dispatch(Unknown Source)
	at sun.rmi.server.UnicastServerRef.oldDispatch(UnicastServerRef.java:410)
	at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:268)
	at sun.rmi.transport.Transport$1.run(Transport.java:178)
	at sun.rmi.transport.Transport$1.run(Transport.java:175)
	at java.security.AccessController.doPrivileged(Native Method)
	at sun.rmi.transport.Transport.serviceCall(Transport.java:174)
	at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:557)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:812)
	at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:671)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:744)
	at sun.rmi.transport.StreamRemoteCall.exceptionReceivedFromServer(StreamRemoteCall.java:276)
	at sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:253)
	at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:379)
	at sun.rmi.registry.RegistryImpl_Stub.lookup(Unknown Source)
	at java.rmi.Naming.lookup(Naming.java:101)
	at CheckLogging.checkServerCallLog(CheckLogging.java:178)
	at CheckLogging.main(CheckLogging.java:206)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94)
	at java.lang.Thread.run(Thread.java:744)

Nov 27, 2013 5:50:00 PM LogStream print
INFO: MainThread: bingo, this is a getLog test
TEST FAILED: log data length is zero
TEST_LIBRARY: unexporting object...
TestFailedException: TEST FAILED: log data length is zero
	at TestLibrary.bomb(TestLibrary.java:121)
	at TestLibrary.bomb(TestLibrary.java:124)
	at CheckLogging.verifyLog(CheckLogging.java:137)
	at CheckLogging.main(CheckLogging.java:209)
	at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.lang.reflect.Method.invoke(Method.java:483)
	at com.sun.javatest.regtest.MainWrapper$MainThread.run(MainWrapper.java:94)
	at java.lang.Thread.run(Thread.java:744)

JavaTest Message: Test threw exception: TestFailedException: TEST FAILED: log data length is zero
JavaTest Message: shutting down test

STATUS:Failed.`main' threw exception: TestFailedException: TEST FAILED: log data length is zero
Comments
I can confirm that the failure that I'm seeing is due to the Logger being GC'ed. Sean's patch works and would be nice to get into jdk8.
04-12-2013
We don't have a strong reference maintained for the Logger.getLogger call in the testcase. Looks like GC is more ambitious to collect the object now. suggested fix : diff -r 28ca338366ff test/sun/rmi/runtime/Log/checkLogging/CheckLogging.java --- a/test/sun/rmi/runtime/Log/checkLogging/CheckLogging.java Mon Nov 25 20:22:23 2013 -0800 +++ b/test/sun/rmi/runtime/Log/checkLogging/CheckLogging.java Wed Dec 04 15:22:42 2013 +0000 @@ -76,6 +76,7 @@ public class CheckLogging { private static int REGISTRY_PORT = -1; private static String LOCATION; + private static Logger logger; private static final ByteArrayOutputStream clientCallOut = new ByteArrayOutputStream(); @@ -89,8 +90,8 @@ System.err.println("set default stream"); LogStream.setDefaultStream(new PrintStream(clientCallOut)); } else { - Logger.getLogger("sun.rmi.client.call"). - addHandler(new InternalStreamHandler(clientCallOut)); + logger = Logger.getLogger("sun.rmi.client.call"); + logger.addHandler(new InternalStreamHandler(clientCallOut)); } }
04-12-2013
I tried this test standalone against the latest on two of the failing systems, and it executes OK. tried it also on Linux and Solaris using latest from jdk8/tl currently investigating the call floes involved in the test to get a handle of a potential cause.
04-12-2013
Alan Bateman wrote: I just checked jdk8-b117 and jdk8-b118 and the test passes for me. However when I try a build of jdk8/tl then it fails every time so it does appear that we have picked up something in either the jdk or langtools repository. Hopefully it won't be too hard to bisect this.
29-11-2013