WIP: Investigate CI failure on Ruby 3.2

[ashie]

Which issue(s) this PR fixes:
Fixes #

What this PR does / why we need it:

Docs Changes:

Release Note:

[ashie]

It seems that it fails to create ack handler thread.

fluentd/lib/fluent/plugin/out_forward.rb

Lines 303 to 306 in c0f1db9

	if @require_ack_response
	overwrite_delayed_commit_timeout
	thread_create(:out_forward_receiving_ack, &method(:ack_reader))
	end

Failed test:

fluentd/test/plugin/test_out_forward.rb

Lines 1324 to 1355 in c0f1db9

	test 'Create connection per send_data' do
	target_input_driver = create_target_input_driver(conf: target_config)
	output_conf = config + %[
	require_ack_response true
	keepalive true
	keepalive_timeout 2
	]
	d = create_driver(output_conf)
	d.instance_start
	begin
	chunk = Fluent::Plugin::Buffer::MemoryChunk.new(Fluent::Plugin::Buffer::Metadata.new(nil, nil, nil))
	mock.proxy(d.instance).socket_create_tcp(TARGET_HOST, @target_port,
	linger_timeout: anything,
	send_timeout: anything,
	recv_timeout: anything,
	connect_timeout: anything) { |sock|
	mock(sock).close.once; sock
	}.twice
	target_input_driver.run(timeout: 15) do
	d.run(shutdown: false) do
	node = d.instance.nodes.first
	2.times do
	node.send_data('test', chunk) rescue nil
	end
	end
	end
	ensure
	d.instance_shutdown
	end
	end

Following test is almost same with above but it's not failed.
The difference is require_ack_response.

fluentd/test/plugin/test_out_forward.rb

Lines 1283 to 1311 in c0f1db9

	test 'Do not create connection per send_data' do
	target_input_driver = create_target_input_driver(conf: target_config)
	output_conf = config + %[
	keepalive true
	keepalive_timeout 2
	]
	d = create_driver(output_conf)
	d.instance_start
	begin
	chunk = Fluent::Plugin::Buffer::MemoryChunk.new(Fluent::Plugin::Buffer::Metadata.new(nil, nil, nil))
	mock.proxy(d.instance).socket_create_tcp(TARGET_HOST, @target_port,
	linger_timeout: anything,
	send_timeout: anything,
	recv_timeout: anything,
	connect_timeout: anything
	) { |sock| mock(sock).close.once; sock }.once
	target_input_driver.run(timeout: 15) do
	d.run(shutdown: false) do
	node = d.instance.nodes.first
	2.times do
	node.send_data('test', chunk) rescue nil
	end
	end
	end
	ensure
	d.instance_shutdown
	end

[ashie]

Oops, it succeeded on current master:
https://github.com/fluent/fluentd/runs/8148387823?check_suite_focus=true

Something fixed in Ruby?

[ashie]

Still failed in this PR. Probably it just a timing issue.

[ashie]

Oops, it succeeded on current master:
https://github.com/fluent/fluentd/runs/8148387823?check_suite_focus=true

Even in this case, following error log is shown:

2022-09-02T02:21:36.3486942Z     with require_ack_response: 
2022-09-02T02:21:37.2666496Z #<Thread:0x000002c8428e1360@event_loop D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:70 run> terminated with exception (report_on_exception is true):
2022-09-02T02:21:37.2667830Z D:/rubyinstaller-head-x64/lib/ruby/gems/3.2.0+2/gems/cool.io-1.7.1/lib/cool.io/listener.rb:65:in `accept': stream closed in another thread (IOError)
2022-09-02T02:21:37.2668548Z 	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-02T02:21:37.2671990Z 	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-02T02:21:37.2673429Z 	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-02T02:21:37.2673959Z 	from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2022-09-02T02:21:37.2674392Z 	from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-09-02T02:21:37.6163337Z       test: Create connection per send_data:		.: (1.267459)

[ashie]

It seems that it fails to create ack handler thread.

I forgot to show the error message:

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 ===============================================================================

[ashie]

Although I tried to fix it at cool.io by 5fddb7e, I found that the comment in this commit is totally wrong. I confirmed that sometimes evloop value at the end of Coolio::Server#on_connection becomes nil even if it was valid loop object at the head of the method. It means a race condition is occurred. It seems that it's caused by d.instance_shutdown, exiting the test driver normally doesn't cause it.

I've created another pull request to fix it: #3968