Kiran Singh - 2009-10-15

Hi,

We are using the Remote Tea version 1.0.5 in our java rpc client code. Recently we have started receiving this OncRpcException (can not receive ONC/RPC data) while trying to receive the response for the rpc calls. Looking into the readBuffer code, I noticed that this exception comes at a place when the bytesRead is -1. Most of the times, it comes in the beginning when the code is trying to read the first 4 bytes of the response header. But some times it also happens while reading when it is at very end of a large rpc response (say ~500k bytes).

If anybody has any clues as to why we might be seeing this, please help.

Thanks
Kiran

I have added some debugging code in the readBuffer in XdrTcpDecodingStream class:

    protected void readBuffer(InputStream stream, byte  bytes, int bytesToRead)
            throws IOException, OncRpcException {
        int bytesRead;
        int byteOffset = 0;

        long start = System.currentTimeMillis();
        if (debugout != null) {
            String msg = "readBuffer: start, bytesToRead=" + bytesToRead;
            msg = "/* " + formatter.format(start) + " */" + msg;
            debugout.println(msg);
        }

        while ( bytesToRead > 0 ) {
            bytesRead = stream.read(bytes, byteOffset, bytesToRead);
            if ( bytesRead < 0 ) {
                //
                // Stream is at EOF - note that bytesRead is not allowed
                // to be zero here, as we asked for at least one byte…
                //
                if (debugout != null) {
                    String msg = "readBuffer: EOF: bytesToRead=" + bytesToRead +
                                ", byteOffset=" + byteOffset +
                                ", bytesRead=" + bytesRead;
                    debugout.println("/* " + formatter.format(System.currentTimeMillis()) + " */" + msg);
                }
                throw(new OncRpcException(OncRpcException.RPC_CANTRECV));
            } else if (bytesRead == 0) {
                //
                // In NIO mode 0 bytes read means there was nothing to read on this channel
                // for now, we need to wait for following rounds to fill the whole buffer.
                //
                long current = System.currentTimeMillis();
                if ((current - start) > 30000){
                    if (debugout != null) {
                        String msg = "readBuffer: Nothing to read: bytesToRead=" + bytesToRead +
                                    ", byteOffset=" + byteOffset +
                                    ", bytesRead=" + bytesRead;
                    debugout.println("/* " + formatter.format(System.currentTimeMillis()) + " */" + msg);
                    }
                    throw(new OncRpcException(OncRpcException.RPC_CANTRECV));
                }
                if (debugout != null) {
                    String msg = "readBuffer retrying";
                    msg = "/* " + formatter.format(System.currentTimeMillis()) + " */" + msg;
                    debugout.println(msg);
                }
            }
            bytesToRead -= bytesRead;
            byteOffset += bytesRead;

            if (debugout != null) {
                String msg = "readBuffer: bytesToRead=" + bytesToRead +
                            ", byteOffset=" + byteOffset +
                            ", bytesRead=" + bytesRead;
                msg = "/* " + formatter.format(System.currentTimeMillis()) + " */" + msg;
                debugout.println(msg);
            }
        }
    }

This is what debugOut looks like when this exception happens:

….

/* Wed Oct 14 2009 07:46:14.590 */call: ProcNumber=78 Sending…. msgId=1392808127

/* Wed Oct 14 2009 07:46:14.590 */flush: lastFragment=true batch=false bufferIndex=424 bufferHighmark=500124

/* Wed Oct 14 2009 07:46:14.590 */streamFlush, bytes=424

/* Wed Oct 14 2009 07:46:14.590 */call: ProcNumber=78 Receiving….

/* Wed Oct 14 2009 07:46:14.590 */readBuffer: start, bytesToRead=4

/* Wed Oct 14 2009 07:46:14.590 */readBuffer: EOF: bytesToRead=4, byteOffset=0, bytesRead=-1

……

Another time:

….

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: start, bytesToRead=4

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: bytesToRead=0, byteOffset=4, bytesRead=4

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: start, bytesToRead=8996

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: bytesToRead=8680, byteOffset=316, bytesRead=316

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: bytesToRead=4300, byteOffset=4696, bytesRead=4380

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: bytesToRead=0, byteOffset=8996, bytesRead=4300

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: start, bytesToRead=4

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: EOF: bytesToRead=4, byteOffset=0, bytesRead=-1

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: start, bytesToRead=4

/* Wed Oct 14 2009 07:47:31.184 */readBuffer: EOF: bytesToRead=4, byteOffset=0, bytesRead=-1

….