Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CI: Fail on Ruby 3.2 preview2 on Windows #3869

Closed
ashie opened this issue Aug 22, 2022 · 4 comments
Closed

CI: Fail on Ruby 3.2 preview2 on Windows #3869

ashie opened this issue Aug 22, 2022 · 4 comments
Assignees

Comments

@ashie
Copy link
Member

ashie commented Aug 22, 2022

Describe the bug

CI fails with ruby 3.2.0dev (2022-08-22 master 9f3140a42e) [x64-mingw-ucrt] on Windows:
https://github.com/fluent/fluentd/runs/7945647354?check_suite_focus=true

It succeeded with ruby 3.2.0dev (2022-08-19 master 35c794b26d) [x64-mingw-ucrt] on Windows though:
https://github.com/fluent/fluentd/runs/7913475855?check_suite_focus=true

To Reproduce

Run CI with ruby 3.2.0dev (2022-08-22 master 9f3140a42e) [x64-mingw-ucrt] on Windows

Expected behavior

The test should succeed.

Your Environment

- Fluentd version: 1.15.2
- TD Agent version:
- Operating system: Windows
- Kernel version:

Your Configuration

Changes in Ruby: https://github.com/ruby/ruby/compare/35c794b..9f3140a

Your Error Log

2022-08-22T06:26:48.0261596Z   keepalive: 
2022-08-22T06:26:48.7718954Z     test: Do not create connection per send_data:	.: (0.745608)
2022-08-22T06:26:49.0457212Z     test: create timer of purging obsolete sockets:	.: (0.273691)
2022-08-22T06:26:49.0458376Z     with require_ack_response: 
2022-08-22T06:26:49.8032564Z #<Thread:0x000001febc53fe78@event_loop D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:70 run> terminated with exception (report_on_exception is true):
2022-08-22T06:26:49.8044023Z 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-08-22T06:26:49.8044554Z 
2022-08-22T06:26:49.8044905Z       @_read_watcher.attach(loop)
2022-08-22T06:26:49.8045358Z                             ^^^^
2022-08-22T06:26:49.8047633Z 	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-08-22T06:26:49.8052740Z 	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-08-22T06:26:49.8053208Z 	from (eval):7:in `attach'
2022-08-22T06:26:49.8053789Z 	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-08-22T06:26:49.8054504Z 	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-08-22T06:26:49.8055191Z 	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-08-22T06:26:49.8055848Z 	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-08-22T06:26:49.8056338Z 	from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2022-08-22T06:26:49.8056825Z 	from D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'
2022-08-22T06:26:50.2666186Z       test: Create connection per send_data:		E
2022-08-22T06:26:50.2666978Z ===============================================================================
2022-08-22T06:26:50.2670563Z 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-08-22T06:26:50.2672222Z 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-08-22T06:26:50.2673551Z 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-08-22T06:26:50.2675050Z 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-08-22T06:26:50.2675808Z (eval):7:in `attach'
2022-08-22T06:26:50.2676773Z 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-08-22T06:26:50.2677918Z 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-08-22T06:26:50.2679011Z 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-08-22T06:26:50.2680245Z 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-08-22T06:26:50.2681169Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/event_loop.rb:93:in `block in start'
2022-08-22T06:26:50.2682012Z D:/a/fluentd/fluentd/lib/fluent/plugin_helper/thread.rb:78:in `block in thread_create'


### Additional context

_No response_
@ashie ashie self-assigned this Aug 22, 2022
@ashie
Copy link
Member Author

ashie commented Aug 29, 2022

On latest version of Ruby, error tests are increased to more than 100.

https://github.com/fluent/fluentd/runs/8061680028?check_suite_focus=true

2022-08-29T00:26:12.2121065Z [command]D:\rubyinstaller-head-x64\bin\ruby.exe --version
2022-08-29T00:26:12.2310423Z ruby 3.2.0dev (2022-08-29 master 5fcce23ae2) [x64-mingw-ucrt]
2022-08-29T00:50:01.9189975Z -------------------------------------------------------------------------------
2022-08-29T00:50:01.9190646Z 3768 tests, 12942 assertions, 0 failures, 118 errors, 0 pendings, 50 omissions, 0 notifications
2022-08-29T00:50:01.9191096Z 97.6062% passed
2022-08-29T00:50:01.9195298Z -------------------------------------------------------------------------------

Probably most of new errors are caused by same root cause:

e.g.)

2022-08-29T00:35:22.5828727Z ===============================================================================
2022-08-29T00:35:22.5835214Z Error: test: creates lock directory when with_lock is true to exclude operations of other worker process(FileOutputTest::#find_filepath_available): Errno::EACCES: Permission denied @ apply2files - D:/a/fluentd/fluentd/test/tmp/out_file/find_filepath_test/exist_0.log
2022-08-29T00:35:22.5836627Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2300:in `unlink'
2022-08-29T00:35:22.5837361Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2300:in `block in remove_file'
2022-08-29T00:35:22.5838037Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2308:in `platform_support'
2022-08-29T00:35:22.5838710Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2299:in `remove_file'
2022-08-29T00:35:22.5839349Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2288:in `remove'
2022-08-29T00:35:22.5840005Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1425:in `block in remove_entry'
2022-08-29T00:35:22.5840690Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2347:in `block (2 levels) in postorder_traverse'
2022-08-29T00:35:22.5841376Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2351:in `postorder_traverse'
2022-08-29T00:35:22.5842071Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2346:in `block in postorder_traverse'
2022-08-29T00:35:22.5842727Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2345:in `each'
2022-08-29T00:35:22.5843336Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:2345:in `postorder_traverse'
2022-08-29T00:35:22.5844001Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1423:in `remove_entry'
2022-08-29T00:35:22.5844660Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1276:in `block in rm_r'
2022-08-29T00:35:22.5845269Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1272:in `each'
2022-08-29T00:35:22.5845847Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1272:in `rm_r'
2022-08-29T00:35:22.5846470Z D:/rubyinstaller-head-x64/lib/ruby/3.2.0+2/fileutils.rb:1300:in `rm_rf'
2022-08-29T00:35:22.5847056Z D:/a/fluentd/fluentd/test/plugin/test_out_file.rb:993:in `block (2 levels) in <class:FileOutputTest>'
2022-08-29T00:35:22.5847573Z ===============================================================================

@ashie
Copy link
Member Author

ashie commented Sep 1, 2022

On latest version of Ruby, error tests are increased to more than 100.

2022-08-29T00:35:22.5828727Z ===============================================================================
2022-08-29T00:35:22.5835214Z Error: test: creates lock directory when with_lock is true to exclude operations of other worker process(FileOutputTest::#find_filepath_available): Errno::EACCES: Permission denied @ apply2files - D:/a/fluentd/fluentd/test/tmp/out_file/find_filepath_test/exist_0.log

This is because FileUtils.rm_rf in Ruby 3.2 doesn't ignore Errno::EACCES anymore, only Errno::ENOENT is swallowed:
ruby/ruby@983115c

On windows, probably delete pending state causes this error.

@ashie
Copy link
Member Author

ashie commented Nov 24, 2022

The issue originally I reported is fixed in #3968:

2022-08-22T06:26:49.8044023Z 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-08-22T06:26:49.8044554Z 
2022-08-22T06:26:49.8044905Z       @_read_watcher.attach(loop)
2022-08-22T06:26:49.8045358Z                             ^^^^

But recently, still one more test constantly fails on Ruby 3.2 on Windows:
#3968 (comment)

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'

It seems related with #3842 (comment)

It doesn't reproduce on my local environment.

@ashie
Copy link
Member Author

ashie commented Dec 14, 2022

It's not Ruby 3.2 specific, I seems that it randomly occur (or doesn't occur) on all platforms. So I close this issue.

@ashie ashie closed this as completed Dec 14, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
Status: Done
Development

No branches or pull requests

1 participant