I/O Error in sampler. Read timed out

[nosalan]

Hi

I get the error pasted below from the read sampler. I am using the prerelease version 1.2.6 that spun from the #115 issue. What’s interesting is that it happens when testing WSS endpoint only and not WS. It also doesn’t always occur, it’s usually working for minute or two and then fails. The endpoint I test sends larger and larger responses over test time. It initially sends messages of several hundreds of bytes in size and read sampler works file, but when it gets to around 20kbytes it fails. If I modified the server to respond always with 500 bytes messages, it worked fine the entire test over WSS. I also have Optional read (read timeout will not lead to sampler error) option enabled. I also modified the server being tested to use continuation frames if message was larger than 4096 bytes but it didn’t help.
I thought it may be problem with TLS but the Python script I run worked fine with larger messages as well. So it seems this issue may be Sampler related.

‌

2019-11-04 15:23:21,563 DEBUG e.l.j.w.SingleReadWebSocketSampler: I/O Error in sampler 'WebSocket Single Read Sampler - Thread: 0000'.
javax.net.ssl.SSLException: Read timed out
    at sun.security.ssl.Alert.createSSLException(Alert.java:127) ~[?:?]
    at sun.security.ssl.TransportContext.fatal(TransportContext.java:324) ~[?:?]
    at sun.security.ssl.TransportContext.fatal(TransportContext.java:267) ~[?:?]
    at sun.security.ssl.TransportContext.fatal(TransportContext.java:262) ~[?:?]
    at sun.security.ssl.SSLTransport.decode(SSLTransport.java:137) ~[?:?]
    at sun.security.ssl.SSLSocketImpl.decode(SSLSocketImpl.java:1463) ~[?:?]
    at sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1431) ~[?:?]
    at sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1022) ~[?:?]
    at java.io.BufferedInputStream.fill(BufferedInputStream.java:245) ~[?:?]
    at java.io.BufferedInputStream.read1(BufferedInputStream.java:285) ~[?:?]
    at java.io.BufferedInputStream.read(BufferedInputStream.java:344) ~[?:?]
    at eu.luminis.websocket.Frame.readFromStream(Frame.java:245) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.websocket.Frame.readFromStream(Frame.java:218) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.websocket.Frame.parseFrame(Frame.java:107) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.websocket.WebSocketClient.receiveFrame(WebSocketClient.java:407) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.jmeter.wssampler.FrameFilter.receiveFrame(FrameFilter.java:69) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.jmeter.wssampler.WebsocketSampler.readFrame(WebsocketSampler.java:296) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.jmeter.wssampler.SingleReadWebSocketSampler.doSample(SingleReadWebSocketSampler.java:69) ~[JMeterWebSocketSamplers-1.2.6.jar:?]
    at eu.luminis.jmeter.wssampler.WebsocketSampler.sample(WebsocketSampler.java:169) [JMeterWebSocketSamplers-1.2.6.jar:?]
    at org.apache.jmeter.threads.JMeterThread.doSampling(JMeterThread.java:622) [ApacheJMeter_core.jar:5.1.1 r1855137]
    at org.apache.jmeter.threads.JMeterThread.executeSamplePackage(JMeterThread.java:546) [ApacheJMeter_core.jar:5.1.1 r1855137]
    at org.apache.jmeter.threads.JMeterThread.processSampler(JMeterThread.java:486) [ApacheJMeter_core.jar:5.1.1 r1855137]
    at org.apache.jmeter.threads.JMeterThread.run(JMeterThread.java:253) [ApacheJMeter_core.jar:5.1.1 r1855137]
    at java.lang.Thread.run(Thread.java:830) [?:?]
Caused by: java.net.SocketTimeoutException: Read timed out
    at sun.nio.ch.NioSocketImpl.timedRead(NioSocketImpl.java:284) ~[?:?]
    at sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:310) ~[?:?]
    at sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:351) ~[?:?]
    at sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:802) ~[?:?]
    at java.net.Socket$SocketInputStream.read(Socket.java:937) ~[?:?]
    at sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:450) ~[?:?]
    at sun.security.ssl.SSLSocketInputRecord.decodeInputRecord(SSLSocketInputRecord.java:237) ~[?:?]
    at sun.security.ssl.SSLSocketInputRecord.decode(SSLSocketInputRecord.java:190) ~[?:?]
    at sun.security.ssl.SSLTransport.decode(SSLTransport.java:108) ~[?:?]
    ... 19 more

‌

[nosalan]

It looks like when I reverted to Oracle JDK8 it stopped occurring. Previously I used OpenJDK 13

[Peter Doornbosch]

Hi Andrzej,

Thanks for reporting.

I don’t have a clue (yet); this is strange because SSL is completely handled by the JDK and should be completely transparent to the plugin (once it is setup at leaset).

With what frequency does your endpoint send messages and how does this relate to the timeout configured in the sampler?

Regards

Peter

‌

[nosalan]

Hi. The tested endpoint sends messages at various rate, but no more than 2/second. They can to be large tough (10-200KB). After bit of testing I can definitely say that with JDK8 this problem doesn’t show up anymore.

[Peter Doornbosch]

Hi,

1. What is the value of the timeout configured in the read sampler?
2. When the error occurs, is the rate at which messages are send around 2/second? You say “no more than”, but i’m actually interested in the lower bound of the message rate . And how it relates to the read timeout in the sampler.
3. Does the test plan use frame filters?

Let me explain why i’m asking all these question. What could happen if the socket timeout is short, that the receiving of a complete SSL record fails because the network stream does not deliver all bytes in time. The way the SSL library works is that is aborts the connection with an SSL Alert. The sampler does not recognise this as a socket timeout - and if it did, it would be useless, because the SSL connection cannot be resumed since the SSL lib has aborted the connection. This is a big difference with the non-ssl case: if a read timeout occurs in the TCP connection, the sampler can resume reading bytes from the connection.

I would expect (with the knowledge i have now, must investigate more) that such a scenario would only occur if the timeout is relatively small. The socket timeout used is the read timeout you configure in the sampler, but when frame filters are used, the socket timeout is computed from the read timeout and time passed and so can become significantly smaller than the read timeout.

If i’ve time, i’ll setup a few experiments to investigate my assumptions.

Again, thanks for writing such excellent problem report; I’d wish more people would do i it like this .

Regards

Peter

‌

[nosalan]

Hi

1. The read timeout on read sampler varies between 100 and 500 ms and is computed via groovy expression
2. Actually the write sampler sends 2 messages/sec. If you ask about received messages (read sampler), then it is usually no more than 1 per second though the received messages are small at the beginning and larger at the end.
3. Yeah, only Ping Pong frames (with automatic reply with Pong under each Read Samplers are used.

Regarding this timeout option on read sampler, I assume this is timeout waiting for anything on the websocket but not timeout for receiving once it has started? Lets say a message shows up lets 1 ms before the timeout ends, does it mean it will be anandoned (or cause the SSL lib error you mentioned)?

Thanks for taking a look into this

‌