Major Description
While investigating the root case of the problem described at http://www.nabble.com/Counting-connections-in-MINA-tt22200162.html I found that it's most likely caused by the collisions of the session ids.
See org.apache.mina.core.service.IoServiceListenerSupport#fireSessionCreated:
// If already registered, ignore.
if (managedSessions.putIfAbsent(Long.valueOf(session.getId()), session) != null) {
return;
}
If the new created session has the same id as the one already managed by the service, this method returns and sessionCreated/sessionOpened are not invoked in the IoHandler. It's not surprising as the JavaDoc for getId() says:
TODO this method implementation is totally wrong. It has to be rewritten.
This problem is pretty serious as under heavy load you will get several collisions per hour. Basically, you will get sessionClosed with empty attributes map which will not correspond to any sessionOpened/sessionCreated. Which leads to inability to track anything via session attributes (consider a simple counter for connected IP addresses which gives you a number of users connected per IP).
There is probably also some race condition as in some cases duplicate id doesn't cause such problem. It must be investigated further.
I've rewritten the getId() method to use AtomicLong incremented in the constructor of the class and it has fixed the problem for me.
I'm attaching the test case which reproduces the problem on my machine. You may need to run it several times to get the expected result or adjust the number of created sessions and the packet size.
Sample output with current getId() implementation:
[2009-03-01 01:06:43,070] START
[2009-03-01 01:06:44,503] DUPLICATE SESSION CLOSED WITHOUT CREATED/OPEN: (0x01028859: nio socket, server, null => null) / DUPLICATE ID: true
[2009-03-01 01:06:47,172] DUPLICATE SESSION CLOSED WITHOUT CREATED/OPEN: (0x012BDC2C: nio socket, server, null => null) / DUPLICATE ID: true
[2009-03-01 01:06:51,187] DUPLICATE SESSION CLOSED WITHOUT CREATED/OPEN: (0x012C0881: nio socket, server, null => null) / DUPLICATE ID: true
[2009-03-01 01:06:55,398] FINISH
Sample output with getId() implementation using AtomicLong():
[2009-03-01 01:08:00,728] START
[2009-03-01 01:08:12,653] FINISH
I have no time for additional investigations for now, hope it helps.
The proposed solution is to either rewrite id generation or make the behavior consistent in case duplicate id is generated. Duplicate ids should not stop the application from normal operation.