search

Links2004 / arduinoWebSockets

arduinoWebSockets
GNU Lesser General Public License v2.1
1.89k stars 555 forks source link

[ESP8266] Websocket Client STOMP over SockJS with Spring Boot - Disconnected! #595

Open cgisca opened 3 years ago

cgisca commented 3 years ago

I am following next guide on how to set up Spring Boot STOMP over SockJS websocket server. Tested with Android client and it works as expected. But when using current library for ESP8266, I am not able to connect to the server. I am using WebSocketClientStompOverSockJs.ino example for esp8266, and changing WiFi credentials, IP address and port of the running Spring Boot server in localhost. If I change ws_baseurl from "/socketentry/" to "/gs-guide-websocket/" (if following Spring boot tutorial registry.addEndpoint("/gs-guide-websocket").withSockJS();) then I am getting repeatedly Connected Disconnected!, as shown below:

Logging into WLAN: ******* ...scandone
13:33:19.365 -> state: 0 -> 2 (b0)
13:33:19.365 -> state: 2 -> 3 (0)
13:33:19.365 -> state: 3 -> 5 (10)
13:33:19.399 -> add 0
13:33:19.399 -> aid 19
13:33:19.399 -> cnt 
13:33:19.399 -> state: 5 -> 2 (4a0)
13:33:19.399 -> rm 0
13:33:19.764 -> ..reconnect
13:33:20.394 -> state: 2 -> 0 (0)
13:33:20.494 -> scandone
13:33:20.494 -> state: 0 -> 2 (b0)
13:33:20.494 -> state: 2 -> 3 (0)
13:33:20.494 -> state: 3 -> 5 (10)
13:33:20.494 -> add 0
13:33:20.494 -> aid 54
13:33:20.527 -> cnt 
13:33:20.759 -> ........state: 5 -> 2 (4a0)
13:33:24.407 -> rm 0
13:33:24.739 -> ..reconnect
13:33:25.403 -> state: 2 -> 0 (0)
13:33:25.502 -> scandone
13:33:25.502 -> state: 0 -> 2 (b0)
13:33:25.502 -> state: 2 -> 3 (0)
13:33:25.502 -> state: 3 -> 5 (10)
13:33:25.536 -> add 0
13:33:25.536 -> aid 16
13:33:25.536 -> cnt 
13:33:25.536 -> 
13:33:25.536 -> connected with *******, channel 3
13:33:25.569 -> dhcp client start...
13:33:25.768 -> ....ip:192.168.100.31,mask:255.255.255.0,gw:192.168.100.1
13:33:27.759 -> . success.
13:33:27.759 -> IP: 192.168.100.31
13:33:27.990 -> [WSc] Connected to url: /gs-guide-websocket/129/566475/websocket
13:33:27.990 -> [WSc] get text: o
13:33:27.990 -> [WSc] Disconnected!
13:33:28.057 -> [WSc] Connected to url: /gs-guide-websocket/129/566475/websocket
13:33:28.057 -> [WSc] get text: o
13:33:28.057 -> [WSc] Disconnected!
13:33:28.123 -> [WSc] Connected to url: /gs-guide-websocket/129/566475/websocket
13:33:28.123 -> [WSc] get text: o
13:33:28.123 -> [WSc] Disconnected!
13:33:28.156 -> [WSc] Connected to url: /gs-guide-websocket/129/566475/websocket
13:33:28.189 -> [WSc] get text: o
13:33:28.189 -> [WSc] Disconnected!

But if I leave ws_baseurl = "/socketentry/" as it is, I am getting next logs below, continuously saying [WSc] Disconnected!, but I am getting also next error in the Spring boot server : java.lang.IllegalArgumentException: Invalid character found in method name [User-Agent:]. HTTP method names must be tokens

13:27:59.799 -> Logging into WLAN: ******* ........scandone
13:28:03.679 -> state: 0 -> 2 (b0)
13:28:03.679 -> .state: 2 -> 3 (0)
13:28:03.679 -> state: 3 -> 5 (10)
13:28:03.679 -> add 0
13:28:03.679 -> aid 49
13:28:03.679 -> cnt 
13:28:03.679 -> state: 5 -> 2 (4a0)
13:28:03.679 -> rm 0
13:28:04.177 -> ..reconnect
13:28:04.674 -> state: 2 -> 0 (0)
13:28:04.807 -> scandone
13:28:04.807 -> state: 0 -> 2 (b0)
13:28:04.807 -> state: 2 -> 3 (0)
13:28:04.807 -> state: 3 -> 5 (10)
13:28:04.807 -> add 0
13:28:04.807 -> aid 50
13:28:04.807 -> cnt 
13:28:05.172 -> ........state: 5 -> 2 (4a0)
13:28:08.690 -> rm 0
13:28:09.188 -> ..reconnect
13:28:09.685 -> state: 2 -> 0 (0)
13:28:09.818 -> scandone
13:28:09.818 -> state: 0 -> 2 (b0)
13:28:09.818 -> state: 2 -> 3 (0)
13:28:09.818 -> state: 3 -> 5 (10)
13:28:09.818 -> add 0
13:28:09.818 -> aid 51
13:28:09.818 -> cnt 
13:28:09.851 -> 
13:28:09.851 -> connected with *******, channel 3
13:28:09.851 -> dhcp client start...
13:28:10.183 -> ....ip:192.168.100.31,mask:255.255.255.0,gw:192.168.100.1
13:28:12.174 -> . success.
13:28:12.174 -> IP: 192.168.100.31
13:28:12.406 -> [WSc] Disconnected!
13:28:12.936 -> [WSc] Disconnected!
13:28:13.533 -> [WSc] Disconnected!
13:28:14.131 -> [WSc] Disconnected!
13:28:14.762 -> [WSc] Disconnected!
13:28:15.359 -> [WSc] Disconnected!
13:28:15.957 -> [WSc] Disconnected!
13:28:16.587 -> [WSc] Disconnected!
13:28:17.218 -> [WSc] Disconnected!
13:28:17.815 -> [WSc] Disconnected!
Detailed error in Spring Boot server:
2020-12-30 13:33:57.773  INFO 16708 --- [MessageBroker-4] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[0 current WS(0)-HttpStream(0)-HttpPoll(0), 323 total, 0 closed abnormally (0 connect failure, 0 send limit, 0 transport error)], stompSubProtocol[processed CONNECT(0)-CONNECTED(0)-DISCONNECT(0)], stompBrokerRelay[null], inboundChannel[pool size = 8, active threads = 0, queued tasks = 0, completed tasks = 969], outboundChannel[pool size = 8, active threads = 0, queued tasks = 0, completed tasks = 323], sockJsScheduler[pool size = 4, active threads = 1, queued tasks = 1, completed tasks = 6]
2020-12-30 13:56:17.935  INFO 16708 --- [nio-8080-exec-8] o.apache.coyote.http11.Http11Processor   : Error parsing HTTP request header
 Note: further occurrences of HTTP request parsing errors will be logged at DEBUG level.

java.lang.IllegalArgumentException: Invalid character found in method name [User-Agent:]. HTTP method names must be tokens
    at org.apache.coyote.http11.Http11InputBuffer.parseRequestLine(Http11InputBuffer.java:417) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:261) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) ~[na:na]
    at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) ~[na:na]
    at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) ~[tomcat-embed-core-9.0.41.jar:9.0.41]
    at java.base/java.lang.Thread.run(Thread.java:830) ~[na:na]

From stackoverflow, this exception seems to occur when client try to execute https request on endpoint which isn't https enabled.

@Links2004 could you please help me understand what I am doing wrong. I am struggling with this couple of days and can't find the solution to make it work. Thanks in advance

Links2004 commented 3 years ago

Hi,

I never used stomp myself but we can start with the basics :) please enable the debug output of the lib via the IDE menu or build_flags = -D DEBUG_ESP_PORT=Serial for platformIO. with that output we get more info then only the "Disconnected"

cgisca commented 3 years ago

Sorry, here is the debug output :

21:39:40.264 -> Logging into WLAN: ******* ...scandone
21:39:40.397 -> state: 0 -> 2 (b0)
21:39:40.397 -> state: 2 -> 3 (0)
21:39:40.762 -> ..state: 3 -> 0 (4)
21:39:41.393 -> reconnect
21:39:41.525 -> scandone
21:39:41.525 -> state: 0 -> 2 (b0)
21:39:41.525 -> state: 2 -> 3 (0)
21:39:41.525 -> state: 3 -> 5 (10)
21:39:41.525 -> add 0
21:39:41.525 -> aid 105
21:39:41.525 -> cnt 
21:39:41.791 -> ..
21:39:42.587 -> connected with *******, channel 3
21:39:42.587 -> dhcp client start...
21:39:42.786 -> ....ip:192.168.100.31,mask:255.255.255.0,gw:192.168.100.1
21:39:44.780 -> . success.
21:39:44.780 -> IP: 192.168.100.31
21:39:44.780 -> [WS-Client] connect ws...
21:39:45.875 -> [WS-Client] connected to 192.168.100.6:8080.
21:39:45.875 -> [WS-Client][sendHeader] sending header...
21:39:45.875 -> [WS-Client][sendHeader] handshake GET /gs-guide-websocket/992/587011/websocket HTTP/1.1
21:39:45.875 -> Host: 192.168.100.6:8080
21:39:45.875 -> Connection: Upgrade
21:39:45.875 -> Upgrade: websocket
21:39:45.875 -> Sec-WebSocket-Version: 13
21:39:45.908 -> Sec-WebSocket-Key: rB/JIvdgKBccWyIRmQYraQ==
21:39:45.908 -> Sec-WebSocket-Protocol: arduino
21:39:45.908 -> 
21:39:45.908 -> User-Agent: arduino-WebSocket-Client
21:39:45.908 -> 
21:39:45.908 -> [write] n: 269 t: 5686
21:39:45.908 -> [WS-Client][sendHeader] sending header... Done (25469us).
21:39:45.999 -> [WS-Client][handleHeader] RX: HTTP/1.1 200
21:39:45.999 -> [WS-Client][handleHeader] RX: Vary: Origin
21:39:45.999 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Method
21:39:45.999 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Headers
21:39:45.999 -> [WS-Client][handleHeader] RX: Content-Length: 0
21:39:45.999 -> [WS-Client][handleHeader] RX: Date: Wed, 30 Dec 2020 19:39:45 GMT
21:39:45.999 -> [WS-Client][handleHeader] Header read fin.
21:39:45.999 -> [WS-Client][handleHeader] Client settings:
21:39:45.999 -> [WS-Client][handleHeader]  - cURL: /gs-guide-websocket/992/587011/websocket
21:39:45.999 -> [WS-Client][handleHeader]  - cKey: rB/JIvdgKBccWyIRmQYraQ==
21:39:45.999 -> [WS-Client][handleHeader] Server header:
21:39:45.999 -> [WS-Client][handleHeader]  - cCode: 200
21:39:45.999 -> [WS-Client][handleHeader]  - cIsUpgrade: 0
21:39:45.999 -> [WS-Client][handleHeader]  - cIsWebsocket: 1
21:39:45.999 -> [WS-Client][handleHeader]  - cAccept: 
21:39:45.999 -> [WS-Client][handleHeader]  - cProtocol: arduino
21:39:45.999 -> [WS-Client][handleHeader]  - cExtensions: 
21:39:45.999 -> [WS-Client][handleHeader]  - cVersion: 0
21:39:45.999 -> [WS-Client][handleHeader]  - cSessionId: 
21:39:45.999 -> [WS-Client][handleHeader] no Websocket connection close.
21:39:46.012 -> [write] n: 27 t: 5801
21:39:46.073 -> [WS-Client] client disconnected.
21:39:46.073 -> [WSc] Disconnected!
21:39:46.504 -> [WS-Client] connect ws...
21:39:46.504 -> [WS-Client] connected to 192.168.100.6:8080.
21:39:46.504 -> [WS-Client][sendHeader] sending header...
21:39:46.537 -> [WS-Client][sendHeader] handshake GET /gs-guide-websocket/992/587011/websocket HTTP/1.1
21:39:46.537 -> Host: 192.168.100.6:8080
21:39:46.537 -> Connection: Upgrade
21:39:46.537 -> Upgrade: websocket
21:39:46.537 -> Sec-WebSocket-Version: 13
21:39:46.537 -> Sec-WebSocket-Key: b8RlQDjxmB1ZKbmx2Ndc8Q==
21:39:46.537 -> Sec-WebSocket-Protocol: arduino
21:39:46.537 -> 
21:39:46.537 -> User-Agent: arduino-WebSocket-Client
21:39:46.537 -> 
21:39:46.537 -> [write] n: 269 t: 6330
21:39:46.537 -> [WS-Client][sendHeader] sending header... Done (25216us).
21:39:46.570 -> [WS-Client][handleHeader] RX: HTTP/1.1 200
21:39:46.570 -> [WS-Client][handleHeader] RX: Vary: Origin
21:39:46.570 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Method
21:39:46.570 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Headers
21:39:46.604 -> [WS-Client][handleHeader] RX: Content-Length: 0
21:39:46.604 -> [WS-Client][handleHeader] RX: Date: Wed, 30 Dec 2020 19:39:45 GMT
21:39:46.604 -> [WS-Client][handleHeader] Header read fin.
21:39:46.604 -> [WS-Client][handleHeader] Client settings:
21:39:46.604 -> [WS-Client][handleHeader]  - cURL: /gs-guide-websocket/992/587011/websocket
21:39:46.604 -> [WS-Client][handleHeader]  - cKey: b8RlQDjxmB1ZKbmx2Ndc8Q==
21:39:46.637 -> [WS-Client][handleHeader] Server header:
21:39:46.637 -> [WS-Client][handleHeader]  - cCode: 200
21:39:46.637 -> [WS-Client][handleHeader]  - cIsUpgrade: 0
21:39:46.637 -> [WS-Client][handleHeader]  - cIsWebsocket: 0
21:39:46.637 -> [WS-Client][handleHeader]  - cAccept: 
21:39:46.637 -> [WS-Client][handleHeader]  - cProtocol: arduino
21:39:46.637 -> [WS-Client][handleHeader]  - cExtensions: 
21:39:46.637 -> [WS-Client][handleHeader]  - cVersion: 0
21:39:46.637 -> [WS-Client][handleHeader]  - cSessionId: 
21:39:46.670 -> [WS-Client][handleHeader] no Websocket connection close.
21:39:46.670 -> [write] n: 27 t: 6441
21:39:46.670 -> [WS-Client] client disconnected.
21:39:46.670 -> [WSc] Disconnected!
Links2004 commented 3 years ago

ok, the log clearly shows that your server does not answer with a websocket response. it is delivering a 200 with no content (Content-Length: 0).

the response that is needed looks something like this:

HTTP/1.1 101 Switching Protocols
Upgrade: websocket
Connection: Upgrade
Sec-WebSocket-Accept: <BASE64 here>

currently the server answers with this:

HTTP/1.1 200
Vary: Origin
Vary: Access-Control-Request-Method
Vary: Access-Control-Request-Headers
Content-Length: 0
Date: Wed, 30 Dec 2020 19:39:45 GMT
cgisca commented 3 years ago

thanks for the indication, I managed to get the server response that you mentioned, but I get instantly the connection lost from the client and it tries to connect and disconnect repeatedly . Do you have any clue what should be the problem? thanks

21:05:37.179 -> [WS-Client] connect ws...
21:05:37.246 -> [WS-Client] connected to 192.168.100.6:8080.
21:05:37.279 -> [WS-Client][sendHeader] sending header...
21:05:37.279 -> [WS-Client][sendHeader] handshake GET /gs-guide-websocket/746/969169/websocket HTTP/1.1
21:05:37.279 -> Host: 192.168.100.6:8080
21:05:37.279 -> Connection: Upgrade
21:05:37.279 -> Upgrade: websocket
21:05:37.279 -> Sec-WebSocket-Version: 13
21:05:37.279 -> Sec-WebSocket-Key: SzU3JDYfcmRBAcM+5UWbjQ==
21:05:37.279 -> Sec-WebSocket-Protocol: arduino
21:05:37.279 -> 
21:05:37.279 -> User-Agent: arduino-WebSocket-Client
21:05:37.312 -> 
21:05:37.312 -> [write] n: 269 t: 116438
21:05:37.312 -> [WS-Client][sendHeader] sending header... Done (25436us).
21:05:37.411 -> [WS-Client][handleHeader] RX: HTTP/1.1 101
21:05:37.411 -> [WS-Client][handleHeader] RX: Vary: Origin
21:05:37.411 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Method
21:05:37.411 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Headers
21:05:37.411 -> [WS-Client][handleHeader] RX: Upgrade: websocket
21:05:37.444 -> [WS-Client][handleHeader] RX: Connection: upgrade
21:05:37.444 -> [WS-Client][handleHeader] RX: Sec-WebSocket-Accept: l+xtUm2WLULxPu1ValkdKrrffHc=
21:05:37.444 -> [WS-Client][handleHeader] RX: Date: Fri, 01 Jan 2021 19:05:37 GMT
21:05:37.444 -> [WS-Client][handleHeader] Header read fin.
21:05:37.444 -> [WS-Client][handleHeader] Client settings:
21:05:37.444 -> [WS-Client][handleHeader]  - cURL: /gs-guide-websocket/746/969169/websocket
21:05:37.444 -> [WS-Client][handleHeader]  - cKey: SzU3JDYfcmRBAcM+5UWbjQ==
21:05:37.477 -> [WS-Client][handleHeader] Server header:
21:05:37.477 -> [WS-Client][handleHeader]  - cCode: 101
21:05:37.477 -> [WS-Client][handleHeader]  - cIsUpgrade: 1
21:05:37.477 -> [WS-Client][handleHeader]  - cIsWebsocket: 1
21:05:37.477 -> [WS-Client][handleHeader]  - cAccept: l+xtUm2WLULxPu1ValkdKrrffHc=
21:05:37.477 -> [WS-Client][handleHeader]  - cProtocol: arduino
21:05:37.477 -> [WS-Client][handleHeader]  - cExtensions: 
21:05:37.477 -> [WS-Client][handleHeader]  - cVersion: 0
21:05:37.511 -> [WS-Client][handleHeader]  - cSessionId: 
21:05:37.511 -> [WS-Client][handleHeader] Websocket connection init done.
21:05:37.511 -> [WS][0][headerDone] Header Handling Done.
21:05:37.511 -> [WSc] Connected to url: /gs-guide-websocket/746/969169/websocket
21:05:37.511 -> [WS-Client] connection lost.
21:05:37.511 -> [WS-Client] client disconnected.
21:05:37.511 -> [WSc] Disconnected!
21:05:37.511 -> [WS-Client] connect ws...
21:05:37.511 -> [WS-Client] connected to 192.168.100.6:8080.
21:05:37.544 -> [WS-Client][sendHeader] sending header...
21:05:37.544 -> [WS-Client][sendHeader] handshake GET /gs-guide-websocket/746/969169/websocket HTTP/1.1
21:05:37.544 -> Host: 192.168.100.6:8080
21:05:37.544 -> Connection: Upgrade
21:05:37.544 -> Upgrade: websocket
21:05:37.544 -> Sec-WebSocket-Version: 13
21:05:37.544 -> Sec-WebSocket-Key: tgLQk+O7tXi9xSfTZSxHXg==
21:05:37.544 -> Sec-WebSocket-Protocol: arduino
21:05:37.544 -> 
21:05:37.544 -> User-Agent: arduino-WebSocket-Client
21:05:37.544 -> 
21:05:37.577 -> [write] n: 269 t: 116703
21:05:37.577 -> [WS-Client][sendHeader] sending header... Done (25288us).
21:05:37.577 -> [WS-Client][handleHeader] RX: HTTP/1.1 101
21:05:37.577 -> [WS-Client][handleHeader] RX: Vary: Origin
21:05:37.577 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Method
21:05:37.610 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Headers
21:05:37.610 -> [WS-Client] connection lost.
21:05:37.610 -> [WS-Client] client disconnected.
21:05:37.610 -> [WSc] Disconnected!
Links2004 commented 3 years ago

are you sure that you are running the latest release of the lib? 2.3.1 is the latest release.

21:05:37.544 -> Sec-WebSocket-Protocol: arduino
21:05:37.544 -> 
21:05:37.544 -> User-Agent: arduino-WebSocket-Client

the empty line here looks like a bug that I fixed some time ago. https://github.com/Links2004/arduinoWebSockets/issues/577

cgisca commented 3 years ago

Yes I am using the latest lib version 2.3.1 . I found out why it was not working. In the WebSocketClientStompOverSockJs.ino example I need to remove next line 143 webSocket.setExtraHeaders();

Closing this issue as resolved. Thank you @Links2004 for your help and time.

cgisca commented 3 years ago

Actually webSocket.setExtraHeaders(); should not be removed, because the default Origin: file:// header breaks the connection with server. But if we leave webSocket.setExtraHeaders(); as is in current .ino example for some reason it ads a NEW_LINE in the headers that also is the cause of not able to connect to server. What I tried is to add a non empty header, and it worked. Instead of this webSocket.setExtraHeaders();, I used this webSocket.setExtraHeaders("foo: I am so funny\r\nbar: not");

@Links2004 not sure it is a bug in the library or it is intended to work like this.

Links2004 commented 3 years ago

yes if this happens its a bug, but can you check if this code here is in you version of the lib? https://github.com/Links2004/arduinoWebSockets/blob/c5900db6364e76442e06a46f0d721af8bb5ef8b3/src/WebSocketsClient.cpp#L646-L649 my expectation is that the code here prevents this problem but may there is something wrong.

cgisca commented 3 years ago

I confirm that this code is present in the WebSocketsClient.cpp . I checked arduino libraries folder (path: ./Arduino/libraries/WebSockets/src/WebSocketsClient.cpp) .

Links2004 commented 3 years ago

can you please retest with the new version 2.3.2

cgisca commented 3 years ago

Tried 2.3.2 version and works the same. The issue is not fixed. In the path: ./Arduino/libraries I removed the previous websockets library and added unzipped arduinoWebSockets-2.3.2. The result is the same as for version 2.3.1

Links2004 commented 3 years ago

can you please change 

 // add extra headers; by default this includes "Origin: file://" 
 if(client->extraHeaders.length() > 0) { 
     handshake += client->extraHeaders + NEW_LINE; 
 }

to

DEBUG_WEBSOCKETS("[WS-Client][extraHeaders] length: %d", client->extraHeaders.length());
DEBUG_WEBSOCKETS("[WS-Client][extraHeaders] c_str: '%s'", (uint8_t *)client->extraHeaders.c_str());

 // add extra headers; by default this includes "Origin: file://" 
 if(client->extraHeaders.length() > 0) { 
     handshake += client->extraHeaders + NEW_LINE; 
 }

looks like to Arduino Stings class doing something strange in your case. the debug code will help to get more details.

javeke commented 2 years ago

Has a fix for this been implemented? I am currently having the same issue.

javeke commented 2 years ago

Disregard my comment. Turns out my issue was something else. Resolved and everything working now.