Skip to content

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

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

Merged
mihaibuzgau merged 1 commit into from
Oct 6, 2020
Merged

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions .github/workflows/acceptance_tests.yml
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
34 changes: 34 additions & 0 deletions acceptance/tests/custom_facts/long_stderr_with_time_limit.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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
Copy link
Copy Markdown

@gimmyxd gimmyxd Oct 1, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You can make use of ruby here, to generate the needed text, eg:

length = 1000
file_content = <<-EOM
   #!/bin/sh
   long_output=#{"Lorem ipsum dolor sit amet" * length }
   echo 'newfact=value_of_fact'
   1>&2 echo $long_output
   exit 1
EOM

And play with the length to achieve the expected output.

Also i think would be useful to add some description to this scenario and what is this test doing

#!/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

16 changes: 8 additions & 8 deletions acceptance/tests/custom_facts/time_limit_for_execute_command.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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
Expand Down
20 changes: 13 additions & 7 deletions lib/facter/custom_facts/core/execution/base.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand All @@ -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 = +''
Comment on lines +103 to +104
Copy link
Copy Markdown

@gimmyxd gimmyxd Oct 1, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

why not use a simple initialize?

stdout_messages = ''
stderr_messages = ''

Copy link
Copy Markdown
Contributor Author

@oanatmaria oanatmaria Oct 1, 2020 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

they will be treated as frozen strings and this will generate an error later when we try to append the output of the command to these strings

Copy link
Copy Markdown
Contributor

@joshcooper joshcooper Oct 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I've started using String.new to make it clearer that I'm creating a string that isn't frozen

Copy link
Copy Markdown
Contributor Author

@oanatmaria oanatmaria Oct 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

Copy link
Copy Markdown
Contributor Author

@oanatmaria oanatmaria Oct 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Unfortunately i get the following error when i try to use String.new : lib/facter/custom_facts/core/execution/base.rb:104:33: C: Performance/UnfreezeString: Use unary plus to get an unfrozen string literal.

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

@joshcooper joshcooper Oct 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If stdout.read (on line 105) raises then ruby will raise that exception when out_reader.value is called. So it's possible for line 109 to raise something like Errno::EIO, in which case we never call err_reader.value. As a result we may never join that thread and fully read stderr. I don't know if that's going to be an actual problem though...

Copy link
Copy Markdown
Contributor Author

@oanatmaria oanatmaria Oct 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If out_reader.value raises an error, the error message will be logged (if execution is called with on_fail => :raise line 122). If the stdout will raise an error, the resolvers can't get the information needed for facts to be solved, the stderr message can only be used for debug purposes in this case.

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

@joshcooper joshcooper Oct 2, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Can Process.kill raise such as if the child process no longer exists? If so then kill is never called on the readers.

Copy link
Copy Markdown
Contributor Author

@oanatmaria oanatmaria Oct 5, 2020

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

i wrapped the threads kill in an ensure block

end
[output, err]
[stdout_messages, stderr_messages]
end
log_stderr(stderr, command, logger)
rescue StandardError => e
Expand Down
2 changes: 1 addition & 1 deletion lib/facter/resolvers/aix/os_level.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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'

Expand Down
2 changes: 1 addition & 1 deletion spec/facter/resolvers/aix/os_level_spec.rb
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
⚡