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.

Sign up for GitHub

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

Jump to bottom

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

Closed
Watson1978 opened this issue Oct 18, 2024 · 11 comments · Fixed by #4675 or #4686
Closed

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

Watson1978 opened this issue Oct 18, 2024 · 11 comments · Fixed by #4675 or #4686
Assignees
@Watson1978
Labels
CI Test/CI issues

Comments

@Watson1978
Copy link
Contributor

Watson1978 commented Oct 18, 2024 •
edited
Loading

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 Watson1978 added waiting-for-triage bug Something isn't working and removed waiting-for-triage labels Oct 18, 2024
@Watson1978 Watson1978 moved this to To-Do in Fluentd Kanban Oct 18, 2024
@Watson1978 Watson1978 self-assigned this Oct 18, 2024
@Watson1978
Copy link
Contributor Author

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
Copy link
Contributor Author

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 Watson1978 mentioned this issue Oct 20, 2024
Merged
@github-project-automation github-project-automation bot moved this from Work-In-Progress to Done in Fluentd Kanban Oct 21, 2024
@Watson1978
Copy link
Contributor Author

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

@Watson1978 Watson1978 reopened this Oct 22, 2024
@daipom
Copy link
Contributor

daipom commented Oct 22, 2024

😢

@Watson1978
Copy link
Contributor Author

When I added debug print, it just use UDP protocol in test_cat.rb

diff --git a/lib/fluent/plugin_helper/server.rb b/lib/fluent/plugin_helper/server.rb
index eecee5ae..ad487858 100644
--- a/lib/fluent/plugin_helper/server.rb
+++ b/lib/fluent/plugin_helper/server.rb
@@ -122,6 +122,9 @@ module Fluent
       def server_create(title, port, proto: nil, bind: '0.0.0.0', shared: true, socket: nil, backlog: nil, tls_options: nil, max_bytes: nil, flags: 0, **socket_options, &callback)
         proto ||= (@transport_config && @transport_config.protocol == :tls) ? :tls : :tcp

+        puts "\n[debug] server_create: proto: #{proto}, port: #{port}"
+        pp caller.take(20)
+
         raise ArgumentError, "BUG: title must be a symbol" unless title && title.is_a?(Symbol)
         raise ArgumentError, "BUG: port must be an integer" unless port && port.is_a?(Integer)
         raise ArgumentError, "BUG: invalid protocol name" unless PROTOCOLS.include?(proto)
PS C:\src\fluentd> bundle exec rake base_test TEST=test/command/test_cat.rb TESTOPTS="-v --no-show-detail-immediately"
test_file_util.rb for non-root user env. Disable this test on root environment
C:/Ruby30-x64/bin/ruby.exe -w -I"lib;test" -Eascii-8bit:ascii-8bit C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/rake-13.2.1/lib/rake/rake_test_loader.rb "test/command/test_cat.rb" -v --no-show-detail-immediately
C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/serverengine-2.3.2/lib/serverengine/socket_manager_win.rb:141: warning: assigned but unused variable - type
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:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/rake-13.2.1/lib/rake/rake_test_loader
Started
TestFluentCat:
  json:
    test_cat_json:
[debug] server_create: proto: udp, port: 21900
["C:/src/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:78:in `run'",
 "C:/src/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'",
 "C:/src/fluentd/test/command/test_cat.rb:71:in `test_cat_json'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:871:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:566:in `block (2 levels) in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:257:in `run_fixture'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:292:in `run_setup'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:564:in `block in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `catch'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'"]
.: (1.158458)
  msgpack:
    test_cat_secondary_file:
[debug] server_create: proto: udp, port: 5875
["C:/src/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:78:in `run'",
 "C:/src/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'",
 "C:/src/fluentd/test/command/test_cat.rb:88:in `test_cat_secondary_file'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:871:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:566:in `block (2 levels) in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:257:in `run_fixture'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:292:in `run_setup'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:564:in `block in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `catch'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'"]
.: (1.591392)
  send specific event time:
    test_with_event_time:
[debug] server_create: proto: udp, port: 60081
["C:/src/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:78:in `run'",
 "C:/src/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'",
 "C:/src/fluentd/test/command/test_cat.rb:119:in `test_with_event_time'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:871:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:566:in `block (2 levels) in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:257:in `run_fixture'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:292:in `run_setup'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:564:in `block in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `catch'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'"]
.: (1.100989)
    test_without_event_time:
[debug] server_create: proto: udp, port: 17910
["C:/src/fluentd/lib/fluent/plugin/in_forward.rb:183:in `start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:120:in `instance_start'",
 "C:/src/fluentd/lib/fluent/test/driver/base.rb:78:in `run'",
 "C:/src/fluentd/lib/fluent/test/driver/base_owner.rb:130:in `run'",
 "C:/src/fluentd/test/command/test_cat.rb:104:in `test_without_event_time'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:871:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:566:in `block (2 levels) in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:276:in `block in create_fixtures_runner'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:257:in `run_fixture'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/fixture.rb:292:in `run_setup'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:564:in `block in run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `catch'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testcase.rb:563:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:53:in `run'",
 "C:/Ruby30-x64/lib/ruby/gems/3.0.0/gems/test-unit-3.6.2/lib/test/unit/testsuite.rb:124:in `run_test'"]
.: (1.101926)

Finished in 4.955243 seconds.
----------------------------------------------------------------------------------------------------------------------------------
4 tests, 5 assertions, 0 failures, 0 errors, 0 pendings, 0 omissions, 0 notifications
100% passed
----------------------------------------------------------------------------------------------------------------------------------
0.81 tests/s, 1.01 assertions/s

Looks like I got a wrong for test_cat.rb at #4675

@Watson1978 Watson1978 mentioned this issue Oct 28, 2024
Merged
@daipom daipom added CI Test/CI issues and removed bug Something isn't working labels Oct 28, 2024
@daipom
Copy link
Contributor

daipom commented Oct 28, 2024

When I added debug print, it just use UDP protocol in test_cat.rb

No.
It is in_forward_server_udp_heartbeat, not in_forward_server.

fluentd/lib/fluent/plugin/in_forward.rb

Lines 172 to 190 in f493f25

server_create_connection(
:in_forward_server, @port,
bind: @bind,
shared: shared_socket,
resolve_name: @resolve_hostname,
linger_timeout: @linger_timeout,
send_keepalive_packet: @send_keepalive_packet,
backlog: @backlog,
&method(:handle_connection)
)
server_create(:in_forward_server_udp_heartbeat, @port, shared: shared_socket, proto: :udp, bind: @bind, resolve_name: @resolve_hostname, max_bytes: 128) do |data, sock|
log.trace "heartbeat udp data arrived", host: sock.remote_host, port: sock.remote_port, data: data
begin
sock.write HEARTBEAT_UDP_PAYLOAD
rescue Errno::EAGAIN, Errno::EWOULDBLOCK, Errno::EINTR
log.trace "error while heartbeat response", host: sock.remote_host, error: e
end
end

@Watson1978
Copy link
Contributor Author

Watson1978 commented Oct 28, 2024 •
edited
Loading

@daipom Unfortunately, when I run the test, only UDP is used.

So, it need to check that the free UDP port in here at the very least.
If there is a possibility of using TCP, it will need to take care of both.

@daipom
Copy link
Contributor

daipom commented Oct 28, 2024

Unfortunately, when I run the test, only UDP is used.

Although I have not confirmed this yet,

If there is a possibility of using TCP, it will need to take care of both.

it may be a good idea to take care of both!

@daipom
Copy link
Contributor

daipom commented Oct 28, 2024 •
edited
Loading

Unfortunately, when I run the test, only UDP is used.

I can confirm both TCP and UDP are used.

$ lsof -Pni | grep ruby
ruby      589081 daipom    7u  IPv4 3418806      0t0  TCP 127.0.0.1:45691 (LISTEN)
ruby      589081 daipom    8u  IPv4 3418807      0t0  UDP 127.0.0.1:45691

@daipom
Copy link
Contributor

daipom commented Oct 28, 2024

When I added debug print, it just use UDP protocol in test_cat.rb

No. It is in_forward_server_udp_heartbeat, not in_forward_server.

fluentd/lib/fluent/plugin/in_forward.rb

Lines 172 to 190 in f493f25

server_create_connection(
:in_forward_server, @port,
bind: @bind,
shared: shared_socket,
resolve_name: @resolve_hostname,
linger_timeout: @linger_timeout,
send_keepalive_packet: @send_keepalive_packet,
backlog: @backlog,
&method(:handle_connection)
)
server_create(:in_forward_server_udp_heartbeat, @port, shared: shared_socket, proto: :udp, bind: @bind, resolve_name: @resolve_hostname, max_bytes: 128) do |data, sock|
log.trace "heartbeat udp data arrived", host: sock.remote_host, port: sock.remote_port, data: data
begin
sock.write HEARTBEAT_UDP_PAYLOAD
rescue Errno::EAGAIN, Errno::EWOULDBLOCK, Errno::EINTR
log.trace "error while heartbeat response", host: sock.remote_host, error: e
end
end

Please note that in_forward uses two different helper API:

  • server_create_connection
  • server_create

@Watson1978
Copy link
Contributor Author

Thanks

@github-project-automation github-project-automation bot moved this from Work-In-Progress to Done in Fluentd Kanban Oct 28, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@Watson1978 Watson1978

Labels
CI Test/CI issues
Projects
Fluentd Kanban
Status: Done
Milestone
No milestone
2 participants
@Watson1978 @daipom