SubProtocolWebSocketHandler should check is session is open before adding it to its map [SPR-12812]

[spring-issuemaster]

Pierantonio Cangianiello opened SPR-12812 and commented

After dropping some websocket connections from the client (sock.js 0.3.4), the checkSessions() method complains about hanging connection, logging many times the following line:
SEVERE: No messages received after 5449478 ms. Closing XhrStreamingSockJsSession[id=pkwy0gwf].
These errors get logged continuously, for each message that the server dispatches.
Looking at the code in debug mode, the checkSessions method does not detect that the sessions it is trying to close have already been closed previously (I checked the internal PollingSockJsSession.state variables, they are CLOSED), and they should be removed from the sessions Map.

Environment: Tomcat 7.0.53 running on Oracle JVM 1.8.0_20

---

Affects: 4.1.5

Issue Links:

• #19370 SubProtocolWebSocketHandler should check session status before adding to map

Referenced from: commits 0c9cd4c

0 votes, 6 watchers

[spring-issuemaster]

Rossen Stoyanchev commented

The assumption with checkSessions and in general is that no matter how a session is closed , the afterConnectionClosed callback is invoked and that's where SubProtocolWebSocketHandler clears the session. That doesn't seem to be happening. Looking at AbstractSockJsSession, whenever the state field is set to CLOSED, it also results in a call to the WebSocketHandler's afterConnectionClosed. So I'm not quite sure what's causing this.

Is it a reproducible scenario? Or if you're able to debug it? It would be useful to break when AbstractSockJsSession.state is set to CLOSED and step from there to see it call the SubProtocolWebSocketHandler's afterConnectionClosed method, which should clear the session.

[spring-issuemaster]

Rossen Stoyanchev commented

Just a thought. Could there be a WebSocketHandlerDecorator perhaps that for some reason doesn't delegate the afterConnectionClosed callback to SubProtocolWebSocketHandler?

[spring-issuemaster]

Pierantonio Cangianiello commented

Ok, we checked that. Actually there was a swallowed exception in our security handler, but in the afterConnectionEstablished method, where the connection was closed prior to invoking the delegate handler. Probably this was causing a condition in which the session was removed from the map by the close() call, then added again by the delegate afterConnectionEstablished(), keeping it in CLOSED status.

[spring-issuemaster]

Rossen Stoyanchev commented

Okay that does sound like it explains what's happening. A couple of questions. Is there a reason to delegate afterConnectionEstablished if you've decided to close the connection? I suppose we could defensively check if the session is closed before adding it to the map. Also I didn't understand where an exception is swallowed, or if it matters?

[spring-issuemaster]

Rossen Stoyanchev commented

I'm turning this into an improvement to add a check if the session passed into afterConnectionEstablished is already closed.

[spring-issuemaster]

Pierantonio Cangianiello commented

Actually the issue was related to the execution order of the following blocks in our afterConnectionEstablished method:

1. the session was closed and the exception was swallowed
2. super.afterConnectionEstablished(...)

We solved the issue by fixing the wrong exception handling and swapping the two blocks above. In this way, the super.afterConnectionEstablished is called always; so, only after the connection is really established we check the security information we need. However, I agree with this improvement, that avoids the insertion of closed sessions, and protects the inner behaviour from unwanted side effects (like this one).

[spring-issuemaster]

Rossen Stoyanchev commented

Okay thanks for clarifying.

[spring-issuemaster]

Joe Sweden commented

I can see this fix/improvement in the 4.2.X codebase but it seems to have disappeared in 4.3.3 (Current). Is there a reason for this? We are seeing memory leaks in our system and we currently believe the source is the session handling in this class. We are using 4.1.4 where this fix is not in place, and want this fix but would prefer to go to 4.3.3 directly, but the fix seems to be missing from there.

[spring-issuemaster]

Juergen Hoeller commented

ManDudeBoy, could you create a separate ticket for this please, referring to this issue and making us revisit it in 4.3.x?

[spring-issuemaster]

Max Kuklinski commented

Same here, using Spring 4.3.4.RELEASE. We get these kind of message every few minutes:

07:08:17.646 [http-nio-20001-exec-9] ERROR [org.springframework.web.socket.messaging.SubProtocolWebSocketHandler] - No messages received after 211122 ms. Closing WebSocketServerSockJsSession[id=e5dm0y4h].

00:04:52.480 [http-nio-20001-exec-6] ERROR [org.springframework.web.socket.messaging.SubProtocolWebSocketHandler] - No messages received after 180679 ms. Closing PollingSockJsSession[id=44vohvvt].

It seem if the browser is closed without closing the SockJs connection, the error is logged. Does this have to be logged on error level, what about warn or even lower?