SubProtocolWebSocketHandler does not update lastSessionCheckTime [SPR-13745]

[spring-projects-issues]

Kevin McLaughlin opened SPR-13745 and commented

We're getting a lot of the exceptions below in our logs. I believe they are caused by our selenium tests not properly establishing the full connection. That said, there looks to be an issue w/ spring security integration when trying to close the "half-open" connections so the exceptions keep repeating.

Couple other things I noticed in SubProtocolWebSocketHandler.java that look questionable to me:

• lastSessionCheckTime does not seem to be updated. So, every handleMessage incurs the overhead of checkSessions(). That does not seem to be the intent of that code.
• There is some ~90 minute timer which I haven't figured out. The same session (I think) is trying to be closed every ~90 minutes.

2015-11-30 14:27:21.425 ERROR 4500 --- [http-nio-4441-exec-14] o.s.w.s.m.SubProtocolWebSocketHandler    : No messages received after 60440 ms. Closing EventSourceStreamingSockJsSession[id=yvhws030].
2015-11-30 15:57:55.443 ERROR 4500 --- [http-nio-4441-exec-2] o.s.w.s.m.SubProtocolWebSocketHandler    : No messages received after 60769 ms. Closing EventSourceStreamingSockJsSession[id=yvhws030].
2015-11-30 17:27:27.201 ERROR 4500 --- [http-nio-4441-exec-14] o.s.w.s.m.SubProtocolWebSocketHandler    : No messages received after 60008 ms. Closing EventSourceStreamingSockJsSession[id=yvhws030].

Here is the full exception:

2015-11-30 17:49:42.421 ERROR 4500 --- [http-nio-4441-exec-5] o.s.w.s.m.SubProtocolWebSocketHandler    : No messages received after 60722 ms. Closing EventSourceStreamingSockJsSession[id=3pps00e1].
2015-11-30 17:49:42.421 ERROR 4500 --- [http-nio-4441-exec-5] w.s.h.ExceptionWebSocketHandlerDecorator : Unhandled error for ExceptionWebSocketHandlerDecorator [delegate=LoggingWebSocketHandlerDecorator [delegate=SessionWebSocketHandler [delegate=SubProtocolWebSocketHandler[StompSubProtocolHandler[v10.stomp, v11.stomp, v12.stomp]]]]]

org.springframework.messaging.MessageDeliveryException: Failed to send message to ExecutorSubscribableChannel[clientInboundChannel]; nested exception is org.springframework.security.access.AccessDeniedException: Access is denied
	at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:127) ~[spring-messaging-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:104) ~[spring-messaging-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.messaging.StompSubProtocolHandler.afterSessionEnded(StompSubProtocolHandler.java:595) ~[spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.clearSession(SubProtocolWebSocketHandler.java:442) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.afterConnectionClosed(SubProtocolWebSocketHandler.java:432) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.afterConnectionClosed(WebSocketHandlerDecorator.java:85) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.afterConnectionClosed(WebSocketHandlerDecorator.java:85) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.afterConnectionClosed(LoggingWebSocketHandlerDecorator.java:72) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.afterConnectionClosed(ExceptionWebSocketHandlerDecorator.java:92) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.close(AbstractSockJsSession.java:215) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.WebSocketSessionDecorator.close(WebSocketSessionDecorator.java:158) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.ConcurrentWebSocketSessionDecorator.close(ConcurrentWebSocketSessionDecorator.java:167) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.checkSessions(SubProtocolWebSocketHandler.java:412) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.messaging.SubProtocolWebSocketHandler.handleMessage(SubProtocolWebSocketHandler.java:321) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.WebSocketHandlerDecorator.handleMessage(WebSocketHandlerDecorator.java:75) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.LoggingWebSocketHandlerDecorator.handleMessage(LoggingWebSocketHandlerDecorator.java:56) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.ExceptionWebSocketHandlerDecorator.handleMessage(ExceptionWebSocketHandlerDecorator.java:72) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.AbstractSockJsSession.delegateMessages(AbstractSockJsSession.java:385) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.sockjs.transport.session.WebSocketServerSockJsSession.handleMessage(WebSocketServerSockJsSession.java:194) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.sockjs.transport.handler.SockJsWebSocketHandler.handleTextMessage(SockJsWebSocketHandler.java:92) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.handler.AbstractWebSocketHandler.handleMessage(AbstractWebSocketHandler.java:43) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.handleTextMessage(StandardWebSocketHandlerAdapter.java:112) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter.access$000(StandardWebSocketHandlerAdapter.java:42) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:82) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.web.socket.adapter.standard.StandardWebSocketHandlerAdapter$3.onMessage(StandardWebSocketHandlerAdapter.java:79) [spring-websocket-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.apache.tomcat.websocket.WsFrameBase.sendMessageText(WsFrameBase.java:393) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.websocket.WsFrameBase.processDataText(WsFrameBase.java:494) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.websocket.WsFrameBase.processData(WsFrameBase.java:289) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.websocket.WsFrameBase.processInputBuffer(WsFrameBase.java:130) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.websocket.server.WsFrameServer.onDataAvailable(WsFrameServer.java:60) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.websocket.server.WsHttpUpgradeHandler$WsReadListener.onDataAvailable(WsHttpUpgradeHandler.java:203) [tomcat-embed-websocket-8.0.28.jar!/:8.0.28]
	at org.apache.coyote.http11.upgrade.AbstractServletInputStream.onDataAvailable(AbstractServletInputStream.java:198) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at org.apache.coyote.http11.upgrade.AbstractProcessor.upgradeDispatch(AbstractProcessor.java:96) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at org.apache.coyote.AbstractProtocol$AbstractConnectionHandler.process(AbstractProtocol.java:668) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1500) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.run(NioEndpoint.java:1456) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) [na:1.8.0_65]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) [na:1.8.0_65]
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61) [tomcat-embed-core-8.0.28.jar!/:8.0.28]
	at java.lang.Thread.run(Thread.java:745) [na:1.8.0_65]
Caused by: org.springframework.security.access.AccessDeniedException: Access is denied
	at org.springframework.security.access.vote.AffirmativeBased.decide(AffirmativeBased.java:83) ~[spring-security-core-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
	at org.springframework.security.access.intercept.AbstractSecurityInterceptor.beforeInvocation(AbstractSecurityInterceptor.java:232) ~[spring-security-core-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
	at org.springframework.security.messaging.access.intercept.ChannelSecurityInterceptor.preSend(ChannelSecurityInterceptor.java:69) ~[spring-security-messaging-4.0.3.RELEASE.jar!/:4.0.3.RELEASE]
	at org.springframework.messaging.support.AbstractMessageChannel$ChannelInterceptorChain.applyPreSend(AbstractMessageChannel.java:158) ~[spring-messaging-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	at org.springframework.messaging.support.AbstractMessageChannel.send(AbstractMessageChannel.java:113) ~[spring-messaging-4.2.3.RELEASE.jar!/:4.2.3.RELEASE]
	... 40 common frames omitted

2015-11-30 17:49:52.810  INFO 4500 --- [MessageBroker-14] o.s.w.s.c.WebSocketMessageBrokerStats    : WebSocketSession[51 current WS(45)-HttpStream(6)-HttpPoll(0), 5482 total, 3521 closed abnormally (3521 connect failure, 0 send limit, 1 transport error)], stompSubProtocol[processed CONNECT(215)-CONNECTED(147)-DISCONNECT(0)], stompBrokerRelay[16 sessions, localhost:61613 (available), processed CONNECT(148)-CONNECTED(148)-DISCONNECT(117)], inboundChannel[pool size = 32, active threads = 0, queued tasks = 0, completed tasks = 135534], outboundChannelpool size = 32, active threads = 0, queued tasks = 0, completed tasks = 40559], sockJsScheduler[pool size = 16, active threads = 1, queued tasks = 38, completed tasks = 44458]

---

Affects: 4.1.8, 4.2.3

Referenced from: commits ff8bbc9, f5e681e

Backported to: 4.1.9

[spring-projects-issues]

Kevin McLaughlin commented

One other note, though it doesn't show up in this stack trace, we are also using spring-session backed by redis.

[spring-projects-issues]

Rossen Stoyanchev commented

The "No messages received after 60722 ms" message indicates that a WebSocket connection was established but no further WebSocket messages were received, or at least not one with a STOMP CONNECT frame. The WebSocket connection is proactively closed after 60 seconds by the SubProtocolWebSocketHandler to avoid a memory leak. That also causes a DISCONNECT frame to be sent upstream to the broker to remove state for the connection and it looks like the DISCONNECT is not allowed, not sure why. Could you share the WebSocket-related parts of your Spring Security configuration? It's true that in this particular case the broker shouldn't have any state (since a CONNECT frame was received) so technically there is no need to send a DISCONNECT at all. That said it shouldn't have any side effects.

You're right about the lastSessionCheckTime flag, will fix that.

There is a scheduled task in TransportHandlingSockJsService that cleans up closed sessions every 5 seconds. There is a scheduled task for WebSocketMessageBrokerStats every 15 min by default. I can't think of what the 90 min timer would be. A session shouldn't be closed more than once.

[spring-projects-issues]

Kevin McLaughlin commented

Been trying to get a small test case/project to reproduce this, but, not easy. Will turn up debug logs in an environment where this is happening tomorrow and see if that sheds any light. I had thought that maybe the current security context was not being properly applied since it is closing sessions in response to a message from a different session. That still feels like what it is doing, but, when I step through it I can see SecurityContextChannelInterceptor setting the correct user.

[spring-projects-issues]

Rossen Stoyanchev commented

I'm curious to see though if you're applying any authorization in your security config.

[spring-projects-issues]

Kevin McLaughlin commented

Basically this:

@Configuration
public class WebSocketSecurityConfig extends AbstractSecurityWebSocketMessageBrokerConfigurer {

    protected void configureInbound(MessageSecurityMetadataSourceRegistry messages) {
        messages.simpTypeMatchers(SimpMessageType.values()).hasRole(WebsocketExceptionApplication.ROLE_USER)
                .anyMessage().denyAll();
    }

}

At debug level:

2015-12-01 17:51:16.751 ERROR 17219 --- [http-nio-4441-exec-8] o.s.w.s.m.SubProtocolWebSocketHandler    : No messages received after 60477 ms. Closing XhrStreamingSockJsSession[id=h3ikjjsc].
2015-12-01 17:51:16.751 DEBUG 17219 --- [http-nio-4441-exec-8] o.s.s.m.a.i.ChannelSecurityInterceptor   : Secure object: GenericMessage [payload=byte[0], headers={simpMessageType=DISCONNECT, stompCommand=DISCONNECT, simpSessionAttributes={SPRING.SESSION.ID=f7a46b78-0542-4d16-ba44-5bb45548ff57, org.springframework.security.web.csrf.CsrfToken=org.springframework.security.web.csrf.DefaultCsrfToken@7a9e975d}, simpSessionId=h3ikjjsc}]; Attributes: [hasRole('ROLE_USER')]
2015-12-01 17:51:16.751 DEBUG 17219 --- [http-nio-4441-exec-8] o.s.s.m.a.i.ChannelSecurityInterceptor   : Previously Authenticated: org.springframework.security.authentication.AnonymousAuthenticationToken@52a3d06d: Principal: anonymous; Credentials: [PROTECTED]; Authenticated: true; Details: null; Granted Authorities: ROLE_ANONYMOUS
2015-12-01 17:51:16.751 DEBUG 17219 --- [http-nio-4441-exec-8] o.s.s.access.vote.AffirmativeBased       : Voter: org.springframework.security.messaging.access.expression.MessageExpressionVoter@6e145e51, returned: -1
2015-12-01 17:51:16.751 DEBUG 17219 --- [http-nio-4441-exec-8] o.s.m.s.s.StompBrokerRelayMessageHandler : Detected unsent DISCONNECT message. Processing anyway.
2015-12-01 17:51:16.751 DEBUG 17219 --- [http-nio-4441-exec-8] o.s.m.s.s.StompBrokerRelayMessageHandler : Ignoring DISCONNECT in session h3ikjjsc. Connection already cleaned up.
2015-12-01 17:51:16.752 ERROR 17219 --- [http-nio-4441-exec-8] w.s.h.ExceptionWebSocketHandlerDecorator : Unhandled error for ExceptionWebSocketHandlerDecorator [delegate=LoggingWebSocketHandlerDecorator [delegate=SessionWebSocketHandler [delegate=SubProtocolWebSocketHandler[StompSubProtocolHandler[v10.stomp, v11.stomp, v12.stomp]]]]]

org.springframework.messaging.MessageDeliveryException: Failed to send message to ExecutorSubscribableChannel[clientInboundChannel]; nested exception is org.springframework.security.access.AccessDeniedException: Access is denied

[spring-projects-issues]

Rossen Stoyanchev commented

So ROLE_USER is required but Principal: anonymous with Granted Authorities: ROLE_ANONYMOUS so it's not the correct user.

[spring-projects-issues]

Kevin McLaughlin commented

I've gotten a bit further.

What I think is happening is we have the web socket URL open in spring (http) security. For example: /hello/178/1ya215g4/eventsource.

Something (probably our web-tests) is requesting this URL in an unauthenticated state and then sending nothing else (or possibly being denied on sending a message). Then checkSessions comes along and tries to close it and hits the auth check.

[spring-projects-issues]

Rossen Stoyanchev commented

That sounds pretty plausible. The only thing I see that needs fixing from our side is making sure lastSessionCheckTime is updated. If so I will update the title accordingly.

[spring-projects-issues]

Kevin McLaughlin commented

I fixed up our http web security config (protect "/hello") and the logs have been clean for awhile. Will check again in the morning, but, so far so good. I also turned on the the boot/tomcat access logs and I can see all the 'bad' web socket initiation requests being redirected to our login page.

Thanks for bearing with me.

[spring-projects-issues]

Juergen Hoeller commented

Kevin McLaughlin, have you had a chance to try a recent 4.2.4.BUILD-SNAPSHOT for the lastSessionCheckTime update fix? It'd be great if you could give it a quick try at least, making sure that it works for you...

Juergen

[spring-projects-issues]

Kevin McLaughlin commented

After I fixed the security config, haven't had any problems. I also switched our app over to boot 1.3.1.BUILD-SNAPSHOT (which pulls 4.2.4.BUILD-SNAPSHOT) and everything seems fine so far.