Closed PeterRunich closed 1 year ago
Okay, I figured out such a test, but it doesn't work with http 2. I'm going to continue my research.
https://github.com/PeterRunich/async-websocket/commit/c48e6aa0a8093508d31baed1552b86fb920c4c18
I haven't been able to figure it out yet, but when I send #close 1001, then in the server code on this line https://github.com/socketry/protocol-http2/blob/main/lib/protocol/http2/framer.rb#L82 (using print) you can catch two frames `
` as I understand it, this is the signal to close the connection , but in the future, as I understood in the protocol-websocket library, the frames should turn into CloseFrame, but this does not happen. Unfortunately, I am not yet familiar with the specification of http and websocket and do not understand the entire code base of the library very well. I hope this information will help @ioquatix figure it out.
if you switch to http 1 then here https://github.com/socketry/protocol-websocket/blob/58f0d15c6c5b44d224fd7a6eb237ce331bd8a587/lib/protocol/websocket/framer.rb#L54 You can catch the CloseFrame I was talking about
#<Protocol::WebSocket::CloseFrame:0x00007f78d33d1ff0 @finished=true, @flags=0, @opcode=8, @mask="\xA8%|\n", @length=2, @payload="\xAB\xCC">
Thanks for the investigation, I'll take a look later today.
Also, if you initiate the closing of the connection from the server on http2, something strange happen.
http1 outputs
1002
http2 outputs
1.29s warn: Async::Task [oid=0xd34] [ec=0xd48] [pid=21689] [2023-03-07 12:01:10 +0300]
| Task may have ended with unhandled exception.
| Protocol::HTTP2::ProtocolError: Cannot send data in state: closed
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http2-0.15.1/lib/protocol/http2/stream.rb:218 in `send_data'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/output.rb:119 in `send_data'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/output.rb:66 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http-0.24.1/lib/protocol/http/body/stream.rb:130 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/frame.rb:218 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:59 in `write_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:93 in `write_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:199 in `send_close'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:87 in `rescue in read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:68 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:230 in `read'
| test/async/websocket/client.rb:53 in `block (7 levels) in <top (required)>'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:248 in `block in schedule'
| Caused by EOFError: Could not read frame header!
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:67 in `read_header'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:49 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:71 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:230 in `read'
| test/async/websocket/client.rb:53 in `block (7 levels) in <top (required)>'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:248 in `block in schedule'
1.29s warn: Async::Task [oid=0xd5c] [ec=0xd70] [pid=21689] [2023-03-07 12:01:10 +0300]
| Task may have ended with unhandled exception.
| Protocol::HTTP2::ProtocolError: Cannot send data in state: closed
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http2-0.15.1/lib/protocol/http2/stream.rb:218 in `send_data'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/output.rb:119 in `send_data'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/output.rb:66 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http-0.24.1/lib/protocol/http/body/stream.rb:130 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/frame.rb:218 in `write'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:59 in `write_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:93 in `write_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:199 in `send_close'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:87 in `rescue in read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:68 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:230 in `read'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/3.2.0/delegate.rb:87 in `method_missing'
| test/async/websocket/client.rb:66 in `block (5 levels) in <top (required)>'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:248 in `block in schedule'
| Caused by EOFError: Could not read frame header!
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:67 in `read_header'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:49 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:71 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:230 in `read'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/3.2.0/delegate.rb:87 in `method_missing'
| test/async/websocket/client.rb:66 in `block (5 levels) in <top (required)>'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.0/lib/async/task.rb:248 in `block in schedule'
upd: I noticed that if you change the closing code (1001, 1002, 1003 etc), on the http1 server, the client still gets 1002 💀
Oops, looks a bit odd.
https://github.com/socketry/async-websocket/commit/7eb22b6a44d2fefd43bde110859c5d3fde314aed fixes the argument passing, but it looks like we have other issues here.
yep
By the way, i use async-websocket in my library for discord and there the error codes come different correctly. There I use http1.
Hmm, I see part of the problem. The RFC 6455 is a bit weird:
If an endpoint receives a Close frame and did not previously send a
Close frame, the endpoint MUST send a Close frame in response. (When
sending a Close frame in response, the endpoint typically echos the
status code it received.) It SHOULD do so as soon as practical. An
endpoint MAY delay sending a Close frame until its current message is
sent (for instance, if the majority of a fragmented message is
already sent, an endpoint MAY send the remaining fragments before
sending a Close frame). However, there is no guarantee that the
endpoint that has already sent a Close frame will continue to process
data.
After both sending and receiving a Close message, an endpoint
considers the WebSocket connection closed and MUST close the
underlying TCP connection. The server MUST close the underlying TCP
connection immediately; the client SHOULD wait for the server to
close the connection but MAY close the connection at any time after
sending and receiving a Close message, e.g., if it has not received a
TCP Close from the server in a reasonable time period.
If a client and server both send a Close message at the same time,
both endpoints will have sent and received a Close message and should
consider the WebSocket connection closed and close the underlying TCP
connection.
When you receive a close frame, you should echo it back, but this often fails because the stream is closed. I wonder what the correct behaviour is here.
Maybe I misunderstood, but it says
the client SHOULD wait for the server to close the connection but MAY close the connection at any time after sending and receiving a Close message, e.g., if it has not received a TCP Close from the server in a reasonable time period.
is it waiting for any signal from the server on the client now when I call #close? I haven't looked at the source code, but judging by the way I see it, I guess it just sounds like close and the connection closes immediately.
I'm not sure there is value in waiting for the server to send a close frame, unless it's a matter of processing any pending data frames, i.e.
Connection#close
.In terms of code, this would need to be something like this:
# On the server:
server.send(...) # send data frames
server.close # send close frame
# On the client:
client.send_close # send the close frame to the server
while message = client.read # Eventually this will return nil
process(message)
end
I'll continue investigating this tomorrow.
ok thanks, it doesn't really affect my code, I'll try to expand my knowledge, maybe I can help with something 🙂
I've released the main fix (passing arguments through to close) in v0.25.0.
Can you please try it out.
I believe it should correctly handle closed states and send_close(error_code)
better now. If you have time to try it out, please let me know how you get on.
on server
rescue Errno::EPIPE => e
changed to
rescue Protocol::WebSocket::ClosedError => e
i think it's good
https://github.com/PeterRunich/async-websocket/blob/oddities-with-closing/test/async/websocket/wip.rb further read "with" descriptions in code above
i read a little more about error codes https://www.rfc-editor.org/rfc/rfc6455.html#section-5.1 about 1002, maybe this relates to the second test case i started using 4000-4999 range codes, just in case, because the interpretation of these codes is undefined by this protocol
traces for second test:
http1
2.22s warn: Async::Task [oid=0x16d0] [ec=0x16e4] [pid=13510] [2023-03-08 14:59:39 +0300]
| Task may have ended with unhandled exception.
| Async::TimeoutError: execution expired
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/wrapper.rb:35 in `wait_readable'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/generic.rb:220 in `async_send'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/generic.rb:69 in `block in wrap_blocking_method'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/stream.rb:263 in `fill_read_buffer'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/stream.rb:83 in `read'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/framer.rb:63 in `read_header'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/framer.rb:49 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/connection.rb:91 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/connection.rb:238 in `read'
| test/async/websocket/wip.rb:61 in `block (6 levels) in <top (required)>'
| lib/async/websocket/adapters/http.rb:41 in `block in open'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/body/hijack.rb:56 in `call'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http1/server.rb:85 in `each'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/server.rb:56 in `accept'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/server.rb:32 in `block in accept_each'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-io-1.34.3/lib/async/io/socket.rb:73 in `block in accept'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:248 in `block in schedule'
1002
http2 sleep 1 not commented
describe Async::WebSocket::Client with http/2 it behaves like a websocket client with http1 Async::TimeoutError: execution expired and client rcv 1002, http2 Protocol::HTTP2::ProtocolError: Cannot send data in state: closed it closes with custom error test/async/websocket/wip.rb:101:72
⚠ Protocol::HTTP2::ProtocolError: Cannot send data in state: closed
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http2-0.15.1/lib/protocol/http2/stream.rb:218 send_data
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/stream.rb:151 finish_output
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-http-0.60.1/lib/async/http/protocol/http2/output.rb:73 close
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http-0.24.1/lib/protocol/http/body/stream.rb:155 close_write
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-http-0.24.1/lib/protocol/http/body/stream.rb:162 close
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/framer.rb:38 close
/home/pepe/Desktop/ruby_pr/pod_dis/fork/async-websocket/lib/async/websocket/client.rb:83 close
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/connection.rb:85 close
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/3.2.0/delegate.rb:87 method_missing
/home/pepe/Desktop/ruby_pr/pod_dis/fork/async-websocket/lib/async/websocket/client.rb:45 close
test/async/websocket/wip.rb:84 block (4 levels) in <top (required)>
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-0.20.3/lib/sus/it.rb:49 block in handle_skip
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-0.20.3/lib/sus/it.rb:48 catch
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-0.20.3/lib/sus/it.rb:48 handle_skip
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-0.20.3/lib/sus/it.rb:42 block (2 levels) in call
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-0.20.3/lib/sus/base.rb:28 around
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-fixtures-async-0.1.1/lib/sus/fixtures/async/reactor_context.rb:70 block (2 levels) in around
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/sus-fixtures-async-0.1.1/lib/sus/fixtures/async/reactor_context.rb:37 block in run_with_timeout
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:107 block in run
/home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:248 block in schedule
http2 sleep 1 commented
0.88s warn: Async::Task [oid=0x16d0] [ec=0x16e4] [pid=13440] [2023-03-08 14:59:08 +0300]
| Task may have ended with unhandled exception.
| EOFError: Could not read frame header!
| → /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/framer.rb:67 in `read_header'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/framer.rb:49 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/connection.rb:91 in `read_frame'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/protocol-websocket-0.11.0/lib/protocol/websocket/connection.rb:238 in `read'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/3.2.0/delegate.rb:87 in `method_missing'
| test/async/websocket/wip.rb:77 in `block (5 levels) in <top (required)>'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:107 in `block in run'
| /home/pepe/.rbenv/versions/3.2.1/lib/ruby/gems/3.2.0/gems/async-2.4.1/lib/async/task.rb:248 in `block in schedule'
I haven't been able to figure it out yet, but when I send #close 1001, then in the server code on this line https://github.com/socketry/protocol-http2/blob/main/lib/protocol/http2/framer.rb#L82 (using print) you can catch two frames
#<Protocol::HTTP2::Data Frame stream_id=1 flags=0 6b> #<Protocol::HTTP2::Data Frame stream_id=1 flags=0 2b>
as I understand it, this is the signal to close the connection , but in the future, as I understood in the protocol-websocket library, the frames should turn into CloseFrame, but this does not happen. Unfortunately, I am not yet familiar with the specification of http and websocket and do not understand the entire code base of the library very well. I hope this information will help ioquatix figure it out.if you switch to http 1 then here https://github.com/socketry/protocol-websocket/blob/58f0d15c6c5b44d224fd7a6eb237ce331bd8a587/lib/protocol/websocket/framer.rb#L54 You can catch the CloseFrame I was talking about
#<Protocol::WebSocket::CloseFrame:0x00007f78d33d1ff0 @finished=true, @flags=0, @opcode=8, @mask="\xA8%|\n", @length=2, @payload="\xAB\xCC">
just in case, I repeat, this applies to the first test with http2
Off-topic: I hope I'm not too annoying. As far as I understand, websocket over http 2 is not particularly popular. I'm not insisting that we solve these problems right now. I'd enjoy taking the time to solve these problems myself, but I feel that reading the spec and code base would take a long time. I'm finishing college right now and I'm doing a Discord library as part of my thesis, that takes a lot of time too :( . The only thing I would really pay attention to is the second test with http1. 🙂
Hi again! I opened this https://github.com/socketry/async-websocket/issues/46 issue some time ago. Today i found a small bug, we forgot to forward arguments in the delegator #close method. https://github.com/socketry/async-websocket/blob/cff18c07ee46034d9d3a84b6771e06a130feb009/lib/async/websocket/client.rb#L38-L52 Here are the arguments I was talking about https://github.com/socketry/protocol-websocket/blob/58f0d15c6c5b44d224fd7a6eb237ce331bd8a587/lib/protocol/websocket/connection.rb#L62-L63
https://github.com/PeterRunich/async-websocket/commit/3e7698dd10240fa0bc085859e6a066f6c563af99 i fixed it, but i didn't figure out how to write a test. i think it should look similar like this test https://github.com/socketry/async-websocket/blob/cff18c07ee46034d9d3a84b6771e06a130feb009/test/async/websocket/client.rb#L23-L33 but i didn't figured out how to expect "moment of closing" on the server and comparing close codes, it would be nice if you explain it (or if it takes less of your time, you can write it yourself :) )