test_out_forward: Fix a failed test on Ruby 3.2 on Windows #3968

ashie · 2022-11-22T09:00:39Z

Which issue(s) this PR fixes:
Fixes #3885

What this PR does / why we need it:
Fluent::Test::Driver::Base#instance_shutdown causes rase on Ruby 3.2 on Windows. I'm not sure the detailed mechanism of this issue but exiting the test driver normally doesn't cause it.

2022-09-15T04:02:03.9921391Z #<Thread:0x000001ddefc90b20@event_loop D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:70 run> terminated with exception (report_on_exception is true):
2022-09-15T04:02:03.9948504Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach': expected loop to be an instance of Coolio::Loop, not nil (ArgumentError)
2022-09-15T04:02:03.9948899Z
2022-09-15T04:02:03.9949030Z       @_read_watcher.attach(loop)
2022-09-15T04:02:03.9949263Z                             ^^^^
2022-09-15T04:02:03.9949760Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach'
2022-09-15T04:02:03.9950342Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/socket.rb:39:in `attach'
2022-09-15T04:02:03.9950654Z 	 from (eval):7:in `attach'
2022-09-15T04:02:03.9951144Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/server.rb:40:in `on_connection'
2022-09-15T04:02:03.9951733Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/listener.rb:65:in `on_readable'
2022-09-15T04:02:03.9952292Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once'
2022-09-15T04:02:03.9952792Z 	 from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run'
2022-09-15T04:02:03.9953233Z 	 from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2022-09-15T04:02:03.9953646Z 	 from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-09-15T04:02:04.9796436Z Started
2022-09-15T04:02:04.9796980Z E
2022-09-15T04:02:04.9797374Z ===============================================================================
2022-09-15T04:02:04.9803849Z Error: test: Create connection per send_data(ForwardOutputTest::keepalive::with require_ack_response): ArgumentError: expected loop to be an instance of Coolio::Loop, not nil
2022-09-15T04:02:04.9805379Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach'
2022-09-15T04:02:04.9806300Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach'
2022-09-15T04:02:04.9807276Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/socket.rb:39:in `attach'
2022-09-15T04:02:04.9807673Z (eval):7:in `attach'
2022-09-15T04:02:04.9808146Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/server.rb:40:in `on_connection'
2022-09-15T04:02:04.9808662Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/listener.rb:65:in `on_readable'
2022-09-15T04:02:04.9809222Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once'
2022-09-15T04:02:04.9809774Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run'
2022-09-15T04:02:04.9810202Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2022-09-15T04:02:04.9810573Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-09-15T04:02:04.9810931Z ===============================================================================

Docs Changes:
N/A

Release Note:
N/A

Fluent::Test::Driver::Base#instance_shutdown causes rase on Ruby 3.2 on Windows. I'm not sure the detailed mechanism of this issue but exiting the test driver normally doesn't cause it. ``` 2022-09-15T04:02:03.9921391Z #<Thread:0x000001ddefc90b20@event_loop D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:70 run> terminated with exception (report_on_exception is true): 2022-09-15T04:02:03.9948504Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach': expected loop to be an instance of Coolio::Loop, not nil (ArgumentError) 2022-09-15T04:02:03.9948899Z 2022-09-15T04:02:03.9949030Z @_read_watcher.attach(loop) 2022-09-15T04:02:03.9949263Z ^^^^ 2022-09-15T04:02:03.9949760Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach' 2022-09-15T04:02:03.9950342Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/socket.rb:39:in `attach' 2022-09-15T04:02:03.9950654Z from (eval):7:in `attach' 2022-09-15T04:02:03.9951144Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/server.rb:40:in `on_connection' 2022-09-15T04:02:03.9951733Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/listener.rb:65:in `on_readable' 2022-09-15T04:02:03.9952292Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once' 2022-09-15T04:02:03.9952792Z from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run' 2022-09-15T04:02:03.9953233Z from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start' 2022-09-15T04:02:03.9953646Z from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create' 2022-09-15T04:02:04.9796436Z Started 2022-09-15T04:02:04.9796980Z E 2022-09-15T04:02:04.9797374Z =============================================================================== 2022-09-15T04:02:04.9803849Z Error: test: Create connection per send_data(ForwardOutputTest::keepalive::with require_ack_response): ArgumentError: expected loop to be an instance of Coolio::Loop, not nil 2022-09-15T04:02:04.9805379Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach' 2022-09-15T04:02:04.9806300Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/io.rb:35:in `attach' 2022-09-15T04:02:04.9807276Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/socket.rb:39:in `attach' 2022-09-15T04:02:04.9807673Z (eval):7:in `attach' 2022-09-15T04:02:04.9808146Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/server.rb:40:in `on_connection' 2022-09-15T04:02:04.9808662Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/listener.rb:65:in `on_readable' 2022-09-15T04:02:04.9809222Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run_once' 2022-09-15T04:02:04.9809774Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/loop.rb:88:in `run' 2022-09-15T04:02:04.9810202Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start' 2022-09-15T04:02:04.9810573Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create' 2022-09-15T04:02:04.9810931Z =============================================================================== ``` Fix #3885 Signed-off-by: Takuro Ashie <[email protected]>

cosmo0920

Hmm..., it's interesting behavior. Looks good.
Just removing d.instance_shutdown and begin ... ensure clause prevents this race condition error, right?

ashie · 2022-11-22T15:53:45Z

Hmm..., it's interesting behavior. Looks good. Just removing d.instance_shutdown and begin ... ensure clause prevents this race condition error, right?

That's right.

ashie · 2022-11-23T01:23:49Z

Still one test is failed on Ruby 3.2 on Windows but it's not related to this.

2022-11-23T00:12:01.5360433Z #<Thread:0x000001cc34399a48@http_server_helper_test_tls D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:70 run> terminated with exception (report_on_exception is true):
2022-11-23T00:12:01.5360848Z   test_cors_preflight:					E
2022-11-23T00:12:01.5639465Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+3/logger.rb:700:in `warn': wrong number of arguments (given 3, expected 0..1) (ArgumentError)
2022-11-23T00:12:01.5640035Z ===============================================================================
2022-11-23T00:12:01.5643199Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:242:in `fail!'
2022-11-23T00:12:01.5643735Z Error: test_cors_preflight(HttpInputTest): ArgumentError: wrong number of arguments (given 3, expected 0..1)
2022-11-23T00:12:01.5662051Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:267:in `rescue in block in make_fiber'
2022-11-23T00:12:01.5663581Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+3/logger.rb:700:in `warn'
2022-11-23T00:12:01.5665222Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:264:in `block in make_fiber'
2022-11-23T00:12:01.5666790Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:242:in `fail!'
2022-11-23T00:12:01.5668120Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+3/openssl/buffering.rb:214:in `sysread_nonblock': SSL_read: unexpected eof while reading (OpenSSL::SSL::SSLError)
2022-11-23T00:12:01.5668903Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:267:in `rescue in block in make_fiber'
2022-11-23T00:12:01.5670712Z 	from D:/rubyinstaller-head-x64/lib/ruby/3.2.0+3/openssl/buffering.rb:214:in `read_nonblock'
2022-11-23T00:12:01.5671265Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:264:in `block in make_fiber'
2022-11-23T00:12:01.5672356Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/generic.rb:216:in `async_send'
2022-11-23T00:12:01.5673096Z ===============================================================================
2022-11-23T00:12:01.5673927Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/generic.rb:69:in `block in wrap_blocking_method'
2022-11-23T00:12:01.5674404Z : (0.019065)
2022-11-23T00:12:01.5675249Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/stream.rb:261:in `fill_read_buffer'
2022-11-23T00:12:01.5676758Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/stream.rb:131:in `read_until'
2022-11-23T00:12:01.5677698Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-http-0.59.3/lib/async/http/protocol/http1/connection.rb:51:in `read_line?'
2022-11-23T00:12:01.5679858Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/protocol-http1-0.14.6/lib/protocol/http1/connection.rb:165:in `read_request'
2022-11-23T00:12:01.5680823Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-http-0.59.3/lib/async/http/protocol/http1/request.rb:31:in `read'
2022-11-23T00:12:01.5682268Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-http-0.59.3/lib/async/http/protocol/http1/server.rb:40:in `next_request'
2022-11-23T00:12:01.5689588Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-http-0.59.3/lib/async/http/protocol/http1/server.rb:61:in `each'
2022-11-23T00:12:01.5690505Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-http-0.59.3/lib/async/http/server.rb:56:in `accept'
2022-11-23T00:12:01.5691329Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/server.rb:32:in `block in accept_each'
2022-11-23T00:12:01.5692113Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-io-1.34.0/lib/async/io/ssl_socket.rb:145:in `block in accept'
2022-11-23T00:12:01.5692897Z 	from D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+3/gems/async-1.30.3/lib/async/task.rb:261:in `block in make_fiber'

ashie · 2022-11-23T01:24:47Z

Thanks for your review!

ashie · 2022-12-07T02:41:15Z

refs:

Investigate "expected loop to be an instance of Coolio::Loop" error socketry/cool.io#50
in_forward emits "expected loop to be an instance of Coolio::Loop" error #703

ashie mentioned this pull request Nov 22, 2022

WIP: Investigate CI failure on Ruby 3.2 #3885

Closed

ashie marked this pull request as ready for review November 22, 2022 09:40

ashie requested a review from cosmo0920 November 22, 2022 09:40

cosmo0920 approved these changes Nov 22, 2022

View reviewed changes

ashie merged commit 79eb77a into master Nov 23, 2022

ashie deleted the fix-3885 branch November 23, 2022 01:24

ashie mentioned this pull request Nov 24, 2022

CI: Fail on Ruby 3.2 preview2 on Windows #3869

Closed

ashie added this to the v1.16.0 milestone Feb 9, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

test_out_forward: Fix a failed test on Ruby 3.2 on Windows #3968

test_out_forward: Fix a failed test on Ruby 3.2 on Windows #3968

ashie commented Nov 22, 2022

cosmo0920 left a comment •

edited

Loading

ashie commented Nov 22, 2022

ashie commented Nov 23, 2022 •

edited

Loading

ashie commented Nov 23, 2022

ashie commented Dec 7, 2022

test_out_forward: Fix a failed test on Ruby 3.2 on Windows #3968

test_out_forward: Fix a failed test on Ruby 3.2 on Windows #3968

Conversation

ashie commented Nov 22, 2022

cosmo0920 left a comment • edited Loading

Choose a reason for hiding this comment

ashie commented Nov 22, 2022

ashie commented Nov 23, 2022 • edited Loading

ashie commented Nov 23, 2022

ashie commented Dec 7, 2022

cosmo0920 left a comment •

edited

Loading

ashie commented Nov 23, 2022 •

edited

Loading