unsupported frame type under heavy load

[Former user]

Hello,

I'm currently using the plug-in to connect to an Apache ActiveMQ Broker, and it works fine.

However, when I want to load test a large number of consumers (like 100 simultaneous clients), after a couple of seconds, I have this kind of errors:

2019-06-13 19:45:12,138 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Read notification'.
java.lang.RuntimeException: unsupported frame type: 13
2019-06-13 19:45:12,140 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Read notification'.
java.lang.RuntimeException: unsupported frame type: 5
2019-06-13 19:45:12,141 ERROR e.l.j.w.SingleReadWebSocketSampler: Unexpected frame type received in sampler 'WebSocket Single Read Sampler - Read notification': Binary frame, payload (length 100): 0x61 0x74 0x65 0x48 0x65 0x75 0x72 0x65 0x46 0x69 0x6e 0x50 0x75 0x62 0x6c 0x69 ...
2019-06-13 19:45:12,142 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Read notification'.
java.lang.RuntimeException: unsupported frame type: 15
2019-06-13 19:45:12,393 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Read notification'.
java.lang.RuntimeException: unsupported frame type: 14

Those frame type does not seem to exist as per the RFC, so I'm not sure of what's going on :)

I don't have have this kind of problem with 10 consumers. Is there a chance that the component does not handle correctly a large number of consumers ?

Thanks in advance!

[Nicolas Casaux]

I should mention that it seems that this issue occurs on consumers/connections “1 by 1”. Indeed, it occurs on one consumer/connection, then after a couple of seconds on another one, etc etc… All the consumers are NOT suddenly disconnected and they are all supposed to get the same data (FYI: they have all subscribed to the same JMS topic).

[Peter Doornbosch]

Hi,

You’re not using some funny JMeter plugin that shares connections across different JMeter threads do you? That would be the only thing i can think of that could explain such behaviour….

This is very strange. Of course, i can never be 100% sure that there isn’t a bug in the plugin that causes this behaviour, but i can’t image where/how. It sounds like a concurrency error, but that is impossible, because frame parsing is always on the same thread and moreover, the parsing itself is stateless. And yes, we used this plugin a lot with hundreds of clients and never seen problems like this.

Which JMeter version are you using?

Would it be possible to create a wireshark capture of the test session? Would be nice to know if wireshark can parse all the frames correctly; if it does we are sure there is an issue in the plugin…

Regards, Peter

[Nicolas Casaux]

Hi Peter,

I’m using version 5.1.1 of JMeter, and I do not use any funny JMeter plugin for connections across threads . Only 1 thread group with 100 users.

I’m using JMeter on Windows 10 if this can help.

Tomorrow I will try to capture some packets with Wireshark if I have enough time

Regards, Nicolas

[Peter Doornbosch]

Would be nice, please let me know the outcome.

1 thread group with 100 users should be no problem at all. If i’ve time, i’ll check whether they’ve changed threading in JMeter 5….

[Nicolas Casaux]

Hi Peter,

After further investigation, the problem seems to be linked to the proxy and/or the network I’m using. I did some tests with another proxy/network, and I managed to have 100s of users getting lots of data for like 1 hour. After some time, a few (<5) users still get the same error, but again, I think it’s related to the network and/or the proxy.

Thanks for your help and for your plug-in !

Regards, Nicolas

[Peter Doornbosch]

Hi Nicolas,

Thanks for your reply. However, i doubt that the proxy or network is the cause. TCP guarantees ordered delivery, so all bytes you receive are the same as the peer has sent and in the same order. Network devices in between don’t change that. So either your server is not sending correct bytes, or the plugin has a bug that somehow doesn’t process incoming bytes correctly….

So, if it would be possible to capture a test session with the original setup (the more errors the better), that would still be nice in order to be sure whether there is a bug in the plugin or not.

Regards, Peter

[Nicolas Casaux]

Hi Peter,

I don’t want to waste your time as I really think there is not such issue with your plug-in. Indeed, without proxy at all, I didn’t get those errors.

Regards,

Nicolas

[Peter Doornbosch]

Ok, thanks!

[nosalan]

Hi

@Nicolas Casaux could you tell what was the exact network/proxy configuration that resolved this problem?

I started having exactly the same issue after some changes were made in the intermediate network layers. I only know there was an nginx upgrade, however, don’t have access to this networking layer to find out more.

What’s interesting is that other applications (like Python websocket clients) didn’t suffer from the changes. But the JMeter WebSocket Sampler is now failing almost 100% of time. It was working before.

What I can tell is that the new network doesn’t fragment frames as much as old network (now continuation frames are used much less and frames are larger)

Do you have any Idea what could be the issue?

I attach several errors I get from the read sampler. One of them is really interesting, looks like it treats part of message body as the close reason.

Code: Sampler error: unexpected frame type (non-final binary)., Message: Received: Binary frame, payload (length 58): 0x22 0x62 0x69 0x6f 0x6c 0x6f 0x67 0x69 0x63 0x61 0x6c 0x22 0x2c 0x22 0x63 0x6f ..., Body:
Code: Websocket I/O error, Message: WebSocket I/O error: no continuation frame expected, Body:
Code: Sampler error: unexpected frame type (non-final binary)., Message: Received: Binary frame, payload (length 116): 0x54 0x69 0x6d 0x65 0x22 0x3a 0x34 0x2e 0x30 0x32 0x30 0x30 0x2c 0x22 0x65 0x6e ..., Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 5, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 4, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 13, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 3, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 5, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 4, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 4, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 15, Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 4, Body:
Code: Sampler error: unexpected frame type (close)., Message: Received: Close frame with status code 12332 and close reason '"endTime":2.4900},{"word":"a","confidence":1.0', Body:
Code: Sampler error, Message: Sampler error: java.lang.RuntimeException: unsupported frame type: 4, Body:
Code: Websocket I/O error, Message: WebSocket I/O error: missing continuation frame, Body:

‌

This is also an excerpt from the jmeter.log, it occurs for the unsupported frame type error

2019-09-23 16:52:04,423 DEBUG e.l.j.w.SingleReadWebSocketSampler: Added filter Ping Frame Filter 'WebSocket Ping/Pong Frame Filter' to sampler WS Read sampler 'WebSocket Single Read Sampler - Thread: 0094'; filter list is now [Ping Frame Filter 'WebSocket Ping/Pong Frame Filter']
2019-09-23 16:52:04,424 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Thread: 0094'.
java.lang.RuntimeException: unsupported frame type: 5
at eu.luminis.websocket.Frame.parseFrame(Frame.java:111) ~[jmeter-websocket-samplers-1.2.2.jar:?]
at eu.luminis.websocket.WebSocketClient.receiveFrame(WebSocketClient.java:407) ~[jmeter-websocket-samplers-1.2.2.jar:?]
at eu.luminis.jmeter.wssampler.FrameFilter.receiveFrame(FrameFilter.java:69) ~[jmeter-websocket-samplers-1.2.2.jar:?]
at eu.luminis.jmeter.wssampler.WebsocketSampler.readFrame(WebsocketSampler.java:296) ~[jmeter-websocket-samplers-1.2.2.jar:?]
at eu.luminis.jmeter.wssampler.SingleReadWebSocketSampler.doSample(SingleReadWebSocketSampler.java:69) ~[jmeter-websocket-samplers-1.2.2.jar:?]
at eu.luminis.jmeter.wssampler.WebsocketSampler.sample(WebsocketSampler.java:169) [jmeter-websocket-samplers-1.2.2.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(Unknown Source) [?:1.8.0_221]
2019-09-23 16:52:04,425 INFO o.a.j.e.J.Reader PostProcessor: Previous Response Code for 0094/975 is: Sampler error

‌

[Peter Doornbosch]

Hi nosalan,

Thanks for your feedback. Would it somehow be possible to create a WireShark capture of a test session that fails? Would be great if that is possible…. You can email it to me, or if that’s not possible because of sensitive data, we can arrange something else.

A few questions about the problem: do errors occur right from the start, or does it first read a number of frames correctly before it starts to fail? You are talking about larger frames, what is a typical frame size in the failing scenario?

Also, let me double-check: you are using the latest version of the plugin, right?

Thanks

Peter

‌

[Peter Doornbosch]

Before anything else: can you try the attached 1.2.3 version? Make sure the original version of the plugin is removed from the JMeter directories and please check in the GUI that the right plugin version is running (any websocket sampler → “Check for udpates”). Then repeat your test and check the logs for the following error message: “Blocking read fails with 0 bytes read.“. If this message appears, just let me know, as that means we’ve found the cause. If it does not, please answer the questions in my comment above .

Thanks in advance for your cooperation.

Regards

Peter

[nosalan]

Hi Peter,

Thanks for an immediate support. I can confirm these messages appear in log. There’s been over 2000 of these entries in my 100 threads run. There are also the entries with unsupported frame type. I would be glad to test the fixed version.

Thanks

[Peter Doornbosch]

Ok, that’s nice. Creating a fix will take a few days, as i don’t have much time to spend on this project….

[Peter Doornbosch]

Can you test with this version?

[nosalan]

Thanks for a new version. However, I get following error in all threads at some point:
2019-09-30 10:52:50,600 ERROR e.l.j.w.SingleReadWebSocketSampler: Unhandled error in sampler 'WebSocket Single Read Sampler - Thread: 0008'.
java.lang.ArrayIndexOutOfBoundsException: 0
at eu.luminis.websocket.Frame.readFromStream(Frame.java:215) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.websocket.Frame.readFromStream(Frame.java:187) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.websocket.Frame.parseFrame(Frame.java:92) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.websocket.WebSocketClient.receiveFrame(WebSocketClient.java:407) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.jmeter.wssampler.FrameFilter.receiveFrame(FrameFilter.java:69) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.jmeter.wssampler.WebsocketSampler.readFrame(WebsocketSampler.java:296) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.jmeter.wssampler.SingleReadWebSocketSampler.doSample(SingleReadWebSocketSampler.java:69) ~[JMeterWebSocketSamplers-1.2.4.jar:?]
at eu.luminis.jmeter.wssampler.WebsocketSampler.sample(WebsocketSampler.java:169) [JMeterWebSocketSamplers-1.2.4.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(Unknown Source) [?:1.8.0_221]

[Peter Doornbosch]

That should have been fixed by this version. Can you try again?

Even if it succeeds, can you send (mail) the jmeter log file to me? I’m still curious whether certain situations occurs after these changes….

Thanks in advance!

Regards
Peter

[nosalan]

Thanks again. I’ve sent the logs but still get the original "Unexpected frame type" on version 1.2.5. No ArrayIndexOutOfBoundsException any more.

[Peter Doornbosch]

As discussed: this should fix parse errors after a read timeout.

[nosalan]

Tkanks. I'll try to test it today or tomorrow.

niedz., 6 paź 2019, 21:45 użytkownik Peter Doornbosch <

[Peter Doornbosch]

[nosalan]

Hi Peter. Looks like 1.2.6 version has solved the issue

I didn’t encounter the original errors so far. I will be doing some more testing this and next week and will get back to you if I find anything.

There are log entries like:
2019-10-09 14:36:40,836 ERROR e.l.w.WebSocketClient: 0-length payload for frame 9
2019-10-09 14:36:40,837 ERROR e.l.w.WebSocketClient: readFromStream() called for reading 0 bytes

However, these look more like diagnostic messages for empty pings.

Thanks a lot for supporting your project actively.

[Peter Doornbosch]

Hi,

Thanks for the follow up. Indeed, those messages are not real errors but diagnostics, i only log them on error level so they appear in your log and i was curious if they appear.

I’m glad we finally solved the issue. Thank you for your active involvement in this bug, that was crucial for being able to fix this. This bug has annoyed me since this issue was created, but i was never able to fix it, due to lack of detailled input. Your info and willingness to test with various releases was very valuable and much appreciated.

I will merge the fixes into an official release and also correct the log level of the diagnostic messages.