[ESP8266] Websocket Client STOMP over SockJS and Spring Boot - Compatibility #577
Description
General Information
I am following the Spring Boot guide on setting up a STOMP over SockJS websocket server here. The example works as expected connecting from a JavaScript client.
I copied the current example of the ESP8266 client STOMP over SockJS, and filled out the WiFi settings, along with the IP address port of the machine running the Spring Boot server.
Expected Behavior
My expectation is that the client should connect to the server, send a message, and receive a reply without issue.
Current Behavior
I am actually seeing a repeated series of connects and disconnects on the client with nonstop failure messages of:
1002: The client frame set the reserved bits to [5] for a message with opCode [5] which was not supported by this endpoint
on the Spring boot server. After a bit of digging in the ESP client library, I was able to print more messages for debugging, attached below.
Failure Information
I believe this to be either a bug in the client as the JS client works fine, or outdated example code meaning I'm missing a simple config option that will remedy the issue. Any help in rectifying this would be very appreciated.
Context
- Java version: 1.8
- Spring Boot Version: 2.3.5.RELEASE
- Apache Tomcat Version: 9.0.39
- Arduino platform: HUZZAH ESP8266
- Arduino library version: Latest as .ZIP directory from master branch
Failure Logs
NOTE: These sets of logs are not from the exact same execution, but the jist of the logs is the same
ESP8266 Client Verbose Logs:
15:17:16.012 -> Logging into WLAN: --REDACTED-- ...scandone
15:17:16.627 -> .....scandone
15:17:19.937 -> state: 0 -> 2 (b0)
15:17:19.937 -> .state: 2 -> 3 (0)
15:17:19.970 -> state: 3 -> 5 (10)
15:17:19.970 -> add 0
15:17:19.970 -> aid 1
15:17:19.970 -> cnt
15:17:20.004 ->
15:17:20.004 -> connected with --REDACTED--, channel 1
15:17:20.004 -> dhcp client start...
15:17:20.407 -> ....ip:192.168.86.113,mask:255.255.255.0,gw:192.168.86.1
15:17:22.412 -> . success.
15:17:22.412 -> IP: 192.168.86.113
15:17:22.412 -> [WS-Client] connect ws...
15:17:22.479 -> [WS-Client] connected to 192.168.86.62:8080.
15:17:22.479 -> [WS-Client][sendHeader] sending header...
15:17:22.479 -> [WS-Client][sendHeader] handshake GET /socketentry/968/462116/websocket HTTP/1.1
15:17:22.479 -> Host: 192.168.86.62:8080
15:17:22.479 -> Connection: Upgrade
15:17:22.479 -> Upgrade: websocket
15:17:22.479 -> Sec-WebSocket-Version: 13
15:17:22.479 -> Sec-WebSocket-Key: HtWI88odoYCofeBiOWNHWw==
15:17:22.479 -> Sec-WebSocket-Protocol: arduino
15:17:22.479 ->
15:17:22.479 -> User-Agent: arduino-WebSocket-Client
15:17:22.479 ->
15:17:22.479 -> [write] n: %zu t: 262
15:17:22.479 -> [WS-Client][sendHeader] sending header... Done (24124us).
15:17:22.747 -> [WS-Client][handleHeader] RX: HTTP/1.1 101
15:17:22.747 -> [WS-Client][handleHeader] RX: Vary: Origin
15:17:22.747 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Method
15:17:22.747 -> [WS-Client][handleHeader] RX: Vary: Access-Control-Request-Headers
15:17:22.747 -> [WS-Client][handleHeader] RX: Upgrade: websocket
15:17:22.747 -> [WS-Client][handleHeader] RX: Connection: upgrade
15:17:22.747 -> [WS-Client][handleHeader] RX: Sec-WebSocket-Accept: V62aL74jkKQqwglWiiISE3W6KRs=
15:17:22.747 -> [WS-Client][handleHeader] RX: Date: Tue, 10 Nov 2020 21:17:22 GMT
15:17:22.747 -> [WS-Client][handleHeader] Header read fin.
15:17:22.747 -> [WS-Client][handleHeader] Client settings:
15:17:22.747 -> [WS-Client][handleHeader] - cURL: /socketentry/968/462116/websocket
15:17:22.747 -> [WS-Client][handleHeader] - cKey: HtWI88odoYCofeBiOWNHWw==
15:17:22.747 -> [WS-Client][handleHeader] Server header:
15:17:22.747 -> [WS-Client][handleHeader] - cCode: 101
15:17:22.747 -> [WS-Client][handleHeader] - cIsUpgrade: 1
15:17:22.747 -> [WS-Client][handleHeader] - cIsWebsocket: 1
15:17:22.747 -> [WS-Client][handleHeader] - cAccept: V62aL74jkKQqwglWiiISE3W6KRs=
15:17:22.747 -> [WS-Client][handleHeader] - cProtocol: arduino
15:17:22.747 -> [WS-Client][handleHeader] - cExtensions:
15:17:22.747 -> [WS-Client][handleHeader] - cVersion: 0
15:17:22.747 -> [WS-Client][handleHeader] - cSessionId:
15:17:22.747 -> [WS-Client][handleHeader] Websocket connection init done.
15:17:22.747 -> [WS][0][headerDone] Header Handling Done.
15:17:22.747 -> [WSc] Connected to url: /socketentry/968/462116/websocket
15:17:22.747 -> [WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
15:17:22.747 -> [readCb] n: %zu t: 2
15:17:22.747 -> [WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
15:17:22.747 -> [WS][0][handleWebsocket] ------- read massage frame -------
15:17:22.747 -> [WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0 opCode: 1
15:17:22.747 -> [WS][0][handleWebsocket] mask: 0 payloadLen: 1
15:17:22.747 -> [readCb] n: %zu t: 1
15:17:22.747 -> [WS][0][handleWebsocket] text: o
15:17:22.747 -> [WSc] get text: o
15:17:22.747 -> [WS][0][sendFrame] ------- send message frame -------
15:17:22.747 -> [WS][0][sendFrame] fin: 1 opCode: 1 mask: 1 length: 69 headerToPayload: 0
15:17:22.747 -> [WS][0][sendFrame] text: ["CONNECT\naccept-version:1.1,1.0\nheart-beat:10000,10000\n\n\u0000"]
15:17:22.747 -> [WS][0][sendFrame] pack to one TCP package...
15:17:22.747 -> [write] n: %zu t: 75
15:17:22.747 -> [WS][0][sendFrame] sending Frame Done (2296us).
15:17:22.747 -> [WS][0][handleWebsocketWaitFor] size: 2 cWsRXsize: 0
15:17:22.849 -> [readCb] n: %zu t: 2
15:17:22.849 -> [WS][0][handleWebsocketWaitFor][readCb] size: 2 ok: 1
15:17:22.849 -> [WS][0][handleWebsocket] ------- read massage frame -------
15:17:22.849 -> [WS][0][handleWebsocket] fin: 1 rsv1: 0 rsv2: 0 rsv3 0 opCode: 8
15:17:22.849 -> [WS][0][handleWebsocket] mask: 0 payloadLen: 118
15:17:22.849 -> [readCb] n: %zu t: 118
15:17:22.849 -> [WS][0][handleWebsocket] get ask for close. Code: 1002 (The client frame set the reserved bits to [5] for a message with opCode [5] which was not supported by this endpoint)
15:17:22.849 -> [WS][0][handleWebsocket] clientDisconnect code: 1000
15:17:22.849 -> [WS][0][sendFrame] ------- send message frame -------
15:17:22.849 -> [WS][0][sendFrame] fin: 1 opCode: 8 mask: 1 length: 2 headerToPayload: 0
15:17:22.849 -> [WS][0][sendFrame] pack to one TCP package...
15:17:22.849 -> [write] n: %zu t: 8
15:17:22.849 -> [WS][0][sendFrame] sending Frame Done (2169us).
15:17:22.849 -> [WS-Client] client disconnected.
15:17:22.849 -> [WSc] Disconnected!
Spring Boot Server Logs
:: Spring Boot :: (v2.3.5.RELEASE)
[ main] com.t.Application : Starting Application on Legion with PID 16220
[ main] com.t.Application : No active profile set, falling back to default profiles: default
[ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
[ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
[ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.39]
[ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
[ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1088 ms
[ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'clientInboundChannelExecutor'
[ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'clientOutboundChannelExecutor'
[ main] o.s.s.c.ThreadPoolTaskScheduler : Initializing ExecutorService 'messageBrokerTaskScheduler'
[ main] o.s.s.concurrent.ThreadPoolTaskExecutor : Initializing ExecutorService 'brokerChannelExecutor'
[ main] o.s.b.a.w.s.WelcomePageHandlerMapping : Adding welcome page: class path resource [static/index.html]
[ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
[ main] o.s.m.s.b.SimpleBrokerMessageHandler : Starting...
[ main] o.s.m.s.b.SimpleBrokerMessageHandler : BrokerAvailabilityEvent[available=true, SimpleBrokerMessageHandler [DefaultSubscriptionRegistry[cache[0 destination(s)], registry[0 sessions]]]]
[ main] o.s.m.s.b.SimpleBrokerMessageHandler : Started.
[ main] com.t.Application : Started Application in 2.419 seconds (JVM running for 2.914)
[nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 3 ms
[nio-82020-11-13 20:20:26.762 DEBUG 9416 --- [o-8080-Acceptor] o.apache.tomcat.util.threads.LimitLatch : Counting up[http-nio-8080-Acceptor] latch=1
[nio-8080-exec-1] o.a.coyote.http11.Http11InputBuffer : Before fill(): [true], parsingRequestLine: [true], parsingRequestLinePhase: [0], parsingRequestLineStart: [0], byteBuffer.position() [0]
[nio-8080-exec-1] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:org.apache.tomcat.util.net.NioChannel@19336d9c:java.nio.channels.SocketChannel[connected local=/192.168.86.62:8080 remote=/192.168.86.112:54179]], Read from buffer: [0]
[nio-8080-exec-1] org.apache.tomcat.util.net.NioEndpoint : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:org.apache.tomcat.util.net.NioChannel@19336d9c:java.nio.channels.SocketChannel[connected local=/192.168.86.62:8080 remote=/192.168.86.112:54179]], Read direct from socket: [261]
[nio-8080-exec-1] o.a.coyote.http11.Http11InputBuffer : Received [GET /socketentry/190/63945/websocket HTTP/1.1
Host: 192.168.86.62:8080
Connection: Upgrade
Upgrade: websocket
Sec-WebSocket-Version: 13
Sec-WebSocket-Key: dlO4hmWvSDaBQ9JgOGMMKA==
Sec-WebSocket-Protocol: arduino
User-Agent: arduino-WebSocket-Client
]
[nio-8080-exec-1] org.apache.tomcat.util.http.Parameters : Set query string encoding to UTF-8
[nio-8080-exec-1] o.a.c.authenticator.AuthenticatorBase : Security checking request GET /socketentry/190/63945/websocket
[nio-8080-exec-1] org.apache.catalina.realm.RealmBase : No applicable constraints defined
[nio-8080-exec-1] o.a.c.a.jaspic.AuthConfigFactoryImpl : Loading persistent provider registrations from [C:\Users\James\AppData\Local\Temp\tomcat.8080.7515769303263122045\conf\jaspic-providers.xml]
[nio-8080-exec-1] o.a.c.authenticator.AuthenticatorBase : Not subject to any constraint
[nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Detected StandardServletMultipartResolver
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : enableLoggingRequestDetails='false': request parameters and headers will be masked to prevent unsafe logging of potentially sensitive data
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 4 ms
[nio-8080-exec-1] org.apache.tomcat.util.http.Parameters : Set encoding to UTF-8
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : GET "/socketentry/190/63945/websocket", parameters={}
[nio-8080-exec-1] o.s.w.s.s.s.WebSocketHandlerMapping : Mapped to org.springframework.web.socket.sockjs.support.SockJsHttpRequestHandler@127d7908
[nio-8080-exec-1] o.s.w.s.s.t.h.DefaultSockJsService : Processing transport request: GET http://192.168.86.62:8080/socketentry/190/63945/websocket
[nio-8080-exec-1] c.t.HttpSessionIdHandshakeInterceptor : BEFORE: [host:"192.168.86.62:8080", connection:"Upgrade", upgrade:"websocket", sec-websocket-version:"13", sec-websocket-key:"dlO4hmWvSDaBQ9JgOGMMKA==", sec-websocket-protocol:"arduino"]
[nio-8080-exec-1] c.t.HttpSessionIdHandshakeInterceptor : SOMETHING: GET
[nio-8080-exec-1] c.t.HttpSessionIdHandshakeInterceptor : REQUEST: [host:"192.168.86.62:8080", connection:"Upgrade", upgrade:"websocket", sec-websocket-version:"13", sec-websocket-key:"dlO4hmWvSDaBQ9JgOGMMKA==", sec-websocket-protocol:"arduino"]
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : getResourceAsStream(org/apache/tomcat/util/collections/LocalStrings.properties)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader sun.misc.Launcher$AppClassLoader@14dad5dc
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Searching local repositories
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings_en)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : getResourceAsStream(org/apache/tomcat/util/collections/LocalStrings_en.properties)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader sun.misc.Launcher$AppClassLoader@14dad5dc
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Searching local repositories
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : findClass(org.apache.tomcat.util.collections.LocalStrings_en_US)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Returning ClassNotFoundException
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : getResourceAsStream(org/apache/tomcat/util/collections/LocalStrings_en_US.properties)
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Delegating to parent classloader sun.misc.Launcher$AppClassLoader@14dad5dc
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : Searching local repositories
[nio-8080-exec-1] o.a.c.loader.WebappClassLoaderBase : --> Resource not found, returning null
[nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed 101 SWITCHING_PROTOCOLS
[nio-8080-exec-1] o.apache.coyote.http11.Http11Processor : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:org.apache.tomcat.util.net.NioChannel@19336d9c:java.nio.channels.SocketChannel[connected local=192.168.86.62/192.168.86.62:8080 remote=/192.168.86.112:54179]], Status in: [OPEN_READ], State out: [UPGRADING]
[nio-8080-exec-1] org.apache.tomcat.websocket.WsSession : Created WebSocket session [0]
[nio-8080-exec-1] s.w.s.h.LoggingWebSocketHandlerDecorator : New WebSocketServerSockJsSession[id=63945]
[nio-8080-exec-1] o.a.t.websocket.server.WsFrameServer : wsFrameServer.onDataAvailable
[nio-8080-exec-1] o.a.tomcat.util.net.SocketWrapperBase : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:org.apache.tomcat.util.net.NioChannel@19336d9c:java.nio.channels.SocketChannel[connected local=192.168.86.62/192.168.86.62:8080 remote=/192.168.86.112:54179]], Read from buffer: [40]
[nio-8080-exec-1] o.a.t.websocket.server.WsFrameServer : Read [40] bytes into input buffer ready for processing
[nio-8080-exec-1] s.w.s.h.LoggingWebSocketHandlerDecorator : WebSocketServerSockJsSession[id=63945] closed with CloseStatus[code=1002, reason=The client frame set the reserved bits to [5] for a message with opCode [5] which was not supported by this endpoint]
[nio-8080-exec-1] o.s.w.s.m.SubProtocolWebSocketHandler : Clearing session 63945
[nio-8080-exec-1] c.t.controller.WebSocketController : DISCONNECTED: SessionDisconnectEvent[sessionId=63945, CloseStatus[code=1002, reason=The client frame set the reserved bits to [5] for a message with opCode [5] which was not supported by this endpoint]]
[nboundChannel-2] o.s.m.s.b.SimpleBrokerMessageHandler : Processing DISCONNECT session=63945
[nio-8080-exec-1] o.apache.tomcat.util.threads.LimitLatch : Counting down[http-nio-8080-exec-1] latch=1
[nio-8080-exec-1] org.apache.tomcat.util.net.NioEndpoint : Calling [org.apache.tomcat.util.net.NioEndpoint@5d6d2b20].closeSocket([org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:org.apache.tomcat.util.net.NioChannel@19336d9c:java.nio.channels.SocketChannel[connected local=192.168.86.62/192.168.86.62:8080 remote=/192.168.86.112:54179]])
[nio-8080-exec-1] o.a.c.h.u.UpgradeProcessorInternal : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@5ee386a9:Closed NioChannel], Status in: [OPEN_READ], State out: [CLOSED]
[tboundChannel-1] o.s.w.s.m.SubProtocolWebSocketHandler : No session for GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT_ACK, simpDisconnectMessage=GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={org.springframework.messaging.simp.SimpAttributes.COMPLETED=true}, simpSessionId=63945}], simpSessionId=63945}]