rstoyanchev
commented
10 years ago Strange, assuming you're using 4.0.0.BUILD-SNAPSHOT could it there be a stale snapshot? Try mvn clean and mvn -U package to update snapshot versions.
It appears the tcp client is closing the connection immediately after receiving the CONNECTED frame back from Rabbit. We had an issue in the StompEncoder/Decoder before that exhibited itself this way before and fixed it and improved logging. Hence my suggestion about updating the snapshots. Aside from that I would turn up logging to trace for org.springframework.messaging and reactor to see if anything more turns up.
jmzD
Ogniute
I am having an issue that involves sessions being timed out almost immediately. Additionally, it appears that the stomp client is not acknowledging the onconnect callback even though the CONNECTED frame is being sent to the client, eg.
[clientOutboundChannel-3] StompEncoder - Encoded STOMP command=CONNECTED headers={heart-beat=[10000,10000], session=[session-oEyaM8ybVlEm6Kuk7n1GqA], server=[RabbitMQ/3.2.1], version=[1.1]}
Logged output follows:
14:57:42 [http-bio-8080-exec-10] DispatcherServlet - DispatcherServlet with name 'dispatcher' processing GET request for [/endpoint/info] 14:57:42 [http-bio-8080-exec-10] RequestMappingHandlerMapping - Looking up handler method for path /endpoint/info 14:57:42 [http-bio-8080-exec-10] RequestMappingHandlerMapping - Did not find handler method for [/endpoint/info] 14:57:42 [http-bio-8080-exec-10] SimpleUrlHandlerMapping - Matching patterns for request [/endpoint/info] are [/endpoint/] 14:57:42 [http-bio-8080-exec-10] SimpleUrlHandlerMapping - URI Template variables for request [/endpoint/info] are {} 14:57:42 [http-bio-8080-exec-10] SimpleUrlHandlerMapping - Mapping [/endpoint/info] to HandlerExecutionChain with handler [org.springframework.web.socket.sockjs.SockJsHttpRequestHandler@30aded41] and 1 interceptor 14:57:42 [http-bio-8080-exec-10] DispatcherServlet - Last-Modified value for [/endpoint/info] is: -1 14:57:42 [http-bio-8080-exec-10] DefaultSockJsService - GET with SockJS path [/info] 14:57:42 [http-bio-8080-exec-10] DispatcherServlet - Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling 14:57:42 [http-bio-8080-exec-10] DispatcherServlet - Successfully completed request 14:57:42 [http-bio-8080-exec-6] DispatcherServlet - DispatcherServlet with name 'dispatcher' processing GET request for [/endpoint/132/vhmm9lka/websocket] 14:57:42 [http-bio-8080-exec-6] RequestMappingHandlerMapping - Looking up handler method for path /endpoint/132/vhmm9lka/websocket 14:57:42 [http-bio-8080-exec-6] RequestMappingHandlerMapping - Did not find handler method for [/endpoint/132/vhmm9lka/websocket] 14:57:42 [http-bio-8080-exec-6] SimpleUrlHandlerMapping - Matching patterns for request [/endpoint/132/vhmm9lka/websocket] are [/endpoint/] 14:57:42 [http-bio-8080-exec-6] SimpleUrlHandlerMapping - URI Template variables for request [/endpoint/132/vhmm9lka/websocket] are {} 14:57:42 [http-bio-8080-exec-6] SimpleUrlHandlerMapping - Mapping [/endpoint/132/vhmm9lka/websocket] to HandlerExecutionChain with handler [org.springframework.web.socket.sockjs.SockJsHttpRequestHandler@30aded41] and 1 interceptor 14:57:42 [http-bio-8080-exec-6] DispatcherServlet - Last-Modified value for [/endpoint/132/vhmm9lka/websocket] is: -1 14:57:42 [http-bio-8080-exec-6] DefaultSockJsService - GET with SockJS path [/132/vhmm9lka/websocket] 14:57:42 [http-bio-8080-exec-6] DefaultSockJsService - Creating new session with session id "vhmm9lka" 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Initiating handshake for http://localhost:8080/endpoint/132/vhmm9lka/websocket, headers={upgrade=[websocket], connection=[Upgrade], host=[localhost:8080], origin=[http://localhost:8080], pragma=[no-cache], cache-control=[no-cache], sec-websocket-key=[FxMOmAj5Z8dTVmicIgEC0Q==], sec-websocket-version=[13], sec-websocket-extensions=[x-webkit-deflate-frame], user-agent=[Mozilla/5.0 (Macintosh; Intel Mac OS X 10_8_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/31.0.1650.63 Safari/537.36], cookie=[JSESSIONID=CE92B9D57BC5158BF07EBDA92D7BEA6E]} 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Requested version=13, supported=[13] 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Requested sub-protocol(s): [], WebSocketHandler supported sub-protocol(s): [], configured sub-protocol(s): [] 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Selected sub-protocol: 'null' 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Requested extension(s): [x-webkit-deflate-frame], supported extension(s): [] 14:57:42 [http-bio-8080-exec-6] DefaultHandshakeHandler - Upgrading request, sub-protocol=null, extensions=[x-webkit-deflate-frame] 14:57:42 [http-bio-8080-exec-6] DispatcherServlet - Null ModelAndView returned to DispatcherServlet with name 'dispatcher': assuming HandlerAdapter completed request handling 14:57:42 [http-bio-8080-exec-6] DispatcherServlet - Successfully completed request 14:57:42 [http-bio-8080-exec-6] LoggingWebSocketHandlerDecorator - Connection established, SockJS session id=vhmm9lka, uri=/endpoint/132/vhmm9lka/websocket 14:57:42 [http-bio-8080-exec-6] StompDecoder - Decoded [Payload byte[0]][Headers={stompCommand=CONNECT, stompCredentials=[PROTECTED], nativeHeaders={heart-beat=[10000,10000], host=[/], passcode=[PROTECTED], login=[guest], accept-version=[1.1,1.0]}, simpMessageType=CONNECT, id=6c742cd7-9a59-6206-d66d-f36ea7b43390, timestamp=1386370662329}] 14:57:42 [clientInboundChannel-1] StompBrokerRelayMessageHandler - Processing CONNECT in session=vhmm9lka 14:57:42 [reactor-tcp-io-6] NettyTcpClient - CONNECT: [id: 0xa8039f1b, /127.0.0.1:61237 => /127.0.0.1:61613] 14:57:42 [reactor-tcp-io-6] StompEncoder - Encoded STOMP command=CONNECT headers={heart-beat=[10000,10000], host=[/], passcode=[guest], login=[guest], accept-version=[1.1,1.0]} 14:57:42 [reactor-tcp-io-6] StompDecoder - Decoded [Payload byte[0]][Headers={stompCommand=CONNECTED, nativeHeaders={heart-beat=[10000,10000], session=[session-oEyaM8ybVlEm6Kuk7n1GqA], server=[RabbitMQ/3.2.1], version=[1.1]}, simpMessageType=OTHER, id=66e5ff71-915d-16fb-6802-327d6a928c01, timestamp=1386370662334}] 14:57:42 [ringBuffer-ringbuffer-2] StompBrokerRelayMessageHandler - Received broker message in session=vhmm9lka 14:57:42 [clientOutboundChannel-3] StompEncoder - Encoded STOMP command=CONNECTED headers={heart-beat=[10000,10000], session=[session-oEyaM8ybVlEm6Kuk7n1GqA], server=[RabbitMQ/3.2.1], version=[1.1]} 14:58:03 [reactor-tcp-io-5] NettyTcpClient - CLOSED: [id: 0x0f58780c, /127.0.0.1:61235 :> /127.0.0.1:61613] 14:58:03 [clientOutboundChannel-4] StompEncoder - Encoded STOMP command=ERROR headers={message=[Connection to broker closed]} 14:58:03 [clientOutboundChannel-4] WebSocketServerSockJsSession - Closing SockJS session id=kfdda6dy, CloseStatus [code=1002, reason=null] 14:58:03 [clientOutboundChannel-4] StandardWebSocketSession - Closing WebSocket session id=9 14:58:03 [clientOutboundChannel-4] WebSocketServerSockJsSession - SockJS session id=kfdda6dy was closed, CloseStatus [code=1002, reason=null] 14:58:03 [clientOutboundChannel-4] LoggingWebSocketHandlerDecorator - Connection closed for SockJS session id=kfdda6dy, CloseStatus [code=1002, reason=null] 14:58:03 [clientOutboundChannel-4] LoggingWebSocketHandlerDecorator - Connection closed for SockJS session id=kfdda6dy, CloseStatus [code=1002, reason=null] 14:58:03 [clientOutboundChannel-4] ExceptionWebSocketHandlerDecorator - Unhandled error for ExceptionWebSocketHandlerDecorator [delegate=LoggingWebSocketHandlerDecorator [delegate=org.springframework.web.socket.messaging.SubProtocolWebSocketHandler@140ffc1]] java.lang.IllegalStateException: The WebSocket session has been closed and no method (apart from close()) may be called on a closed session at org.apache.tomcat.websocket.WsSession.checkState(WsSession.java:643) at org.apache.tomcat.websocket.WsSession.getNegotiatedSubprotocol(WsSession.java:298) at org.springframework.web.socket.adapter.standard.StandardWebSocketSession.getAcceptedProtocol(StandardWebSocketSession.java:113) at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.getAcceptedProtocol(WebSocketServerSockJsSession.java:91) at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.findProtocolHandler(SubProtocolWebSocketHandler.java:207) at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.afterConnectionClosed(SubProtocolWebSocketHandler.java:282) at org.springframework.web.socket.handler.WebSocketHandlerDecorator.afterConnectionClosed(WebSocketHandlerDecorator.java:69) at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.afterConnectionClosed(LoggingWebSocketHandlerDecorator.java:74) at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.afterConnectionClosed(ExceptionWebSocketHandlerDecorator.java:89) at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.close(AbstractSockJsSession.java:236) at org.springframework.web.socket.messaging.StompSubProtocolHandler.handleMessageToClient(StompSubProtocolHandler.java:189) at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:252) at org.springframework.messaging.support.ExecutorSubscribableChannel$1.run(ExecutorSubscribableChannel.java:79) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615) at java.lang.Thread.run(Thread.java:744)
Any ideas what may be causing this or is there a chance I can get a look at the documentation wip?