Re: Error unmarshaling return header

> Do we know from the stack trace where this is failing?

It is failing while waiting for the result of a remote invocation; all
of the invocation's request data, including the method identifier and
marshalled arguments, have been written to the socket.  The invocation
is, in particular, an invocation of the "addVersions" method on a
remote object of class "com.me.services.ElementManagerService":

    ...
    at com.me.services.ElementManagerService_Stub.addVersions(Unknown Source)
    at com.me.RuleRunner$3.run(ElementSpecifierRuleRunner.java:1137)
    ...

> Or is there somewhere I can go to learn the different communications
> that go on between a client and a server to make one complete RMI
> call?

I don't know of a write-up other than the JRMP protocol documentation:

        http://archives.java.sun.com/cgi-bin/wa?A2=ind0303&L=rmi-users&P=4706

> In some instrumentation I can see various timeouts being set besides
> our "0" read timeout in the factory. Stepping through the code I see
> these being use:
>
>         sun.rmi.transport.tcp.handshakeTimeout=60000
>         sun.rmi.transport.tcp.responseTimeout=0
>         sun.rmi.transport.connectionTimeout=15000
>
> They sometimes reset the Timeout that my factory sets by
> default. Could any of these be the culprit? As I said this system
> can be heavily loaded; should any of these be increased?

The first two of those system properties do indeed correspond to
socket read timeout settings:

The "handshakeTimeout" property affects the socket read timeout during
the initial handshake phase of the JRMP connection, before any remote
invocations are communicated over it.  From the exception stack trace,
it would appear that this is not the timeout which is expiring.

The "responseTimeout" property affects the socket read timeout after
the initial handshake has completed, but only if the socket's read
timeout value before the handshake had been zero (i.e. disabled)-- so
a non-zero timeout set by a socket factory takes precedence over this
property setting.  And the property's default value is itself zero--
no socket read timeout.

The "sun.rmi.transport.connectionTimeout" system property does not
correspond to a socket read timeout; instead, it controls how long the
client-side RMI implementation lets an outgoing connection remain idle
(after a previous invocation communicated over it has completed), in
order to reuse it for another invocation, before closing it.  (The
default value is 15 seconds.)  This property does not seem applicable
to the problem that you are experiencing.

As far as increasing these system property values:

The "responseTimeout" property should already designate an effectively
infinite value.  Of course, if setting it to a very high non-zero
value (near Integer.MAX_VALUE?) affects the problem, that would be
very interesting to know (would seem to indicate a bug).

The "handshakeTimeout" property should only affect a phase of the
connection different from the one in which the exception is occurring.
Again, of course, if setting it to a higher value affects the problem
you are experiencing, that would be very interesting to know.  And
more generally, it is possible that setting it to a higher value would
be helpful for a heavily-loaded server.

> And finally, this stack trace happens on the client side. Is the
> problem that the server is not responding?

That wouldn't explain why a socket read timeout is occurring when none
should be enabled.

> It must be the first connect because I don't see any exceptions on
> the server side when this happens. So the server must not even know
> that an attempt was made to contact it.

I'm not sure that I follow.  The server side need not realize that the
client has fully closed its side of the connection (after the remote
invocation failure).  If the invocation's result data is small enough,
it could be fully written without the server getting an IOException.
What server-side logging do you have enabled?

-- Peter


> -----Original Message-----
> From: Peter Jones - JavaSoft East [mailto:[email protected]]
> Sent: Friday, December 10, 2004 11:25 AM
> To: Robert DiFalco
> Cc: [email protected]
> Subject: Re: Error unmarshaling return header
>
> > Hi Peter, thanks for the help. Hmmmm...we set our timeout in the
> > client (and server) socket factory to 0. If I understand this setting,
>
> > then it should wait forever and we should never see these read
> timeouts.
>
> Yes, passing zero to Socket.setSoTimeout should cause the read timeout
> to be disabled.  If that's what your client socket factory is doing, I'm
> stumped as to what is causing this exception.  Again I might suggest the
> SSL debug tracing, looking for unexpected timeout settings, or similar
> tracing in a custom socket class.
>
> -- Peter
>
>
> > -----Original Message-----
> > From: Peter Jones - JavaSoft East [mailto:[email protected]]
> > Sent: Tuesday, December 07, 2004 5:26 PM
> > To: Robert DiFalco
> > Cc: [email protected]
> > Subject: Re: Error unmarshaling return header
> >
> > > On a heavily loaded system I occasionally get these?
> > >
> > > Anyone seen them? What's odd is that the read timeout is set to
> days.
> >
> > > Is this something else that is timing out? An ack rather than a
> read?
> >
> > > Is there a sun rmi timeout property that I should be increasing?
> >
> > The exception appears to indicate that a socket read timeout set by
> > invoking setSoTimeout on the underlying socket, presumably by a client
>
> > socket factory, has expired while waiting for the response to a remote
>
> > invocation request.  Do you indeed have a socket factory that sets
> > such a read timeout (is that the read timeout you refer to above, set
> > to days)?  What is the exact value?
> >
> > It appears that you are using 1.4.2?  The client-side RMI
> > implementation sets its own read timeout on the socket during the
> > initial handshake phase of the connection; the value is controlled by
> > the system property "sun.rmi.transport.tcp.handshakeTimeout" (default
> > one minute), as described here:
> >
> >
> > http://java.sun.com/j2se/1.4.2/docs/guide/rmi/sunrmiproperties.html
> >
> > but a timeout during that handshake would cause a different exception,
>
> > and after the handshake has completed, the socket's original read
> > timeout is restored (or if it had been zero, the value of the system
> > property "sun.rmi.transport.tcp.responseTimeout" is used instead).
> >
> > > Does SSL play a part here?
> >
> > Perhaps, although I'm sure how.  There is a known JSSE bug that read
> > timeouts which occur in the middle of reading an SSL record are not
> > recoverable (subsequent read throws an SSLException), but that does
> > not appear to be related to what is happening here.  Enabling JSSE's
> > SSL debug tracing might provide a clue, such as tracing invocations of
>
> > setSoTimeout on SSL sockets:
> >
> > http://java.sun.com/j2se/1.4.2/docs/guide/security/jsse/JSSERefGuide.h
> > tm
> > l#Debug
> >
> > > java.rmi.UnmarshalException: Error unmarshaling return header;
> nested exception is:
> > >         java.net.SocketTimeoutException: Read timed out
> > >         at
> sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java:203
> )
> > >         at sun.rmi.server.UnicastRef.invoke(UnicastRef.java:133)
> > >         at
> com.me.services.ElementManagerService_Stub.addVersions(Unknown Source)
> > >         at
> com.me.RuleRunner$3.run(ElementSpecifierRuleRunner.java:1137)
> > >         at
> EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown
> Source)
> > >         at java.lang.Thread.run(Thread.java:534)
> > > Caused by: java.net.SocketTimeoutException: Read timed out
> > >         at java.net.SocketInputStream.socketRead0(Native Method)
> > >         at
> java.net.SocketInputStream.read(SocketInputStream.java:129)
> > >         at com.sun.net.ssl.internal.ssl.InputRecord.a(DashoA12275)
> > >         at
> com.sun.net.ssl.internal.ssl.InputRecord.read(DashoA12275)
> > >         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.a(DashoA12275)
> > >         at com.sun.net.ssl.internal.ssl.SSLSocketImpl.a(DashoA12275)
> > >         at
> com.sun.net.ssl.internal.ssl.AppInputStream.read(DashoA12275)
> > >         at
> java.io.BufferedInputStream.fill(BufferedInputStream.java:183)
> > >         at
> java.io.BufferedInputStream.read(BufferedInputStream.java:201)
> > >         at
> java.io.DataInputStream.readByte(DataInputStream.java:331)
> > >         at
> > > sun.rmi.transport.StreamRemoteCall.executeCall(StreamRemoteCall.java
> > > :189)
> >
> > -- Peter
> >
>
> ===========================================================================
> 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

===========================================================================
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