I am trying to use Spring Websocket with Sockjs and STOMPjs. As mentioned Spring Websocket Documentation, after the /info request, client send protocol upgrade request to /websocket. HTTP Status 101 expected from client.
In my application, Spring Websocket returns Http 101 as expected, however within 10 second.
Spring Websocket logs;
2018-04-12 14:27:50.219 DEBUG 24509 --- [nio-8080-exec-6] s.w.s.h.LoggingWebSocketHandlerDecorator : WebSocketServerSockJsSession[id=z52e0a20] closed with CloseStatus[code=1001, reason=null]
2018-04-12 14:27:50.219 DEBUG 24509 --- [nio-8080-exec-6] o.s.w.s.m.SubProtocolWebSocketHandler : Clearing session z52e0a20
2018-04-12 14:27:50.220 DEBUG 24509 --- [boundChannel-14] 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}, simpUser=com.gohm.server.entity.auth.UserAuthentication@4794d8fc, simpSessionId=z52e0a20}], simpUser=com.gohm.server.entity.auth.UserAuthentication@4794d8fc, simpSessionId=z52e0a20}]
2018-04-12 14:27:52.651 DEBUG 24509 --- [nio-8080-exec-5] o.s.w.s.s.s.WebSocketHandlerMapping : Matching patterns for request [/api/v3/websocket/info] are [/api/v3/websocket/**]
2018-04-12 14:27:52.652 DEBUG 24509 --- [nio-8080-exec-5] o.s.w.s.s.s.WebSocketHandlerMapping : URI Template variables for request [/api/v3/websocket/info] are {}
2018-04-12 14:27:52.652 DEBUG 24509 --- [nio-8080-exec-5] o.s.w.s.s.s.WebSocketHandlerMapping : Mapping [/api/v3/websocket/info] to HandlerExecutionChain with handler [org.springframework.web.socket.sockjs.support.SockJsHttpRequestHandler@73a845cb] and 1 interceptor
2018-04-12 14:27:52.652 DEBUG 24509 --- [nio-8080-exec-5] o.s.w.s.s.t.h.DefaultSockJsService : Processing transport request: GET http://192.168.0.58:8080/api/v3/websocket/info?t=1523532470618
2018-04-12 14:27:52.668 DEBUG 24509 --- [io-8080-exec-10] o.s.w.s.s.s.WebSocketHandlerMapping : Matching patterns for request [/api/v3/websocket/645/l5ayzctd/websocket] are [/api/v3/websocket/**]
2018-04-12 14:27:52.668 DEBUG 24509 --- [io-8080-exec-10] o.s.w.s.s.s.WebSocketHandlerMapping : URI Template variables for request [/api/v3/websocket/645/l5ayzctd/websocket] are {}
2018-04-12 14:27:52.668 DEBUG 24509 --- [io-8080-exec-10] o.s.w.s.s.s.WebSocketHandlerMapping : Mapping [/api/v3/websocket/645/l5ayzctd/websocket] to HandlerExecutionChain with handler [org.springframework.web.socket.sockjs.support.SockJsHttpRequestHandler@73a845cb] and 1 interceptor
2018-04-12 14:27:52.669 DEBUG 24509 --- [io-8080-exec-10] o.s.w.s.s.t.h.DefaultSockJsService : Processing transport request: GET http://192.168.0.58:8080/api/v3/websocket/645/l5ayzctd/websocket
2018-04-12 14:27:52.669 TRACE 24509 --- [io-8080-exec-10] o.s.w.s.s.s.DefaultHandshakeHandler : Processing request http://192.168.0.58:8080/api/v3/websocket/645/l5ayzctd/websocket with headers={host=[192.168.0.58:8080], user-agent=[Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:60.0) Gecko/20100101 Firefox/60.0], accept=[text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8], accept-language=[en-GB,en;q=0.5], accept-encoding=[gzip, deflate], sec-websocket-version=[13], origin=[null], sec-websocket-extensions=[permessage-deflate], sec-websocket-key=[nf8F1qYfIjSrgm9AqhE3CA==], cookie=[JSESSIONID=2CBA278B1D63F0D3E8E5BBDD324792CC], connection=[keep-alive, Upgrade], pragma=[no-cache], cache-control=[no-cache], upgrade=[websocket]}
2018-04-12 14:27:52.669 TRACE 24509 --- [io-8080-exec-10] o.s.w.s.s.s.DefaultHandshakeHandler : Upgrading to WebSocket, subProtocol=null, extensions=[]
2018-04-12 14:28:02.678 DEBUG 24509 --- [io-8080-exec-10] s.w.s.h.LoggingWebSocketHandlerDecorator : New WebSocketServerSockJsSession[id=l5ayzctd]
2018-04-12 14:28:02.678 TRACE 24509 --- [io-8080-exec-10] o.s.w.s.adapter.NativeWebSocketSession : Sending TextMessage payload=[o], byteCount=1, last=true], StandardWebSocketSession[id=7, uri=/api/v3/websocket/645/l5ayzctd/websocket]
2018-04-12 14:28:02.678 TRACE 24509 --- [io-8080-exec-10] s.w.s.s.t.s.WebSocketServerSockJsSession : Scheduled heartbeat in session l5ayzctd
2018-04-12 14:28:02.694 TRACE 24509 --- [nio-8080-exec-9] s.w.s.h.LoggingWebSocketHandlerDecorator : Handling TextMessage payload=[CONNECT
x-..], byteCount=821, last=true] in WebSocketServerSockJsSession[id=l5ayzctd]
2018-04-12 14:28:02.694 TRACE 24509 --- [nio-8080-exec-9] o.s.w.s.m.StompSubProtocolHandler : From client: CONNECT session=l5ayzctd
2018-04-12 14:28:02.694 INFO 24509 --- [nio-8080-exec-9] c.g.s.c.AuthChannelInterceptorAdapter : Header auth token: {{my_token}}}
2018-04-12 14:28:02.698 TRACE 24509 --- [boundChannel-15] s.w.s.s.t.s.WebSocketServerSockJsSession : Cancelling heartbeat in session l5ayzctd
2018-04-12 14:28:02.698 TRACE 24509 --- [boundChannel-15] s.w.s.s.t.s.WebSocketServerSockJsSession : Preparing to write SockJsFrame content='a["CONNECTED\nversion:1.1\nheart-beat:0,0\nuser-name:admin\n\n\u0000"]'
2018-04-12 14:28:02.698 TRACE 24509 --- [boundChannel-15] s.w.s.s.t.s.WebSocketServerSockJsSession : Writing SockJsFrame content='a["CONNECTED\nversion:1.1\nheart-beat:0,0\nuser-name:admin\n\n\u0000"]'
2018-04-12 14:28:02.698 TRACE 24509 --- [boundChannel-15] o.s.w.s.adapter.NativeWebSocketSession : Sending TextMessage payload=[a["CONNECT..], byteCount=68, last=true], StandardWebSocketSession[id=7, uri=/api/v3/websocket/645/l5ayzctd/websocket]
2018-04-12 14:28:02.698 TRACE 24509 --- [boundChannel-15] s.w.s.s.t.s.WebSocketServerSockJsSession : Scheduled heartbeat in session l5ayzctd
2018-04-12 14:28:02.716 TRACE 24509 --- [nio-8080-exec-2] s.w.s.h.LoggingWebSocketHandlerDecorator : Handling TextMessage payload=[SUBSCRIBE
..], byteCount=49, last=true] in WebSocketServerSockJsSession[id=l5ayzctd]
2018-04-12 14:28:02.716 TRACE 24509 --- [nio-8080-exec-2] o.s.w.s.m.StompSubProtocolHandler : From client: SUBSCRIBE /user/queue/admin id=sub-0 session=l5ayzctd
2018-04-12 14:28:02.716 TRACE 24509 --- [nio-8080-exec-2] s.w.s.h.LoggingWebSocketHandlerDecorator : Handling TextMessage payload=[SUBSCRIBE
..], byteCount=52, last=true] in WebSocketServerSockJsSession[id=l5ayzctd]
2018-04-12 14:28:02.717 TRACE 24509 --- [nio-8080-exec-2] o.s.w.s.m.StompSubProtocolHandler : From client: SUBSCRIBE /user/queue/errors id=sub-1 session=l5ayzctd
And Browser Logs;
Opening Web Socket... stomp.min.js:8:1737
XHRGET http://192.168.0.58:8080/api/v3/websocket/info?t=1523532470618 [HTTP/1.1 200 2007ms]
GET http://192.168.0.58:8080/api/v3/websocket/645/l5ayzctd/websocket [HTTP/1.1 101 10012ms]
Web Socket Opened... stomp.min.js:8:1737
>>> CONNECT
x-auth-token:{{x_auth_token}}
accept-version:1.1,1.0
heart-beat:0,0
� stomp.min.js:8:1737
<<< CONNECTED
version:1.1
heart-beat:0,0
user-name:admin
� stomp.min.js:8:1737
connected to server undefined stomp.min.js:8:1737
>>> SUBSCRIBE
id:sub-0
destination:/user/queue/admin
� stomp.min.js:8:1737
>>> SUBSCRIBE
id:sub-1
destination:/user/queue/errors
�
As you can see clearly, there is 10 seconds of silence after
2018-04-12 14:27:52.669 TRACE 24509 --- [io-8080-exec-10] o.s.w.s.s.s.DefaultHandshakeHandler : Upgrading to WebSocket, subProtocol=null, extensions=[]
I configured my WebSocketBroker with the following;
@Override
public void registerStompEndpoints(StompEndpointRegistry registry) {
registry
.addEndpoint("/api/v3/websocket")
.setHandshakeHandler(new DefaultHandshakeHandler(new TomcatRequestUpgradeStrategy()))
.setAllowedOrigins("*")
.withSockJS()
.setClientLibraryUrl("https://cdnjs.cloudflare.com/ajax/libs/sockjs-client/1.1.4/sockjs.min.js");
}
Question: Where should I focus to solve this delay? I tried different computer, different browser etc. Always ~10seconds of delay happening.
