Re: DGCClient$EndpointEntry stuck

Thanks for having a look at this - some answers inline.
Paul

On Wed, 15 Dec 2004 19:49:06 -0500, Peter Jones - JavaSoft East
<[email protected]> wrote:

>>>> And the sockets don't get closed either,
>>>
>>> That would be a problem.  Do you also log invocations of close() on
>>> your custom socket class?  If so, you don't see any invocations of
>>> it from threads named "RMI ConnectionExpiration-[...]"?
>
>> In any case, the sockets should always close (yes, we do track
>> socket closures and we are not seeing them for the sockets in
>> question).
>
>Do you see threads named "RMI ConnectionExpiration-[...]" (with the
>square brackets containing the same endpoint description as the
>associated RenewClean thread) at all?  Are you setting the
>"sun.rmi.transport.connectionTimeout" system property?  (Any other
>relevant system properties?  A VM thread dump while this is occurring
>might also be helpful.)
>

Here are the relevant parts of the thread dump:

"RMI ConnectionExpiration-[TA-PJOB-W2K:1475]" daemon prio=5 tid=0x106d5b8
nid=0x3e4 waiting on monitor [0x799f000..0x799fdc0]
 at java.lang.Thread.sleep(Native Method)
 at sun.rmi.transport.tcp.TCPChannel$Reaper.run(TCPChannel.java:522)
 at java.lang.Thread.run(Thread.java:479)

"RMI ConnectionExpiration-[TA-PJOB-
W2K:1479,wigan.infrastruct.serviceutil.ClientSocketFactory@f5d9b3ec]"
daemon prio=5 tid=0x1e3e3570 nid=0x324 waiting on monitor
[0xdef000..0xdefdc0]
 at java.lang.Thread.sleep(Native Method)
 at sun.rmi.transport.tcp.TCPChannel$Reaper.run(TCPChannel.java:522)
 at java.lang.Thread.run(Thread.java:479)

"RMI RenewClean-[TA-PJOB-W2K:1475]" daemon prio=5 tid=0x1e6ce5d8 nid=0x104
waiting on monitor [0x1f41f000..0x1f41fdc0]
 at java.lang.Object.wait(Native Method)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:490)
 at java.lang.Thread.run(Thread.java:479)

"RMI RenewClean-[TA-PJOB-
W2K:1479,wigan.infrastruct.serviceutil.ClientSocketFactory@f5d9b3ec]"
daemon prio=5 tid=0x1e8b2008 nid=0x5f8 waiting on monitor
[0xa78f000..0xa78fdc0]
 at java.lang.Object.wait(Native Method)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:490)
 at java.lang.Thread.run(Thread.java:479)

"RMI RenewClean-[TA-PJOB-WS2:1945]" daemon prio=5 tid=0x1e7d7210 nid=0x4f0
waiting on monitor [0xbd9f000..0xbd9fdc0]
 at java.lang.Object.wait(Native Method)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:490)
 at java.lang.Thread.run(Thread.java:479)

"RMI RenewClean-[TA-PJOB-
WS2:1949,wigan.infrastruct.serviceutil.ClientSocketFactory@f5d9b3ec]"
daemon prio=5 tid=0x1e5aa618 nid=0x5b8 waiting on monitor
[0xbb9f000..0xbb9fdc0]
 at java.lang.Object.wait(Native Method)
 at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:103)
 at sun.rmi.transport.DGCClient$EndpointEntry$RenewCleanThread.run
(DGCClient.java:490)
 at java.lang.Thread.run(Thread.java:479)

Note that the last two RenewClean threads do not have corresponding
ConnectionExpiration threads.  Also note that ports TA-PJOB-WS2:1949 and
TA-PJOB-WS2:1945 no longer exist on the RMI server - the server has been
re-started at some point and is now using ports 1475 and 1479.  Has the
server re-start (while there are still remote objects being used on the
RMI client) confused DGC?

How about this for a failure scenario:
1) RMI Client and Server are working normally.
2) RMI Server re-starts while RMI Client has refs to remote objects.
3) RMI Client contacts RMI Server, creating socket inside RenewClean thread
4) RMI Server is now using the old port numbers for some other purpose.
5) RMI Client gets confused by the responses from these ports and retries
forever...

>>> If a DGC "dirty" call fails for some reason, it is retried
>>> (assuming at least the J2SE 1.3 implementation), first quickly, and
>>> then with an exponentially-increasing delay until eventually giving
>>> up-- at which point it should not be retried until a new remote
>>> reference with the same endpoint enters in the VM.
>
>> Also, in any case we are not seeing the exponential hold-off
>> feature.
>[snip]
>> I inserted 'guard' code to spot when lots of sockets are created to
>> the same destination and then refuse additional ones by throwing an
>> IOException in my socket constructor.  This is a snippet of the
>> socket creation details when the java gets into this state:
>[snip]
>> I'm not sure whether this effect isn't triggered by the choice of
>> exception I throw - perhaps if it was a java.rmi.ConnectException it
>> would trigger the exponential hold off and eventual halt?
>
>Note that the exponential backoff I referred to above specifically
>applies to the retry of failed "dirty" calls.  The retry of failed
>"clean" calls is somewhat more haphazard: roughly, the current
>implementation retries them when it's also making a "dirty" call to
>the same endpoint, or when it has reason to make another "clean" call
>to the same endpoint anyway (another remote object at the endpoint has
>become no longer locally reachable), or when the time specified by the
>"sun.rmi.dgc.cleanInterval" (default three minutes) has elapsed since
>last trying.
>
>If you want to cause the retrying of a given "clean" call to stop
>(eventually), then with the current implementations, because of the
>bug discussed earlier in this thread:
>
>        http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6199638
>
>the socket creation operation should throw java.net.ConnectException
>(NOT the higher-level java.rmi.ConnectException, by the way).
>
>> Investigating further, is it possible that when the DGCClient code
>> calls dgc.clean and a new socket connection is made to the RMI
>> server to make the call, the RMI code forgets to call close on the
>> socket if the socket is actually closed first from the remote end
>> (at the RMI server)?
>
>That shouldn't happen (and in bizarre failure scenarios, I would
>expect the socket to be closed through finalization anyway).  If you
>have further evidence that suggests otherwise, please let us know.
>
>> I use a socket factory and extend Socket so that I can instrument
>> socket activity.

Should I have implemented a finalizer on my class that extends Socket?

>
>If you like, send me the socket factory and Socket extension code and
>I can peek to see if anything jumps out at me.
>

I will email this directly.

>>> Here is a list of some of the socket request data.  The timestamp
>>> is the socket creation time:
>
>What J2SE version are you using?  (I can't seem to find a Sun
>implementation version with line numbers that correspond to those
>stack traces.)

I use 1.3.1_06.

>
>It appears that you are not using per-remote-object custom client
>socket factories, but using a custom global RMISocketFactory instead,
>right?

I use a custom global factory and then selected objects are exported using
per object socket factories to get SSL support.

Paul

===========================================================================
To unsubscribe, send email to [email protected] and include in the body
of the message "signoff RMI-USERS".  For general help, send email to
[email protected] and include in the body of the message "help".

For a list of frequently asked RMI questions please refer to:
http://java.sun.com/j2se/1.3/docs/guide/rmi/faq.html

To view past RMI-USERS postings, please see:
http://archives.java.sun.com/archives/rmi-users.html