search

socketry / async-websocket

Asynchronous WebSocket client and server, supporting HTTP/1 and HTTP/2 for Ruby.
MIT License
166 stars 18 forks source link

Test failures in 0.25.0 release #53

Closed felixonmars closed 1 year ago

felixonmars commented 1 year ago

I got these new test failures when packaging for Arch. It reproduces reliably across multiple builders.

Some environment: Ruby 3.0.5, async-http 0.59.5, async-io 1.34.0, protocol-rack 0.2.4, protocol-websocket 0.10.0

{"time":"2023-03-28T10:07:37+02:00","severity":"warn","class":"Async::Pool::Controller","oid":4460,"pid":1352,"subject":"#<Async::Pool::Controller(0/∞)>","message":"Closing resource while still in use!","resource":"#<Async::HTTP::Protocol::HTTP1::Client:0x00005587dfb659d8>","usage":1}
{"time":"2023-03-28T10:07:37+02:00","severity":"warn","class":"Async::Pool::Controller","oid":5300,"pid":1352,"subject":"#<Async::Pool::Controller(0/∞)>","message":"Closing resource while still in use!","resource":"#<Async::HTTP::Protocol::HTTP2::Client 1 active streams>","usage":1}
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
31 passed 2 failed 1 errored out of 34 total (57 assertions)
🏁 Finished in 47.5ms; 1201.103 assertions per second.
🐇 No slow tests found! Well done!

🤔 Failed assertions:
describe Async::WebSocket::Client with http/1 it behaves like a websocket client with #send_close it can read incoming messages and then close test/async/websocket/client.rb:112:24
        expect 0 to
                be == 3
                        ✗ assertion failed test/async/websocket/client.rb:39
        expect #<Async::WebSocket::Connection:0x00005587df9057b0 @framer=#<Async::WebSocket::Client::Framer:0x00005587df905b48 @stream=#<Async::IO::Stream:0x00005587df8df538 @io=#<Async::IO::Socket:0x00005587df8dfb00 @io=#<Socket:(closed)>, @reactor=#<Async::Reactor:0x00005587df8c51b0 @parent=nil, @children=#<Async::Children:0x00005587df8c4a08 @head=nil, @tail=nil, @size=0, @transient_count=0>, @annotation=nil, @object_name=nil, @transient=false, @head=nil, @tail=nil, @selector=nil, @timers=#<Timers::Group:0x00005587df8c5098 @events=#<Timers::Events:0x00005587df8c5048 @sequence=#<Timers::PriorityHeap:0x00005587df8c4ff8 @contents=[]>, @queue=[]>, @timers=#<Set: {}>, @paused_timers=#<Set: {}>, @interval=#<Timers::Interval:0x00005587df8c4e68 @total=0.0, @current=171696.099093903>>, @logger=nil, @ready=[], @running=[], @scheduler=#<Async::Scheduler:0x00005587df8c4da0 @reactor=#<Async::Reactor:0x00005587df8c51b0 ...>>, @interrupted=false, @guard=#<Thread::Mutex:0x00005587df8c4d50>, @blocked=0, @unblocked=[]>, @monitor=nil, @readable=nil, @writable=nil, @any=nil, @timeout=nil>, @eof=false, @pending=0, @writing=#<Async::Semaphore:0x00005587df8df498 @count=0, @limit=1, @waiting=[], @parent=nil>, @block_size=65536, @maximum_read_size=8388608, @read_buffer="", @write_buffer="", @drain_buffer="", @input_buffer="">, @frames={0=>Protocol::WebSocket::ContinuationFrame, 1=>Protocol::WebSocket::TextFrame, 2=>Protocol::WebSocket::BinaryFrame, 8=>Protocol::WebSocket::CloseFrame, 9=>Protocol::WebSocket::PingFrame, 10=>Protocol::WebSocket::PongFrame}, @pool=nil, @connection=nil>, @mask=true, @state=:closed, @frames=[], @reserved=3, @reader=#<Protocol::WebSocket::Extension::Compression::Inflate:0x00005587df9055f8 @parent=#<Async::WebSocket::Connection:0x00005587df9057b0 ...>, @inflate=nil, @window_bits=15, @context_takeover=true>, @writer=#<Protocol::WebSocket::Extension::Compression::Deflate:0x00005587df905530 @parent=#<Async::WebSocket::Connection:0x00005587df9057b0 ...>, @deflate=#<Zlib::Deflate:0x00005587df905170>, @level=-1, @memory_level=8, @strategy=0, @window_bits=15, @context_takeover=true>, @protocol=nil> to
                be closed?
describe Async::WebSocket::Client with http/2 it behaves like a websocket client with #send_close it can read incoming messages and then close test/async/websocket/client.rb:117:24
        expect 0 to
                be == 3
                        ✗ assertion failed test/async/websocket/client.rb:39
        expect #<Async::WebSocket::Connection:0x00005587dfcbe050 @framer=#<Async::WebSocket::Client::Framer:0x00005587dfcbe398 @stream=#<Protocol::HTTP::Body::Stream:0x00005587dfcbe7a8 @input=nil, @output=nil, @buffer=nil, @closed=true>, @frames={0=>Protocol::WebSocket::ContinuationFrame, 1=>Protocol::WebSocket::TextFrame, 2=>Protocol::WebSocket::BinaryFrame, 8=>Protocol::WebSocket::CloseFrame, 9=>Protocol::WebSocket::PingFrame, 10=>Protocol::WebSocket::PongFrame}, @pool=nil, @connection=nil>, @mask=true, @state=:closed, @frames=[], @reserved=3, @reader=#<Protocol::WebSocket::Extension::Compression::Inflate:0x00005587dfcbde98 @parent=#<Async::WebSocket::Connection:0x00005587dfcbe050 ...>, @inflate=nil, @window_bits=15, @context_takeover=true>, @writer=#<Protocol::WebSocket::Extension::Compression::Deflate:0x00005587dfcbddd0 @parent=#<Async::WebSocket::Connection:0x00005587dfcbe050 ...>, @deflate=#<Zlib::Deflate:0x00005587dfcbdbc8>, @level=-1, @memory_level=8, @strategy=0, @window_bits=15, @context_takeover=true>, @protocol=nil> to
                be closed?
describe Async::WebSocket::Client with http/1 it behaves like a websocket client with #send_close it can read incoming messages and then close test/async/websocket/client.rb:112:24
        expect 0 to
                be == 3
                        ✗ assertion failed test/async/websocket/client.rb:39
        expect #<Async::WebSocket::Connection:0x00005587df9057b0 @framer=#<Async::WebSocket::Client::Framer:0x00005587df905b48 @stream=#<Async::IO::Stream:0x00005587df8df538 @io=#<Async::IO::Socket:0x00005587df8dfb00 @io=#<Socket:(closed)>, @reactor=#<Async::Reactor:0x00005587df8c51b0 @parent=nil, @children=#<Async::Children:0x00005587df8c4a08 @head=nil, @tail=nil, @size=0, @transient_count=0>, @annotation=nil, @object_name=nil, @transient=false, @head=nil, @tail=nil, @selector=nil, @timers=#<Timers::Group:0x00005587df8c5098 @events=#<Timers::Events:0x00005587df8c5048 @sequence=#<Timers::PriorityHeap:0x00005587df8c4ff8 @contents=[]>, @queue=[]>, @timers=#<Set: {}>, @paused_timers=#<Set: {}>, @interval=#<Timers::Interval:0x00005587df8c4e68 @total=0.0, @current=171696.099093903>>, @logger=nil, @ready=[], @running=[], @scheduler=#<Async::Scheduler:0x00005587df8c4da0 @reactor=#<Async::Reactor:0x00005587df8c51b0 ...>>, @interrupted=false, @guard=#<Thread::Mutex:0x00005587df8c4d50>, @blocked=0, @unblocked=[]>, @monitor=nil, @readable=nil, @writable=nil, @any=nil, @timeout=nil>, @eof=false, @pending=0, @writing=#<Async::Semaphore:0x00005587df8df498 @count=0, @limit=1, @waiting=[], @parent=nil>, @block_size=65536, @maximum_read_size=8388608, @read_buffer="", @write_buffer="", @drain_buffer="", @input_buffer="">, @frames={0=>Protocol::WebSocket::ContinuationFrame, 1=>Protocol::WebSocket::TextFrame, 2=>Protocol::WebSocket::BinaryFrame, 8=>Protocol::WebSocket::CloseFrame, 9=>Protocol::WebSocket::PingFrame, 10=>Protocol::WebSocket::PongFrame}, @pool=nil, @connection=nil>, @mask=true, @state=:closed, @frames=[], @reserved=3, @reader=#<Protocol::WebSocket::Extension::Compression::Inflate:0x00005587df9055f8 @parent=#<Async::WebSocket::Connection:0x00005587df9057b0 ...>, @inflate=nil, @window_bits=15, @context_takeover=true>, @writer=#<Protocol::WebSocket::Extension::Compression::Deflate:0x00005587df905530 @parent=#<Async::WebSocket::Connection:0x00005587df9057b0 ...>, @deflate=#<Zlib::Deflate:0x00005587df905170>, @level=-1, @memory_level=8, @strategy=0, @window_bits=15, @context_takeover=true>, @protocol=nil> to
                be closed?
describe Async::WebSocket::Client with http/2 it behaves like a websocket client with #send_close it can read incoming messages and then close test/async/websocket/client.rb:117:24
        expect 0 to
                be == 3
                        ✗ assertion failed test/async/websocket/client.rb:39
        expect #<Async::WebSocket::Connection:0x00005587dfcbe050 @framer=#<Async::WebSocket::Client::Framer:0x00005587dfcbe398 @stream=#<Protocol::HTTP::Body::Stream:0x00005587dfcbe7a8 @input=nil, @output=nil, @buffer=nil, @closed=true>, @frames={0=>Protocol::WebSocket::ContinuationFrame, 1=>Protocol::WebSocket::TextFrame, 2=>Protocol::WebSocket::BinaryFrame, 8=>Protocol::WebSocket::CloseFrame, 9=>Protocol::WebSocket::PingFrame, 10=>Protocol::WebSocket::PongFrame}, @pool=nil, @connection=nil>, @mask=true, @state=:closed, @frames=[], @reserved=3, @reader=#<Protocol::WebSocket::Extension::Compression::Inflate:0x00005587dfcbde98 @parent=#<Async::WebSocket::Connection:0x00005587dfcbe050 ...>, @inflate=nil, @window_bits=15, @context_takeover=true>, @writer=#<Protocol::WebSocket::Extension::Compression::Deflate:0x00005587dfcbddd0 @parent=#<Async::WebSocket::Connection:0x00005587dfcbe050 ...>, @deflate=#<Zlib::Deflate:0x00005587dfcbdbc8>, @level=-1, @memory_level=8, @strategy=0, @window_bits=15, @context_takeover=true>, @protocol=nil> to
                be closed?

🔥 Errored assertions:
describe Async::WebSocket::Client with http/1 it behaves like a websocket client with #close(1001) it closes with custom error test/async/websocket/client.rb:112:82
        expect #<Proc:0x00005587dfbd72e0 test/async/websocket/client.rb:86> to
                raise exception Protocol::WebSocket::Error and have {attribute code be == 1001}
                        ⚠ Errno::EPIPE: Broken pipe
                                /usr/lib/ruby/3.0.0/socket.rb:456 __write_nonblock
                                /usr/lib/ruby/3.0.0/socket.rb:456 write_nonblock
                                /usr/lib/ruby/gems/3.0.0/gems/async-io-1.34.0/lib/async/io/generic.rb:216 async_send
                                /usr/lib/ruby/gems/3.0.0/gems/async-io-1.34.0/lib/async/io/generic.rb:62 block in wrap_blocking_method
                                /usr/lib/ruby/gems/3.0.0/gems/async-io-1.34.0/lib/async/io/generic.rb:156 write
                                /usr/lib/ruby/gems/3.0.0/gems/async-io-1.34.0/lib/async/io/stream.rb:160 block in flush
                                /usr/lib/ruby/gems/3.0.0/gems/async-1.30.3/lib/async/semaphore.rb:80 acquire
                                /usr/lib/ruby/gems/3.0.0/gems/async-io-1.34.0/lib/async/io/stream.rb:155 flush
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/framer.rb:42 flush
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:55 flush
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:200 send_close
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:83 rescue in read_frame
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:68 read_frame
                                /usr/lib/ruby/gems/3.0.0/gems/protocol-websocket-0.10.0/lib/protocol/websocket/connection.rb:230 read
                                /usr/lib/ruby/3.0.0/delegate.rb:87 method_missing
                                test/async/websocket/client.rb:87 block (5 levels) in <top (required)>
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/raise_exception.rb:22 block in call
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/assertions.rb:295 block in nested
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/output/buffered.rb:64 indented
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/assertions.rb:293 nested
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/raise_exception.rb:20 call
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/expect.rb:40 block in to
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/assertions.rb:295 block in nested
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/output/buffered.rb:64 indented
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/assertions.rb:293 nested
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/expect.rb:39 to
                                test/async/websocket/client.rb:86 block (4 levels) in <top (required)>
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/it.rb:49 block in handle_skip
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/it.rb:48 catch
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/it.rb:48 handle_skip
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/it.rb:42 block (2 levels) in call
                                /usr/lib/ruby/gems/3.0.0/gems/sus-0.20.2/lib/sus/base.rb:28 around
                                /usr/lib/ruby/gems/3.0.0/gems/sus-fixtures-async-0.1.1/lib/sus/fixtures/async/reactor_context.rb:70 block (2 levels) in around
                                /usr/lib/ruby/gems/3.0.0/gems/sus-fixtures-async-0.1.1/lib/sus/fixtures/async/reactor_context.rb:37 block in run_with_timeout
                                /usr/lib/ruby/gems/3.0.0/gems/async-1.30.3/lib/async/task.rb:261 block in make_fiber
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
PeterRunich commented 1 year ago

I think my issue https://github.com/socketry/async-websocket/issues/50 relates to this, we fixed something with ioquatix. This also affected protocol-websocket. Everything works for protocol-websocket 0.11.0. Try bundle update async-websocket or if you don't use bundler gem update async-websocket. I think we should bump version in .gemspec. @ioquatix

ioquatix commented 1 year ago

I have released 0.25.1 with #54 merged. Can you let me know if that fixes the issues?

ioquatix commented 1 year ago

Also, I removed

zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.
zlib(finalizer): the stream was freed prematurely.

which was emitted by the CRuby zlib code, I guess it took effect in 3.1

felixonmars commented 1 year ago

Confirmed that updating protocol-websocket to 0.11.0 fixes this. Thanks!