Issue metadata
Sign in to add a comment
|
Websocket onclose event fires very late
Reported by
d3c...@gmail.com,
Aug 18
|
||||||||||||||||||||||||
Issue descriptionUserAgent: Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/68.0.3440.84 Safari/537.36 Steps to reproduce the problem: Somewhat similar to https://bugs.chromium.org/p/chromium/issues/detail?id=426798 1) create a websocket object 2) set onopen/onclose 3) use websocket.close(); (connect to https://www.chatment.com ) the intial background scripts make such a connection. I was debuggin why it takes so very long to switch from 'connecting' to 'login' on the button status. I had recently updated the server to have better performance on its sqlite databases, but yet that was still slow. My C application doesn't have the same sort of issue; but I did have to implement shutdown (http://man7.org/linux/man-pages/man2/shutdown.2.html ; https://docs.microsoft.com/en-us/windows/desktop/api/winsock/nf-winsock-shutdown ) What is the expected behavior? Expect the onclose event to fire fairly quickly. What really happens is it fires about 2 seconds later. What happens on the network is the websocket close is sent to the server, followed by a final, the server replies with the websocket close; which is responded to with a RST. The socket has apparently been closed in such a way that it will not receive the response from the server. The server closes the socket. The client(browser) then 2 second later dispatches the onclose event to the JS code. What went wrong? The browser apparently never receives the wwebsocket close message from the server, and delays close event. Did this work before? N/A Does this work in other browsers? N/A Chrome version: 68.0.3440.84 Channel: stable OS Version: 10.0 Flash Version: Attached weireshark log - packet 2845 is the webbrowser sending websocket close towserver 2846 is the browser sending a FIN on the TCP socket. 2849 is server sending websocket close 2850 is client responding with RST instaed of ACK.
,
Aug 18
err sorry I guess it's 3008; 2851 is filtered out.
,
Aug 19
,
Aug 21
Thanks for filing the issue! @Reporter: Could you please share any sample test file which helps us to triage the issue further in a better way.
,
Aug 21
well it's not something that the browser itself can do; it needs a server also. I can of course make simple scripts to replicate it, but I would do it using Node as the server...
,
Aug 21
Thank you for providing more feedback. Adding the requester to the cc list. For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Aug 22
Can you provide a net log? https://www.chromium.org/for-testers/providing-network-details
,
Aug 22
working on log. a quick note: was also making a simpler test case page; which doesn't demonstrate the issue. Will report back with logs and/or more info on the scenario. for example one detail I didn't mention; connection is HTTPS/WSS. (there is not a slowness on http) If ws.close() is called in the onopen; there is no delay. does not require sending data... ws.close has to be called AFTER the onopen event.... (setTimeout(0) in onopen that just does ws.close also triggers slow close... https://www.chatment.com/wsTest.html ------------ <HTML> <HEAD> <TITLE>WebSocket Slow close</TITLE> <BODY> </BODY> <SCRIPT> var start = Date.now(); var ws = new WebSocket( (location.protocol==="https:"?"wss":"ws")+"://"+location.hostname+":"+8000+"/userAuth" , "chatment.core" ) ws.onopen = function() { var openat = Date.now(); console.log( "Opened after", openat-start, "ms" ); setTimeout( ()=> ws.close(), 0 ); } //setTimeout( ()=> ws.close(), 250 ); ws.onmessage = function(evt) { console.log( "Got:", evt ); } ws.onclose = function( reason, code ) { var closeat = Date.now(); console.log( "close event after", closeat-start, "ms", reason, code ); } </SCRIPT> </HTML> ---------------- sample output wsTest.html:13 Opened after 115 ms wsTest.html:23 close event after 2276 ms CloseEvent {isTrusted: true, wasClean: false, code: 1006, reason: "", type: "close", …} undefined
,
Aug 22
Thank you for providing more feedback. Adding the requester to the cc list. For more details visit https://www.chromium.org/issue-tracking/autotriage - Your friendly Sheriffbot
,
Aug 22
I can reproduce the issue. It seems Chrome thinks it hasn't received a CLOSE frame.
,
Aug 22
Yes; what wireshark trace showed is that the Close frame is met with RST.
,
Aug 23
I was wrong. Chrome recognizes the CLOSE frame. Here is my netlog. I modified the script at https://www.chatment.com a bit. Chrome sends a CLOSE frame 3 seconds after the handshake finishes. See SOCKET 1068 entry. t= 599 [st= 488] SSL_SOCKET_BYTES_RECEIVED --> byte_count = 228 --> hex_encoded_bytes = 48 54 54 50 2F 31 2E 31 20 31 30 31 20 53 77 69 HTTP/1.1 101 Swi 74 63 68 69 6E 67 20 50 72 6F 74 6F 63 6F 6C 73 tching Protocols 0D 0A 55 70 67 72 61 64 65 3A 20 57 65 62 53 6F ..Upgrade: WebSo 63 6B 65 74 0D 0A 43 6F 6E 6E 65 63 74 69 6F 6E cket..Connection 3A 20 55 70 67 72 61 64 65 0D 0A 57 65 62 53 6F : Upgrade..WebSo 63 6B 65 74 2D 4F 72 69 67 69 6E 3A 20 68 74 74 cket-Origin: htt 70 3A 2F 2F 6C 6F 63 61 6C 68 6F 73 74 0D 0A 53 p://localhost..S 65 63 2D 57 65 62 53 6F 63 6B 65 74 2D 41 63 63 ec-WebSocket-Acc 65 70 74 3A 20 69 38 38 64 37 55 2F 4C 48 4C 69 ept: i88d7U/LHLi 31 6F 6A 6D 43 69 43 66 45 2B 78 46 72 52 78 55 1ojmCiCfE+xFrRxU 3D 0D 0A 53 65 63 2D 57 65 62 53 6F 63 6B 65 74 =..Sec-WebSocket 2D 50 72 6F 74 6F 63 6F 6C 3A 20 63 68 61 74 6D -Protocol: chatm 65 6E 74 2E 63 6F 72 65 0D 0A 57 65 62 53 6F 63 ent.core..WebSoc 6B 65 74 2D 53 65 72 76 65 72 3A 20 73 61 63 6B ket-Server: sack 0D 0A 0D 0A .... t=3603 [st=3492] SOCKET_BYTES_SENT --> byte_count = 35 --> hex_encoded_bytes = 17 03 03 00 1E 00 00 00 00 00 00 00 02 3B 36 A8 ... . .;6. 6C AD 20 77 5C 0E 72 0F CB 6E 4E B8 18 0B AD D3 l. w\.r..nN..... 6E 35 E3 n5. t=3603 [st=3492] SSL_SOCKET_BYTES_SENT --> byte_count = 6 --> hex_encoded_bytes = 88 80 41 C9 96 E0 ..A... t=3722 [st=3611] SOCKET_BYTES_RECEIVED --> byte_count = 31 --> hex_encoded_bytes = 17 03 03 00 1A D3 81 3F 55 87 73 4A 29 D3 B1 BC ... ...?U.sJ)... 0E DE FA 3D 35 CC E5 08 D1 CB 01 DC 1B 46 99 ...=5........F. t=3722 [st=3611] SSL_SOCKET_BYTES_RECEIVED --> byte_count = 2 --> hex_encoded_bytes = 88 00 . t=5723 [st=5612] -SOCKET_IN_USE t=5723 [st=5612] -SOCKET_IN_USE t=5724 [st=5613] -SOCKET_ALIVE At t=3603 Chrome sends a CLOSE frame. At t=3722 Chrome receives a CLOSE frame ([88, 00]) from the server. What's wrong is SOCKET is not closed. As discussed at issue 426798 , we wait for socket to be closed, with 2 seconds timeout. +Internals>Network
,
Aug 23
I revised my scripts so I don't count on the close event to continue forward in the process. The new method, and the test script, when observed with wireshark do show the close frames going both directions and received, and no RST... So perhaps there's two ways with different behaviors... going to try and revert some of the changes and see if I can cause the other too... And yes; with the simple script, does seem the close frames are sent both ways and received.
,
Aug 28
Chrome waits for the server to close the connection as recommended by RFC6455 section 7.1.1: The underlying TCP connection, in most normal cases, SHOULD be closed first by the server, so that it holds the TIME_WAIT state and not the client (as this would prevent it from re-opening the connection for 2 maximum segment lifetimes (2MSL), while there is no corresponding server impact as a TIME_WAIT connection is immediately reopened upon a new SYN with a higher seq number). In abnormal cases (such as not having received a TCP Close from the server after a reasonable amount of time) a client MAY initiate the TCP Close. As such, when a server is instructed to _Close the WebSocket Connection_ it SHOULD initiate a TCP Close immediately, and when a client is instructed to do the same, it SHOULD wait for a TCP Close from the server. Chrome could in principle fire the onclose event as soon as it gets a Close frame without without waiting for the underlying TCP connection to be closed. It doesn't do this because it complicates the logic, increasing the risk of bugs with little benefit. Servers can easily prevent the issue by closing the TCP connection after sending the Close frame, as RFC6455 suggests.
,
Aug 28
Okay. I can accept that. Thank you for your time and informative response. I was able to modify the close on the server code; and this was actually a user error. |
|||||||||||||||||||||||||
►
Sign in to add a comment |
|||||||||||||||||||||||||
Comment 1 by d3c...@gmail.com
, Aug 18