You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@tomcat.apache.org by bu...@apache.org on 2023/06/30 11:50:33 UTC
[Bug 66676] New: WebSocket session complains about closed state when calling close()
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
Bug ID: 66676
Summary: WebSocket session complains about closed state when
calling close()
Product: Tomcat 10
Version: 10.1.8
Hardware: All
OS: All
Status: NEW
Severity: normal
Priority: P2
Component: WebSocket
Assignee: dev@tomcat.apache.org
Reporter: magicball@gmx.de
Target Milestone: ------
Hey,
I've found a bug with the following stacktrace:
java.lang.IllegalStateException: The WebSocket session [210b] 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:974)
at
org.apache.tomcat.websocket.WsSession.getUserPrincipal(WsSession.java:862)
at
org.apache.tomcat.websocket.server.WsServerContainer.unregisterSession(WsServerContainer.java:350)
at
org.apache.tomcat.websocket.WsSession.sendCloseMessage(WsSession.java:730)
at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:597)
at org.apache.tomcat.websocket.WsSession.doClose(WsSession.java:554)
at org.apache.tomcat.websocket.WsSession.close(WsSession.java:542)
From the message of the exception it is mentioned that it is valid to call
close anytime, so I would not expect this exception.
What happens here is, that sending the close message fails, so the WebSocket
session gets closed in the "sendCloseMessage" method. Later on in the same
method the "unregisterSession" is called which is trying to get the
userPrincipal, but as the session was just closed this fails and you end up
with this exception.
I would either expect that either the "apart from close()" is removed from the
message, or the call fails with the original IOException, but not that the
"unregistering" fails and by that overruling the IOException from sending the
closure and showing a rather confusing message.
Let me know if you've any questions.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #8 from Georg F. <ma...@gmx.de> ---
I'll see what I can do.
Will get back to you, when I have some results.
Thanks again for your help.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #7 from Mark Thomas <ma...@apache.org> ---
We might need to take an iterative approach with this but as a starting point
I'd like:
- a log message logging the session ID and current stack when the session state
is set to closed (and timestamp and thread ID but I'd expect these but default
for any log message)
- the thread ID and timestamp (which should already in the log message) for the
stack trace when the error occurs
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #1 from Mark Thomas <ma...@apache.org> ---
Can you provide more details on how this was triggered. I've looked at the
10.1.8 code and I don't see a code path that could result in the described
behaviour.
The code was refactored in 10.1.9 with a regression that will be fixed in
10.1.11 so this bug report may already be moot but I'd like to understand how
the exception occurred in case the code path - or a similar one - is still
present.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #6 from Georg F. <ma...@gmx.de> ---
I see - well from what I can tell is that it was happening for me 99 times in
the last 30 days.
I'll try to somehow improve logging to get a better understanding of who was
accessing the session at which times.
Let me know if you have some idea/wish of what should be logged additionally.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
Georg F. <ma...@gmx.de> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |NEW
--- Comment #2 from Georg F. <ma...@gmx.de> ---
Hey Mark,
thanks for looking into it.
I think the problem still exists in the latest 10.1.x branch on GitHub.
Let me explain the problem step by step from the code on GitHub:
* When the WebSocket is closed the WebSocket tries to send the close message
via
https://github.com/apache/tomcat/blob/8b1833f75bfce59a05791dede5eb9904b51da3da/java/org/apache/tomcat/websocket/WsSession.java#L718
* This in turn will try to send the message parts via
https://github.com/apache/tomcat/blob/b9a8bd4fdaf31b0cc08cc72f95c802d35bb885f2/java/org/apache/tomcat/websocket/WsRemoteEndpointImplBase.java#L311
* Unfortunately this may fail for whatever reason which then ends up in
closing the session via
https://github.com/apache/tomcat/blob/b9a8bd4fdaf31b0cc08cc72f95c802d35bb885f2/java/org/apache/tomcat/websocket/WsRemoteEndpointImplBase.java#L322
* The problem is now that the session now got to a "CLOSED" state, but when
returning from these methods we end up in
https://github.com/apache/tomcat/blob/8b1833f75bfce59a05791dede5eb9904b51da3da/java/org/apache/tomcat/websocket/WsSession.java#L734
which tries to get the user principal on the closed session which is forbidden.
* And so another exception is thrown which overrules the previous one and
shows this confusing message.
I hope that helps.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #4 from Georg F. <ma...@gmx.de> ---
(In reply to Mark Thomas from comment #3)
> There are two code paths to this line.
> The path via WsSession.doClose() will have set WsSession.state to
> OUTPUT_CLOSING.
> The path via WsSession.onClose() will have set WsSession.state to CLOSING.
Right - my fault: I've mixed up "doClose" and "onClose". Sorry. :(
Then I don't have a real idea of how this happened.
I'm working in a multithreaded environment, so I'm wondering if there is some
way of having a race condition here? Or is everything secured by some locking
mechanism?
What I can tell is, that I first see that a send on "thread A" fails due to a
broken connection to the client. Shortly after "thread B" calls the close()
method and shows this stacktrace. Might be that thread B even calls close()
while the sending fails - can't really tell that from the logs I have. Or would
that already be an illegal procedure?
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
Mark Thomas <ma...@apache.org> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEW |NEEDINFO
--- Comment #3 from Mark Thomas <ma...@apache.org> ---
(In reply to Georg F. from comment #2)
> Hey Mark,
>
> thanks for looking into it.
> I think the problem still exists in the latest 10.1.x branch on GitHub.
>
> Let me explain the problem step by step from the code on GitHub:
> * When the WebSocket is closed the WebSocket tries to send the close
> message via
> https://github.com/apache/tomcat/blob/
> 8b1833f75bfce59a05791dede5eb9904b51da3da/java/org/apache/tomcat/websocket/
> WsSession.java#L718
There are two code paths to this line.
The path via WsSession.doClose() will have set WsSession.state to
OUTPUT_CLOSING.
The path via WsSession.onClose() will have set WsSession.state to CLOSING.
> * This in turn will try to send the message parts via
> https://github.com/apache/tomcat/blob/
> b9a8bd4fdaf31b0cc08cc72f95c802d35bb885f2/java/org/apache/tomcat/websocket/
> WsRemoteEndpointImplBase.java#L311
No further change in WsSession.state occurs to this point.
> * Unfortunately this may fail for whatever reason which then ends up in
> closing the session via
> https://github.com/apache/tomcat/blob/
> b9a8bd4fdaf31b0cc08cc72f95c802d35bb885f2/java/org/apache/tomcat/websocket/
> WsRemoteEndpointImplBase.java#L322
No further change in WsSession.state occurs to this point.
> * The problem is now that the session now got to a "CLOSED" state
How? when WsSession.doClose() is called the state check on line 568 will cause
the method to return immediately with no further change in WsSession.state
https://github.com/apache/tomcat/blob/8b1833f75bfce59a05791dede5eb9904b51da3da/java/org/apache/tomcat/websocket/WsSession.java#L568
>, but when
> returning from these methods we end up in
> https://github.com/apache/tomcat/blob/
> 8b1833f75bfce59a05791dede5eb9904b51da3da/java/org/apache/tomcat/websocket/
> WsSession.java#L734 which tries to get the user principal on the closed
> session which is forbidden.
?
> * And so another exception is thrown which overrules the previous one and
> shows this confusing message.
>
> I hope that helps.
Sorry, it doesn't yet. Following that code path described I don't see how
WsSession.getUserPrincipal() can fail the checkState() test and trigger the
exception.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #9 from Mark Thomas <ma...@apache.org> ---
Ping. It has been two months. This is heading towards being closed as
WORKSFORME.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
--- Comment #5 from Mark Thomas <ma...@apache.org> ---
Everything *should* be protected by some form of lock mechanism. That you saw
the stack trace you did indicates that it wasn't for 10.1.8. I've looked at the
code and I can't see how this could have happened.
I'll leave this open but unless we can figure out how this happened, it will
eventually get resolved as WORKSFORME.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org
[Bug 66676] WebSocket session complains about closed state when calling close()
Posted by bu...@apache.org.
https://bz.apache.org/bugzilla/show_bug.cgi?id=66676
Georg F. <ma...@gmx.de> changed:
What |Removed |Added
----------------------------------------------------------------------------
Status|NEEDINFO |RESOLVED
Resolution|--- |WORKSFORME
--- Comment #10 from Georg F. <ma...@gmx.de> ---
Hey Mark,
sorry for the late response.
So we've rewritten the part of how we close the WebSockets a bit.
It seems that this did the trick as there is now less concurrent action on the
WebSocket session and so all the exceptions are gone.
Of course a bit unsatisfying that we don't know what actually caused the issue,
but I had to get rid of the issue, as this was causing additional trouble.
In any case: Thanks for your help and this ticket is now closed.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@tomcat.apache.org
For additional commands, e-mail: dev-help@tomcat.apache.org