search

fluent / fluentd

Fluentd: Unified Logging Layer (project under CNCF)
https://www.fluentd.org
Apache License 2.0
12.89k stars 1.34k forks source link

CI: Fails with "Errno::EACCES: Permission denied - bind(2)" on Windows #4674

Open Watson1978 opened 1 week ago

Watson1978 commented 1 week ago

Describe the bug

Sometimes, CI fails with "Errno::EACCES: Permission denied - bind(2)" on Windows platform, like

 1) Error: test: skip_invalid_event[tcp](ForwardInputTest::packed forward): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53297
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/plugin/test_in_forward.rb:491:in `block (2 levels) in <class:ForwardInputTest>'

28) Error: test: Create new connection per send_data(ForwardOutputTest): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53356
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/plugin/test_out_forward.rb:1260:in `block in <class:ForwardOutputTest>'

To Reproduce

Run Windows platform lane in CI.

Expected behavior

Succeeded without any failures

Your Environment

- Fluentd version:
- Package version:
- Operating system:
- Kernel version:

Your Configuration

none

Your Error Log

none

Additional context

No response

Watson1978 commented 1 week ago

Hmm, When I run the test on Windows, it creates a lot of sockets in TIME_WAIT state. Until the TIME_WAIT state is released, the port in use on that socket is not available. The tests may be using that port by mistake.

PS C:\src\fluentd> bundle exec rake base_test TEST=test\plugin\test_in_syslog.rb TESTOPTS="-v --no-show-detail-immediately"
test_file_util.rb for non-root user env. Disable this test on root environment
C:/Ruby31-x64/bin/ruby.exe -w -I"lib;test" -Eascii-8bit:ascii-8bit C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/rake-13.2.1/lib/rake/rake_test_loader.rb "test\plugin\test_in_syslog.rb" -v --no-show-detail-immediately
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/serverengine-2.3.2/lib/serverengine/socket_manager_win.rb:141: warning: assigned but unused variable - type
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/async-2.17.0/lib/async/task.rb:290: warning: assigned but unused variable - error
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/async-pool-0.10.1/lib/async/pool/controller.rb:336: warning: assigned but unused variable - error
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/async-http-0.82.1/lib/async/http/protocol/http1/server.rb:55: warning: assigned but unused variable - error
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/async-http-0.82.1/lib/async/http/protocol/http2/connection.rb:98: warning: assigned but unused variable - ignored_error
C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/protocol-http-0.41.0/lib/protocol/http/body/stream.rb:233: warning: assigned but unused variable - buffer
C:/src/fluentd/lib/fluent/plugin_helper.rb:46: warning: method redefined; discarding old inherited
C:/src/fluentd/lib/fluent/plugin_helper.rb:46: warning: previous definition of inherited was here
Loaded suite C:/Ruby31-x64/lib/ruby/gems/3.1.0/gems/rake-13.2.1/lib/rake/rake_test_loader
Started
SyslogInputTest:
  test_configure[ipv4]:                                                                                                 .: (0.038125)
  test_configure[ipv6]:                                                                                                 .: (0.002772)
  test_configure_protocol[Use protocol_type]:                                                                           .: (0.002148)
  test_configure_protocol[Use transport]:                                                                               .: (0.001984)
  test_configure_protocol[Use transport and protocol]:                                                                  .: (0.002274)
  test_emit_rfc5452:                                                                                                    .: (1.113086)
  test_emit_unmatched_lines:                                                                                            .: (1.107398)
  test_emit_unmatched_lines_with_address:                                                                               .: (1.117929)
  test_emit_unmatched_lines_with_hostname:                                                                              .: (1.116825)
  test_msg_size:                                                                                                        .: (1.118479)
  test_msg_size_udp_for_large_msg:                                                                                      .: (1.120173)
  test_msg_size_with_facility_key:                                                                                      .: (1.125206)
  test_msg_size_with_include_source_host:                                                                               .: (1.103977)
  test_msg_size_with_json_format:                                                                                       .: (1.119902)
  test_msg_size_with_same_tcp_connection:                                                                               .: (1.121510)
  test_msg_size_with_severity_key[severity_key]:                                                                        .: (1.124568)
  test_msg_size_with_severity_key[priority_key]:                                                                        .: (1.110733)
  test_msg_size_with_source_address_key:                                                                                .: (1.118415)
  test_msg_size_with_source_hostname_key:                                                                               .: (1.117970)
  test_msg_size_with_tcp:                                                                                               .: (1.114958)
  test_respect_protocol_type_than_transport:                                                                            .: (1.118102)
  test_send_keepalive_packet_can_be_enabled:                                                                            .: (0.578499)
  test_send_keepalive_packet_can_not_be_enabled_for_udp:                                                                .: (0.002483)
  test_send_keepalive_packet_is_disabled_by_default:                                                                    .: (0.002141)
  test_time_format[ipv4]:                                                                                               .: (1.111531)
  test_time_format[ipv6]:                                                                                               .: (1.121918)
  octet counting frame:
    test_msg_size_with_same_tcp_connection:                                                                             .: (1.103448)
    test_msg_size_with_tcp:                                                                                             .: (1.107635)
  source_hostname_key and source_address_key features:
    test: resolve_hostname must be true with source_hostname_key:                                                       .: (0.002255)
    test_configure_resolve_hostname[resolve_hostname]:                                                                  .: (0.001720)
    test_configure_resolve_hostname[source_hostname_key]:                                                               .: (0.001566)

Finished in 22.9573934 seconds.
-------------------------------------------------------------------------------------------------------------------------------------------
31 tests, 138 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
100% passed
-------------------------------------------------------------------------------------------------------------------------------------------
1.35 tests/s, 6.01 assertions/s
PS C:\src\fluentd> netstat -aon | grep TIME_WAIT
  TCP         127.0.0.1:55680        127.0.0.1:55679        TIME_WAIT       0
  TCP         127.0.0.1:55682        127.0.0.1:55681        TIME_WAIT       0
  TCP         127.0.0.1:55684        127.0.0.1:55683        TIME_WAIT       0
  TCP         127.0.0.1:55697        127.0.0.1:55696        TIME_WAIT       0
  TCP         127.0.0.1:55707        127.0.0.1:55706        TIME_WAIT       0
  TCP         127.0.0.1:55710        127.0.0.1:55709        TIME_WAIT       0
  TCP         127.0.0.1:55718        127.0.0.1:55717        TIME_WAIT       0
  TCP         127.0.0.1:55721        127.0.0.1:55720        TIME_WAIT       0
  TCP         127.0.0.1:55725        127.0.0.1:55724        TIME_WAIT       0
  TCP         127.0.0.1:55728        127.0.0.1:55727        TIME_WAIT       0
  TCP         127.0.0.1:55731        127.0.0.1:55730        TIME_WAIT       0
  TCP         127.0.0.1:55734        127.0.0.1:55733        TIME_WAIT       0
  TCP         127.0.0.1:55737        127.0.0.1:55736        TIME_WAIT       0
  TCP         127.0.0.1:55738        127.0.0.1:55735        TIME_WAIT       0
  TCP         127.0.0.1:55741        127.0.0.1:55740        TIME_WAIT       0
  TCP         127.0.0.1:55745        127.0.0.1:55744        TIME_WAIT       0
  TCP         127.0.0.1:55748        127.0.0.1:55747        TIME_WAIT       0
  TCP         127.0.0.1:55752        127.0.0.1:55751        TIME_WAIT       0
  TCP         127.0.0.1:55755        127.0.0.1:55754        TIME_WAIT       0
  TCP         127.0.0.1:55756        127.0.0.1:55753        TIME_WAIT       0
  TCP         127.0.0.1:55757        127.0.0.1:55753        TIME_WAIT       0
  TCP         127.0.0.1:55763        127.0.0.1:55762        TIME_WAIT       0
  TCP         127.0.0.1:55766        127.0.0.1:55765        TIME_WAIT       0
  TCP         127.0.0.1:55772        127.0.0.1:55771        TIME_WAIT       0
  TCP         127.0.0.1:55776        127.0.0.1:55775        TIME_WAIT       0
  TCP         127.0.0.1:55779        127.0.0.1:55778        TIME_WAIT       0
  TCP         127.0.0.1:55780        127.0.0.1:55777        TIME_WAIT       0
  TCP         127.0.0.1:55786        127.0.0.1:55785        TIME_WAIT       0
  TCP         127.0.0.1:55787        127.0.0.1:55784        TIME_WAIT       0
  TCP         127.0.0.1:55788        127.0.0.1:55784        TIME_WAIT       0
  TCP         192.168.10.13:55610    117.18.232.200:443     TIME_WAIT       0
  TCP         192.168.10.13:55625    52.168.117.175:443     TIME_WAIT       0
  TCP         192.168.10.13:55643    172.65.225.25:443      TIME_WAIT       0
  TCP         192.168.10.13:55698    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55699    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55700    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55702    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55703    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55704    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55711    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55712    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55713    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55758    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55759    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55760    192.168.10.1:53        TIME_WAIT       0
  TCP         192.168.10.13:55781    20.189.173.25:443      TIME_WAIT       0
Watson1978 commented 1 week ago

The port used in the test is determined by the unused_port method. However, since the protocols are not properly specified, they wll look at free TCP ports. https://github.com/search?q=repo%3Afluent%2Ffluentd%20unused_port&type=code

At least, looks for me that it need to specify protocols properly in some cases.

Watson1978 commented 4 days ago

Still showing similar errors...

1) Error: test_cat_json(TestFluentCat::json): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53311
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/command/test_cat.rb:71:in `test_cat_json'
     68:   sub_test_case "json" do
     69:     def test_cat_json
     70:       d = create_driver
  => 71:       d.run(expect_records: 1) do
     72:         Open3.pipeline_w("#{ServerEngine.ruby_bin_path} #{FLUENT_CAT_COMMAND} --port #{@port} json") do |stdin|
     73:           stdin.puts('{"key":"value"}')
     74:           stdin.close

2) Error: test_cat_secondary_file(TestFluentCat::msgpack): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53313
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/command/test_cat.rb:88:in `test_cat_secondary_file'
     85:       d = create_secondary_driver
     86:       path = d.instance.write(@chunk)
     87:       d = create_driver
  => 88:       d.run(expect_records: 1) do
     89:         Open3.pipeline_w("#{ServerEngine.ruby_bin_path} #{FLUENT_CAT_COMMAND} --port #{@port} --format msgpack secondary") do |stdin|
     90:           stdin.write(File.read(path))
     91:           stdin.close

3) Error: test_with_event_time(TestFluentCat::send specific event time): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53315
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/command/test_cat.rb:119:in `test_with_event_time'
     116:     def test_with_event_time
     117:       event_time = "2021-01-02 13:14:15.0+00:00"
     118:       d = create_driver
  => 119:       d.run(expect_records: 1) do
     120:         Open3.pipeline_w("#{ServerEngine.ruby_bin_path} #{FLUENT_CAT_COMMAND} --port #{@port} --event-time '#{event_time}' tag") do |stdin|
     121:           stdin.puts('{"key":"value"}')
     122:           stdin.close

4) Error: test_without_event_time(TestFluentCat::send specific event time): Errno::EACCES: Permission denied - bind(2) for 127.0.0.1:53317
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
C:/hostedtoolcache/windows/Ruby/3.1.6/x64/lib/ruby/3.1.0/socket.rb:179:in `bind'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:390:in `server_create_udp_socket'
D:/a/fluentd/fluentd/lib/fluent/plugin_helper/server.rb:174:in `server_create'
D:/a/fluentd/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base.rb:78:in `run'
D:/a/fluentd/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'
D:/a/fluentd/fluentd/test/command/test_cat.rb:104:in `test_without_event_time'
     101:     def test_without_event_time
     102:       event_time = Fluent::EventTime.now
     103:       d = create_driver
  => 104:       d.run(expect_records: 1) do
     105:         Open3.pipeline_w("#{ServerEngine.ruby_bin_path} #{FLUENT_CAT_COMMAND} --port #{@port} tag") do |stdin|
     106:           stdin.puts('{"key":"value"}')
     107:           stdin.close

https://github.com/fluent/fluentd/actions/runs/11450864554/job/31859109136?pr=4681

daipom commented 4 days ago

:cry: