Bug 52072 - LengthPrefixedBinaryTcpClientImpl may end a sample prematurely
LengthPrefixedBinaryTcpClientImpl may end a sample prematurely
Status: RESOLVED FIXED
Product: JMeter
Classification: Unclassified
Component: Main
2.5.1
PC All
: P2 normal (vote)
: ---
Assigned To: JMeter issues mailing list
:
Depends on:
Blocks:
  Show dependency tree
 
Reported: 2011-10-22 07:50 UTC by alexchan
Modified: 2011-10-25 18:28 UTC (History)
0 users



Attachments

Note You need to log in before you can comment on or make changes to this bug.
Description alexchan 2011-10-22 07:50:56 UTC
LengthPrefixedBinaryTcpClientImpl may end a sample prematurely in a network environment with small MSS or client with shortage of TCP buffer.

In LengthPrefixedBinaryTcpClientImp.java, the sampler does a single read on the inputstream after the length of the message is determined:

/**
     * {@inheritDoc}
     */
    public String read(InputStream is) {
        byte[] msg = new byte[0];
        int msgLen = 0;
        try {
            byte[] lengthBuffer = new byte[lengthPrefixLen];
            if (is.read(lengthBuffer, 0, lengthPrefixLen) == lengthPrefixLen) {
                msgLen = byteArrayToInt(lengthBuffer);
                msg = new byte[msgLen];
                int bytes = is.read(msg);
                if (bytes < msgLen){
                    log.warn("Incomplete message read, expected: "+msgLen+" got: "+bytes);
                }
            }
        } catch (SocketTimeoutException e) {
            // drop out to handle buffer
        } catch (InterruptedIOException e) {
            // drop out to handle buffer
        } catch (IOException e) {
            log.warn("Read error:" + e);
        }

        String buffer = JOrphanUtils.baToHexString(msg);
        log.debug("Read: " + msgLen + "\n" + buffer);
        return buffer;
    }

In a network with small MSS or a client with shortage of buffer (e.g. during a stress test), the response message may not be returned completely in just one call to is.read(msg). When this occurs, the sampler mistakenly assumes that the response is complete and leads to the following problems. Let's call the first sample S1, the next one S2 etc.

1. It reports a wrong response time shorter than the actual one for S1

2. In case "Re-use connection" is set to true, the remaining bytes of the response message of S1 in the TCP stream confuses the sampler in the next sample, S2. The sampler thinks that these bytes are the initial part of the response of S2 and therefore reports another wrong and unrealistically short response time for S2. Worse, it now sends yet another new sample S3 because it thinks that S2 has completed. This may cause problem to the server side if the server side assumes the stop-and-wait nature of the connection in order to function correctly. 

In other words, this bug may render the stress test ineffective in these circumstances because of the wrong response times and problems triggered on the server side.
Comment 1 alexchan 2011-10-22 08:06:36 UTC
I have created a temporary fix , at least it works for my case and let me pass my stress test :)
Caveat: The actual timeout may be multiplied by the actual number of read required in the extreme case.

public String read(InputStream is) {
        byte[] msg = new byte[0];
        int msgLen = 0;
        /* BEGFIX */
        int nleft = 0;
        int nread = 0;
        int offset = 0;
        /* ENDFIX */
        try {
            byte[] lengthBuffer = new byte[lengthPrefixLen];
            if (is.read(lengthBuffer, 0, lengthPrefixLen) == lengthPrefixLen) {
                msgLen = byteArrayToInt(lengthBuffer);
                msg = new byte[msgLen];
                /* BEGFIX
                int bytes = is.read(msg);
                if (bytes < msgLen){ 
                     log.warn("Incomplete message read, expected: "+msgLen+"
got: "+bytes);
                }
                ENDFIX */
                /* BEGFIX */
                nleft = msgLen;
                offset = 0;
                while (nleft > 0) {
                    nread = is.read(msg, offset, nleft);
                    nleft = nleft - nread;
                    offset = offset + nread;
                }
                /* ENDFIX */
            }
        } catch (SocketTimeoutException e) {
            // drop out to handle buffer
        } catch (InterruptedIOException e) {
            // drop out to handle buffer
        } catch (IOException e) {
            log.warn("Read error:" + e);
        }

        String buffer = JOrphanUtils.baToHexString(msg);
        log.debug("Read: " + msgLen + "\n" + buffer);
        return buffer;
    }
Comment 2 Sebb 2011-10-22 22:31:47 UTC
Good catch - there is clearly a bug here.

If "re-use connection" is selected, and the sample ends prematurely even after fixing this bug, seems to me this should be treated as an error, and the connection should be closed. Otherwise the error can propagate to the next sample.
Comment 3 Sebb 2011-10-25 18:28:47 UTC
Fixed the incomplete read issue:

URL: http://svn.apache.org/viewvc?rev=1188830&view=rev
Log:
Bug 52072 - LengthPrefixedBinaryTcpClientImpl may end a sample prematurely

Modified:
   jakarta/jmeter/trunk/src/jorphan/org/apache/jorphan/util/JOrphanUtils.java
   jakarta/jmeter/trunk/src/protocol/tcp/org/apache/jmeter/protocol/tcp/sampler/LengthPrefixedBinaryTCPClientImpl.java
   jakarta/jmeter/trunk/xdocs/changes.xml

However, this still leaves the issue of how to handle re-use connection.

At present, this is quite tricky, as the API does not allow for returning a status to the controlling sampler.

See Bug 52087 which has been raised to cover this aspect.