(maint) Avoid deadlock of Facter::Core::Execution.execute

Author: Oana Tanasoiu

.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

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
+

acceptance/tests/custom_facts/time_limit_for_execute_command.rb

@@ -4,15 +4,15 @@
   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
 
   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

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

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'
 

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