Minor Description
The examples of log entries with principal name displayed twice and separated by semicolon are displayed below:
2011-09-07 12:42:41,051 INFO [RMI TCP Connection(3)-169.24.39.206] (Log4jMessageLogger.java:72) - [mng:N/A(169.24.39.206)] MNG-1007 : Open : User guest;guest 2011-09-07 12:42:44,446 INFO [RMI TCP Connection(3)-169.24.39.206] (Log4jMessageLogger.java:72) - [mng:N/A(169.24.39.206)] MNG-1008 : Close : User guest;guest
This problem can be simply reproduced by connecting to broker with Management console and looking into log files.
This issue occurs due to following reason:
On logging of JMX connection Open/Close events a principal name is taken from JMX connection id.
In current RMI server implementation the connection id has the following format
rmi://<hostname>:<port> <principal 1>;<principal 2>...<principal n> <index>
It has the list of principals taken from the subject at the moment of opening the connection.
In current implementation of RMIPasswordAuthenticator on successful authentication an instance of JMXPrincipal is added to subject in addition to existing UsernamePrincipal which is added before in AuthenticationManager#authenticate.
As result of this, Subject contains two entries with the same principal name.
On creating a connection Id RMIServerImpl iterates through all principals in subject and adds them separated by ';' to connection id string.