What type of connections "RMI TCP Connection(idle)" threads correspond to?

Question

I'm working on a distributed system which is RMI based using jdk1.6.

Occasionally I can see ConcurrentModificationException errors on that thread happening within the RMI runtime when it fails to serialize objects. I can reproduce that exception easily by concurrently updating object being returned from remote method.

But the problem is that I can't find the source of those calls. RMI exception is written to stderr (captured on server side within runtime code after it exits remote object method), but there are no matching exception in client services (while if that was a legitimate remote call, RemoteException with appropriate cause would be raised).

The only different thing about those exceptions is that they are happening on "RMI TCP Connection(idle)" thread and not on a thread like "RMI TCP Connection(<connection count>)-<client endpoint info>".

Any clues on what are those "idle" threads in RMI? I failed to find such within the openjdk sources.

Upd: I'm adding an exception stack trace as reproduced, which is what you usually see in described situation.

Server side console shows:

Exception dispatching call to [-3534448f:12f54948b7f:-7fff, 349678755005857493] in thread "RMI TCP Connection(6)-x.x.x.x" at Thu Apr 14 16:15:13 BST 2011:
java.util.ConcurrentModificationException
    at java.util.ArrayList.writeObject(ArrayList.java:573)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:945)
    at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1469)
    at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1400)
    at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1158)
    at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:330)
    at sun.rmi.server.UnicastRef.marshalValue(UnicastRef.java:274)
    at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:315)
    at sun.rmi.transport.Transport$1.run(Transport.java:159)
    at java.security.AccessController.doPrivileged(Native Method)
    at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
    at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
    at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
    at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
    at java.lang.Thread.run(Thread.java:662)

Client size exception thrown to caller:

java.rmi.UnmarshalException: error unmarshalling return; nested exception is:
    java.io.EOFException
    at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:173)
    at java.rmi.server.RemoteObjectInvocationHandler.invokeRemoteMethod(RemoteObjectInvocationHandler.java:178)
    at java.rmi.server.RemoteObjectInvocationHandler.invoke(RemoteObjectInvocationHandler.java:132)
    at $Proxy0.getData(Unknown Source)
    at Clnt.main(Clnt.java:11)
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
    at java.lang.reflect.Method.invoke(Method.java:597)
    at com.intellij.rt.execution.application.AppMain.main(AppMain.java:115)
Caused by: java.io.EOFException
    at java.io.ObjectInputStream$BlockDataInputStream.peekByte(ObjectInputStream.java:2553)
    at java.io.ObjectInputStream.skipCustomData(ObjectInputStream.java:1899)
    at java.io.ObjectInputStream.readSerialData(ObjectInputStream.java:1873)
    at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1752)
    at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1328)
    at java.io.ObjectInputStream.readObject(ObjectInputStream.java:350)
    at sun.rmi.server.UnicastRef.unmarshalValue(UnicastRef.java:306)
    at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:155)
    ... 9 more

Teddy

If RMI gets a a runtime exception during serialization of the return value, it's already too late in the protocol to serialize the exception instead, so it is swallowed. Can you post a stack trace? – Echelon

I've updated the post with stack traces on both sides. The actual exception is swallowed, but client side still can't deserialize method results so it throws a subclass of RE which should be seen somewhere in client logs. – Teddy

Answer 1

I got to the bottom of it. Problem happens in two cases:

1. When marshaling a return value throws some exception and that exception in turn contains an object prone to concurrent modification. UnicastServerRef tries to write the cause into the (already corrupted) return stream and causes ConcurrentModificationException.
2. When method raises an exception and this exception fails to serialize with ConcurrentModificationException (or any other runtime exception).
   This exception goes all the way up the stack and is caught and logged by thread pool, not RMI runtime (that's why there is no Exception dispatching call to line at the beginning). That explains thread name being idle since it is already returned to pool from RMI's point of view.

Here's the real exception which is in fact a bit different from what reproduced exception shows in terms of first line and actual call trace:

Exception in thread "RMI TCP Connection(idle)" java.util.ConcurrentModificationException
 at java.util.ArrayList.writeObject(ArrayList.java:573)
 at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source)
 at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
 at java.lang.reflect.Method.invoke(Method.java:597)
 at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:945)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1461)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1392)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1150)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1509)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1474)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1392)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1150)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1509)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1474)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1392)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1150)
 at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1509)
 at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1474)
 at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1392)
 at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1150)
 at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:326)
 at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:343)
 at sun.rmi.transport.Transport$1.run(Transport.java:159)
 at java.security.AccessController.doPrivileged(Native Method)
 at sun.rmi.transport.Transport.serviceCall(Transport.java:155)
 at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:535)
 at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:790)
 at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:649)
 at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
 at java.lang.Thread.run(Thread.java:619)

It doesn't give much clues to the original problem, so I'll have to wait for a client exception to show up at some point to fix that.
If that kind of exception happens when reading JMX attribute by jconsole, it'll not show stacktrace, but will show attribute value as Unavailable.

Teddy

Answer 2

Threads are created in RMI's connection pool with the name 'RMI TCP Connection(idle)'. When one of these is used, the runnable it is being used to execute renames the thread to 'RMI TCP Connection(n)' where n is the connection number being handled (a sequential number), and renames back to 'idle' in the runnable's finally block. So any trace labelled 'RMI TCP Connection(idle)' must come before the runnable renames it as a connection thread, or after it has been renamed back.

Don't ask me how that is possible. The actual answer to your problem, if not your question, is not to modify objects while they are concurrently being returned ;-)

Echelon

Ouch! How did I overlooked the renaming bit. Now naming makes sense but looks even weirder, because it shouldn't handle any messages in idle state. I wish I know which object is mutable, because we do defensive copying for potentially mutable results to prevent that. I was hoping to get some clues by identifying what are the endpoints for this chatter. – Teddy

I found how runtime exceptions could leak into thread pool and added explanation as an answer. It does explain why the thread is idle and why the endpoint information is lost by that time. So I have to wait for one of the client connections to fail and log that. Might be a jconsole querying beans so it'll never end up in logs. – Teddy