Test: TestFluentdCommand often fails on Windows

[daipom]

Describe the bug

Recently, TestFluentdCommand often fails on Windows in CI.

Possible fixes that may have caused:

• TEST: Don't use SIGTERM on Windows #4062
• Fix problem that some system configs are not reflected #4064

On my local, once it starts to fail, it starts to fail a lot.
It seems that sometimes it can't get the standard output of some processes correctly.

Some processes often remain not killed, and those surviving processes seem to be the cause of this problem.

After killing all surviving Ruby processes, all the tests start to succeed again.

I think the reason the tests fail so frequently these days is because the number of tests increases in #4064.

To Reproduce

Repeat the following several times.

$ bundle exec rake test TESTOPTS='-t"TestFluentdCommand"'

Expected behavior

Tests succeed stably.

Your Environment

- Fluentd version: v1.15.3
- Operating system: Windows 10 Home
- Ruby 3.2

Your Configuration

None

Your Error Log

Failure: test: failed to start(TestFluentdCommand::configuration to load plugin which raises unrecoverable error in #start):
  fluentd failed to start, without specified regular expressions:
  2023-03-13 22:27:58 +0900 [info]: init supervisor logger path=nil rotate_age=nil rotate_size=nil
  2023-03-13 22:27:58 +0900 [info]: parsing config file is succeeded path="C:/Users/reang/Documents/work/fluentd/fluentd/test/command/../tmp/commandfluentd/e13266ed6235d47abcf9/crashing_plugin.conf"
  2023-03-13 22:27:58 +0900 [info]: gem 'fluentd' version '1.15.3'
  2023-03-13 22:27:59 +0900 [info]: using configuration file: <ROOT>
    <source>
      @type crashing
      @id dummy
      @label @dummydata
      tag dummy
      dummy {"message":"yay!"}
    </source>
    <label @dummydata>
      <match dummy>
        @type null
        @id blackhole
      </match>
    </label>
  </ROOT>
  2023-03-13 22:27:59 +0900 [info]: starting fluentd-1.15.3 pid=16044 ruby="3.2.0"
  2023-03-13 22:27:59 +0900 [info]: spawn command to main:  cmdline=["C:/Ruby32-x64/bin/ruby.exe", "-rC:/Ruby32-x64/lib/ruby/gems/3.2.0/gems/bundler-2.4.8/lib/bundler/setup", "-Eutf-8", "C:/Users/reang/Documents/work/fluentd/fluentd/bin/fluentd", "-c", "C:/Users/reang/Documents/work/fluentd/fluentd/test/command/../tmp/commandfluentd/e13266ed6235d47abcf9/crashing_plugin.conf", "-p", "C:/Users/reang/Documents/work/fluentd/fluentd/test/command/../tmp/commandfluentd/e13266ed6235d47abcf9/plugin", "--under-supervisor"]
  .
  <false> is not true.
C:/Users/reang/Documents/work/fluentd/fluentd/test/command/test_fluentd.rb:239:in `assert_fluentd_fails_to_start'
C:/Users/reang/Documents/work/fluentd/fluentd/test/command/test_fluentd.rb:578:in `block (2 levels) in <class:TestFluentdCommand>'

Failure: test: runs successfully(TestFluentdCommand::with --conf-encoding):
  execution timeout.
  <"">
  was expected to include:
  <["fluentd worker is now running", "worker=0"]>
C:/Users/reang/Documents/work/fluentd/fluentd/test/command/test_fluentd.rb:192:in `assert_log_matches'
C:/Users/reang/Documents/work/fluentd/fluentd/test/command/test_fluentd.rb:280:in `block (2 levels) in <class:TestFluentdCommand>'
     277: </match>
     278: CONF
     279:       conf_path = create_conf_file('shift_jis.conf', conf, 'shift_jis')
  => 280:       assert_log_matches(create_cmdline(conf_path, '--conf-encoding', 'shift_jis'), "fluentd worker is now running", 'worker=0')
     281:     end
     282:
     283:     test 'failed to run by invalid encoding' do

......

Additional context

No response

[daipom]

I think it can be fixed by making sure the processes are killed.

[daipom]

I found the cause.

fluentd/test/command/test_fluentd.rb

Lines 12 to 13 in 4e24866

	SUPERVISOR_PID_PATTERN = /starting fluentd-[.0-9]+ pid=(\d+)/
	WORKER_PID_PATTERN = /starting fluentd worker pid=(\d+) /

fluentd/test/command/test_fluentd.rb

Lines 153 to 158 in 4e24866

	if SUPERVISOR_PID_PATTERN =~ stdio_buf
	@supervisor_pid = $1.to_i
	end
	stdio_buf.scan(WORKER_PID_PATTERN) do |worker_pid|
	@worker_pids << worker_pid.first.to_i
	end

fluentd/test/command/test_fluentd.rb

Lines 102 to 108 in 4e24866

	process_kill(pid)
	if @supervisor_pid
	process_kill(@supervisor_pid)
	end
	@worker_pids.each do |cpid|
	process_kill(cpid)
	end

So If the test is completed before these matching logs are generated, the process cannot be killed.

[daipom]

fluentd/test/command/test_fluentd.rb

Line 138 in 4e24866

while process_exist?(pid) && !matched

Testing under conditions that match at an early stage can cause this to happen.

[daipom]

fluentd/test/command/test_fluentd.rb

Lines 1188 to 1201 in 4e24866

	data("Trace" => "-vv")
	data("Invalid low level should be treated as Trace level": "-vvv")
	test 'trace' do |option|
	conf = <<CONF
	<source>
	@type sample
	tag test
	</source>
	CONF
	conf_path = create_conf_file('sample.conf', conf)
	assert File.exist?(conf_path)
	assert_log_matches(create_cmdline(conf_path, option),
	"[trace]",)
	end

This test will certainly cause this phenomenon, which is added in #4064.

[daipom]

On my Ubuntu environment, the processes are completely killed.
I don't know why this phenomenon occurs only on Windows...

[daipom]

On my Ubuntu environment, the processes are completely killed. I don't know why this phenomenon occurs only on Windows...

Now I understand the reason.
On Non-Windows, the initial process is the supervisor process, so we don't need @supervisor_pid .
In addition, the supervisor kills its workers when it is killed, so we don't need @worker_pids either.

On the other hand, on Windows, the initial process is different from the supervisor process, so we need @supervisor_pid to kill the supervisor.

[daipom]

I just noticed that the while-loop taking logs finishes when all the pattern_list matches.
So patterns_not_match can only test logs up to that point.

fluentd/test/command/test_fluentd.rb

Lines 138 to 150 in 4e24866

	while process_exist?(pid) && !matched
	readables, _, _ = IO.select([stdout], nil, nil, 1)
	next unless readables
	break if readables.first.eof?
	buf = eager_read(readables.first)
	# puts buf
	stdio_buf << buf
	lines = stdio_buf.split("\n")
	if pattern_list.all?{|ptn| lines.any?{|line| ptn.is_a?(Regexp) ? ptn.match(line) : line.include?(ptn) } }
	matched = true
	end
	end

This means that patterns_not_match on the test like this means nothing..... 😢

fluentd/test/command/test_fluentd.rb

Lines 1170 to 1177 in 4e24866

	test 'info' do
	conf = ""
	conf_path = create_conf_file('empty.conf', conf)
	assert File.exist?(conf_path)
	assert_log_matches(create_cmdline(conf_path),
	"[info]",
	patterns_not_match: ["[debug]"])
	end

[daipom]

Anyway, we have to fix this to ensure that @supervisor_pid can be taken correctly.
This will stable these tests!