From 1a93169adc98b78927d50f6b5040a3dbe40f240f Mon Sep 17 00:00:00 2001 From: Oana Tanasoiu Date: Thu, 1 Oct 2020 14:24:55 +0300 Subject: [PATCH] (maint) Avoid deadlock of Facter::Core::Execution.execute --- .github/workflows/acceptance_tests.yml | 1 + .../long_stderr_with_time_limit.rb | 34 +++++++++++++++++++ .../time_limit_for_execute_command.rb | 16 ++++----- .../custom_facts/core/execution/base.rb | 20 +++++++---- lib/facter/resolvers/aix/os_level.rb | 2 +- spec/facter/resolvers/aix/os_level_spec.rb | 2 +- 6 files changed, 58 insertions(+), 17 deletions(-) create mode 100644 acceptance/tests/custom_facts/long_stderr_with_time_limit.rb diff --git a/.github/workflows/acceptance_tests.yml b/.github/workflows/acceptance_tests.yml index c158501b6d..5481a94d56 100644 --- a/.github/workflows/acceptance_tests.yml +++ b/.github/workflows/acceptance_tests.yml @@ -17,6 +17,7 @@ jobs: os: [windows-2016, windows-2019, ubuntu-16.04, ubuntu-18.04, ubuntu-20.04, macos-10.15] runs-on: ${{ matrix.os }} env: + BEAKER_debug: true FACTER_ROOT: facter SHA: latest RELEASE_STREAM: puppet7 diff --git a/acceptance/tests/custom_facts/long_stderr_with_time_limit.rb b/acceptance/tests/custom_facts/long_stderr_with_time_limit.rb new file mode 100644 index 0000000000..228ff1d9f6 --- /dev/null +++ b/acceptance/tests/custom_facts/long_stderr_with_time_limit.rb @@ -0,0 +1,34 @@ +test_name "Facter::Core::Execution doesn't kill process with long stderr message" do + tag 'risk:high' + + confine :except, :platform => /windows/ + + long_output = "This is a very long error message. " * 4096 + file_content = <<-EOM + #!/bin/sh + echo 'newfact=value_of_fact' + 1>&2 echo #{long_output} + exit 1 + EOM + + + agents.each do |agent| + + external_dir = agent.tmpdir('external_dir') + fact_file = File.join(external_dir, 'test.sh') + create_remote_file(agent, fact_file, file_content) + agent.chmod('+x', fact_file) + + teardown do + agent.rm_rf(external_dir) + end + + step "Facter: should resolve the external fact and print as warning script's stderr message" do + on agent, facter('--external-dir', external_dir, 'newfact') do |facter_output| + assert_match(/value_of_fact/, facter_output.stdout.chomp) + assert_match(/WARN test.sh .*test.sh resulted with the following stderr message: This is a very long error message./, facter_output.stderr.chomp) + end + end + end +end + diff --git a/acceptance/tests/custom_facts/time_limit_for_execute_command.rb b/acceptance/tests/custom_facts/time_limit_for_execute_command.rb index ebb4a3e391..901d8d9397 100644 --- a/acceptance/tests/custom_facts/time_limit_for_execute_command.rb +++ b/acceptance/tests/custom_facts/time_limit_for_execute_command.rb @@ -4,7 +4,7 @@ first_file_content = <<-EOM Facter.add(:foo) do setcode do - Facter::Core::Execution.execute("sleep 3", {:limit => 2}) + Facter::Core::Execution.execute("sleep 3", {:limit => 2, :on_fail => :not_raise}) end end EOM @@ -12,7 +12,7 @@ second_file_content = <<-EOM Facter.add(:custom_fact) do setcode do - Facter::Core::Execution.execute("sleep 2") + Facter::Core::Execution.execute("sleep 2", {:limit => 1}) end end EOM @@ -31,16 +31,16 @@ end step "Facter: Logs that command of the first custom fact had timeout after setted time limit" do - on agent, facter('--custom-dir', custom_dir, 'foo --debug') do |facter_output| + on agent, facter('--custom-dir', custom_dir, 'foo --debug') do |output| assert_match(/DEBUG Facter::Core::Execution.*Timeout encounter after 2s, killing process with pid:/, - facter_output.stderr.chomp) + output.stderr.chomp) end end - step "Facter: Logs that command of the second custom fact had timeout after befault time limit" do - on agent, facter('--custom-dir', custom_dir, 'custom_fact --debug') do |facter_output| - assert_match(/DEBUG Facter::Core::Execution.*Timeout encounter after 1.5s, killing process with pid:/, - facter_output.stderr.chomp) + step "Facter: Logs an error stating that the command of the second custom fact had timeout" do + on(agent, facter('--custom-dir', custom_dir, 'custom_fact --debug'), acceptable_exit_codes: 1) do |output| + assert_match(/ERROR\s+.*Failed while executing '.*sleep.*2': Timeout encounter after 1s, killing process/, + output.stderr.chomp) end end end diff --git a/lib/facter/custom_facts/core/execution/base.rb b/lib/facter/custom_facts/core/execution/base.rb index 450a829792..7cafcbaae1 100644 --- a/lib/facter/custom_facts/core/execution/base.rb +++ b/lib/facter/custom_facts/core/execution/base.rb @@ -90,7 +90,7 @@ def builtin_command?(command) end def execute_command(command, on_fail, logger = nil, time_limit = nil) - time_limit ||= 1.5 + time_limit ||= 300 begin # Set LC_ALL and LANG to force i18n to C for the duration of this exec; # this ensures that any code that parses the @@ -100,18 +100,24 @@ def execute_command(command, on_fail, logger = nil, time_limit = nil) @log.debug("Executing command: #{command}") out, stderr = Open3.popen3(opts, command.to_s) do |_, stdout, stderr, wait_thr| pid = wait_thr.pid - output = +'' - err = +'' + stdout_messages = +'' + stderr_messages = +'' + out_reader = Thread.new { stdout.read } + err_reader = Thread.new { stderr.read } begin Timeout.timeout(time_limit) do - output << stdout.read - err << stderr.read + stdout_messages << out_reader.value + stderr_messages << err_reader.value end rescue Timeout::Error - @log.debug("Timeout encounter after #{time_limit}s, killing process with pid: #{pid}") + message = "Timeout encounter after #{time_limit}s, killing process with pid: #{pid}" Process.kill('KILL', pid) + on_fail == :raise ? (raise StandardError, message) : @log.debug(message) + ensure + out_reader.kill + err_reader.kill end - [output, err] + [stdout_messages, stderr_messages] end log_stderr(stderr, command, logger) rescue StandardError => e diff --git a/lib/facter/resolvers/aix/os_level.rb b/lib/facter/resolvers/aix/os_level.rb index 8a8eb178b7..ae3f8c771d 100644 --- a/lib/facter/resolvers/aix/os_level.rb +++ b/lib/facter/resolvers/aix/os_level.rb @@ -14,7 +14,7 @@ def post_resolve(fact_name) end def read_oslevel(fact_name) - output = Facter::Core::Execution.execute('/usr/bin/oslevel -s', { limit: 2, logger: log }) + output = Facter::Core::Execution.execute('/usr/bin/oslevel -s', logger: log) @fact_list[:build] = output unless output.empty? @fact_list[:kernel] = 'AIX' diff --git a/spec/facter/resolvers/aix/os_level_spec.rb b/spec/facter/resolvers/aix/os_level_spec.rb index 5a4ddf96d5..3c340e32a8 100644 --- a/spec/facter/resolvers/aix/os_level_spec.rb +++ b/spec/facter/resolvers/aix/os_level_spec.rb @@ -8,7 +8,7 @@ before do os_level.instance_variable_set(:@log, log_spy) allow(Facter::Core::Execution).to receive(:execute) - .with('/usr/bin/oslevel -s', { limit: 2, logger: log_spy }) + .with('/usr/bin/oslevel -s', { logger: log_spy }) .and_return(output) end