JDK-6409194 : RMI debugging always writes to the console no matter what config is specified
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.rmi
  • Affected Version: 5.0
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • OS: solaris_10
  • CPU: sparc
  • Submitted: 2006-04-05
  • Updated: 2006-05-04
  • Resolved: 2006-04-07
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.
Other JDK 6
5.0u10Fixed 6 b80Fixed
Description
FULL PRODUCT VERSION :
java version "1.5.0_06"
Java(TM) 2 Runtime Environment, Standard Edition (build 1.5.0_06-b05)
Java HotSpot(TM) Client VM (build 1.5.0_06-b05, mixed mode, sharing)

ADDITIONAL OS VERSION INFORMATION :
All Operating Systems

A DESCRIPTION OF THE PROBLEM :
I am trying to debug some RMI problems I am having, so I turned on RMI debugging and write the information to a file.  However with this configuration (which should write all relevant information to a file) some information is still written to the console.  The information is coming from the logger sun.rmi.server.Util.

It seems that this is because in the class sun.rmi.server.Util the field serverRefLog is initialised using the unitialised value of the field logLevel in the same class.

STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
1. Set up source code and logging.properties as shown below
2. run java -Djava.util.logging.config.file=logging.properties test.Client


EXPECTED VERSUS ACTUAL BEHAVIOR :
EXPECTED -
No output should appear on the console
ACTUAL -
Some output appears in the console of the form
28-Mar-2006 12:39:38 sun.rmi.server.Util computeMethodHash

REPRODUCIBILITY :
This bug can be reproduced always.

---------- BEGIN SOURCE ----------
logging.properties

handlers = java.util.logging.FileHandler
.level = OFF
sun.rmi.level = ALL

Server.java

package test;
import java.rmi.*;
public interface Server extends Remote {}

ServerImpl.java

package test;
import java.rmi.*;
import java.rmi.registry.*;
import java.rmi.server.*;
public class ServerImpl extends UnicastRemoteObject implements Server {
    public ServerImpl() throws RemoteException {}

    public void main(String[] argv) throws Exception {
        LocateRegistry.createRegistry(1234);
        Naming.rebind("//localhost:1234/Server", new ServerImpl());
    }
}
---------- END SOURCE ----------

Comments
EVALUATION Contribution-Forum:https://jdk-collaboration.dev.java.net/servlets/ProjectForumMessageView?messageID=12472&forumID=1463
05-04-2006

EVALUATION Yes, this is a bug. The submitter is correct in his analysis of the root cause: the ordering of static field initializations in sun.rmi.server.Util is problematic, in that the serverRefLog field's initializer depends on the value of the logLevel field, but the logLevel field's initializer appears after (and thus executes after) the serverRefLog field's initializer. Using the default value of 0 for the uninitialized logLevel field causes the sun.rmi.runtime.Log.LoggerLog to believe that one of the legacy sun.rmi.*.logLevel system properties has been set, and thus it installs an additional handler to the associated Logger that copies the logging output to System.err. The correct value for the logLevel field in this situation (no legacy system property set) is -1, which it will be after its initializer has completed (now too late). A simple (and low risk) fix would be to simply swap the order in which these two static fields are declared and initialized in the sun.rmi.server.Util class. This bug is a regression introduced in 5.0 due to some implementation code rearrangement that was done for that release (it is not reproducible in 1.4.2).
05-04-2006