From 1a1c40b10f4aa68ca218c7e3d3d94ef561b0d996 Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Thu, 31 Oct 2013 16:58:14 -0700 Subject: Remove cruft --- .rspec | 2 +- Gemfile | 5 ---- mixlib-shellout.gemspec | 2 +- test/kitchen/Kitchenfile | 26 ------------------ test/kitchen/cookbooks/Cheffile | 3 -- .../cookbooks/mixlib-shellout_test/README.md | 1 - .../cookbooks/mixlib-shellout_test/metadata.rb | 5 ---- .../mixlib-shellout_test/recipes/default.rb | 32 ---------------------- 8 files changed, 2 insertions(+), 74 deletions(-) delete mode 100644 test/kitchen/Kitchenfile delete mode 100644 test/kitchen/cookbooks/Cheffile delete mode 100644 test/kitchen/cookbooks/mixlib-shellout_test/README.md delete mode 100644 test/kitchen/cookbooks/mixlib-shellout_test/metadata.rb delete mode 100644 test/kitchen/cookbooks/mixlib-shellout_test/recipes/default.rb diff --git a/.rspec b/.rspec index eca491f..7060880 100644 --- a/.rspec +++ b/.rspec @@ -1 +1 @@ --cbfp +-cbfs diff --git a/Gemfile b/Gemfile index b1dd8e0..c1b379a 100644 --- a/Gemfile +++ b/Gemfile @@ -8,8 +8,3 @@ group(:test) do end -group(:kitchen) do - - gem 'test-kitchen', '>= 0.7.0.beta.1' - -end diff --git a/mixlib-shellout.gemspec b/mixlib-shellout.gemspec index cf72f12..f74f15f 100644 --- a/mixlib-shellout.gemspec +++ b/mixlib-shellout.gemspec @@ -13,7 +13,7 @@ Gem::Specification.new do |s| s.homepage = "http://wiki.opscode.com/" - %w(rspec).each { |gem| s.add_development_dependency gem } + s.add_development_dependency "rspec", "~> 2.0" s.bindir = "bin" s.executables = [] diff --git a/test/kitchen/Kitchenfile b/test/kitchen/Kitchenfile deleted file mode 100644 index 60afd49..0000000 --- a/test/kitchen/Kitchenfile +++ /dev/null @@ -1,26 +0,0 @@ -# -# Author:: Seth Chisamore () -# Copyright:: Copyright (c) 2012, Opscode, Inc. () -# -# License:: Apache License, Version 2.0 -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. -# - -integration_test "mixlib-shellout" do - language 'ruby' - runtimes ['1.9.3'] - install 'bundle install --without kitchen' - script 'bundle exec rspec spec' - run_list_extras ['mixlib-shellout_test::default'] -end diff --git a/test/kitchen/cookbooks/Cheffile b/test/kitchen/cookbooks/Cheffile deleted file mode 100644 index 5313b1d..0000000 --- a/test/kitchen/cookbooks/Cheffile +++ /dev/null @@ -1,3 +0,0 @@ -cookbook 'rvm', -:git => 'https://github.com/fnichol/chef-rvm.git', -:ref => 'd6cdb2ab93c421ca6234cbaf5548c914eba4084f' diff --git a/test/kitchen/cookbooks/mixlib-shellout_test/README.md b/test/kitchen/cookbooks/mixlib-shellout_test/README.md deleted file mode 100644 index dd93d60..0000000 --- a/test/kitchen/cookbooks/mixlib-shellout_test/README.md +++ /dev/null @@ -1 +0,0 @@ -This cookbook is used with test-kitchen to test the parent project, mixlib-shellout. diff --git a/test/kitchen/cookbooks/mixlib-shellout_test/metadata.rb b/test/kitchen/cookbooks/mixlib-shellout_test/metadata.rb deleted file mode 100644 index b44b488..0000000 --- a/test/kitchen/cookbooks/mixlib-shellout_test/metadata.rb +++ /dev/null @@ -1,5 +0,0 @@ -maintainer "Opscode, Inc." -maintainer_email "cookbooks@opscode.com" -license "Apache 2.0" -description "This cookbook is used with test-kitchen to test the parent project, mixlib-shellout." -version "1.0.0" diff --git a/test/kitchen/cookbooks/mixlib-shellout_test/recipes/default.rb b/test/kitchen/cookbooks/mixlib-shellout_test/recipes/default.rb deleted file mode 100644 index fa78b4a..0000000 --- a/test/kitchen/cookbooks/mixlib-shellout_test/recipes/default.rb +++ /dev/null @@ -1,32 +0,0 @@ -# -# Cookbook Name:: mixlib-shellout_test -# Recipe:: default -# -# Copyright 2012, Opscode, Inc. -# -# Licensed under the Apache License, Version 2.0 (the "License"); -# you may not use this file except in compliance with the License. -# You may obtain a copy of the License at -# -# http://www.apache.org/licenses/LICENSE-2.0 -# -# Unless required by applicable law or agreed to in writing, software -# distributed under the License is distributed on an "AS IS" BASIS, -# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -# See the License for the specific language governing permissions and -# limitations under the License. -# - -node.set['rvm']['user_installs'] = [ - { 'user' => 'vagrant', - 'default_ruby' => 'ruby-1.9.3-p327', - 'rubies' => ['1.9.3'] - } -] - -node.set['rvm']['gems'] = { - "ruby-1.9.3-p327" => [ - { 'name' => 'bundler' } - ] -} -include_recipe "rvm::user" -- cgit v1.2.1 From c34885b8247a5ff1d2a2ec2b63f41a6f7b0d0b52 Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Thu, 31 Oct 2013 17:05:42 -0700 Subject: Update mock/stubs to avoid deprecations --- spec/mixlib/shellout_spec.rb | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index 084e1b2..9814473 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -1064,8 +1064,8 @@ describe Mixlib::ShellOut do # test for for_fd returning a valid File object, but close # throwing EBADF. it "should not throw an exception if fd.close throws EBADF" do - fd = mock('File') - fd.stub!(:close).at_least(:once).and_raise(Errno::EBADF) + fd = double('File') + fd.stub(:close).at_least(:once).and_raise(Errno::EBADF) File.should_receive(:for_fd).at_least(:once).and_return(fd) shellout = Mixlib::ShellOut.new() shellout.instance_variable_set(:@process_status_pipe, [ 98, 99 ]) -- cgit v1.2.1 From bc60d9b2abfbf64c848ff2e7bdb5cb69d3d84577 Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Fri, 1 Nov 2013 15:16:19 -0700 Subject: Force subprocess to exit after timeout Fixes MIXLIB-16. This issue is particularly prominent when yum/rpm commands go off the deep end repeatedly, but affects any case where a process takes longer than the timeout to complete. --- lib/mixlib/shellout/unix.rb | 69 +++++++++++++++++++++++++++++++++----------- spec/mixlib/shellout_spec.rb | 32 ++++++++++++++++++-- 2 files changed, 82 insertions(+), 19 deletions(-) diff --git a/lib/mixlib/shellout/unix.rb b/lib/mixlib/shellout/unix.rb index d7b8b92..f884832 100644 --- a/lib/mixlib/shellout/unix.rb +++ b/lib/mixlib/shellout/unix.rb @@ -57,42 +57,38 @@ module Mixlib write_to_child_stdin until @status - ready = IO.select(open_pipes, nil, nil, READ_WAIT_TIME) - unless ready + ready_buffers = attempt_buffer_read + unless ready_buffers @execution_time += READ_WAIT_TIME if @execution_time >= timeout && !@result + # kill the bad proccess + reap_errant_child + # read anything it wrote when we killed it + attempt_buffer_read + # raise raise CommandTimeout, "command timed out:\n#{format_for_exception}" end end - if ready && ready.first.include?(child_stdout) - read_stdout_to_buffer - end - if ready && ready.first.include?(child_stderr) - read_stderr_to_buffer - end - unless @status # make one more pass to get the last of the output after the # child process dies - if results = Process.waitpid2(@child_pid, Process::WNOHANG) - @status = results.last + if attempt_reap redo end end end + self rescue Errno::ENOENT # When ENOENT happens, we can be reasonably sure that the child process # is going to exit quickly, so we use the blocking variant of waitpid2 - Process.waitpid2(@child_pid) rescue nil + reap + raise + rescue CommandTimeout raise rescue Exception - # For exceptions other than ENOENT, such as timeout, we can't be sure - # how long the child process will live, so we use the non-blocking - # variant of waitpid2. This can result in zombie processes when the - # child later dies. See MIXLIB-16 for proposed enhancement. - Process.waitpid2(@child_pid, Process::WNOHANG) rescue nil + reap_errant_child raise ensure # no matter what happens, turn the GC back on, and hope whatever busted @@ -239,6 +235,17 @@ module Mixlib child_stdin.close # Kick things off end + def attempt_buffer_read + ready = IO.select(open_pipes, nil, nil, READ_WAIT_TIME) + if ready && ready.first.include?(child_stdout) + read_stdout_to_buffer + end + if ready && ready.first.include?(child_stderr) + read_stderr_to_buffer + end + ready + end + def read_stdout_to_buffer while chunk = child_stdout.read_nonblock(READ_SIZE) @stdout << chunk @@ -299,6 +306,34 @@ module Mixlib end end + def reap_errant_child + return if attempt_reap + Process.kill(:TERM, @child_pid) + sleep 3 + return if attempt_reap + Process.kill(:KILL, @child_pid) + reap + + # Should not hit this but it's possible if something is calling waitall + # in a separate thread. + rescue Errno::ESRCH + nil + end + + def reap + results = Process.waitpid2(@child_pid) + @status = results.last + end + + + def attempt_reap + if results = Process.waitpid2(@child_pid, Process::WNOHANG) + @status = results.last + else + nil + end + end + end end end diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index 9814473..d068dfc 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -825,12 +825,40 @@ describe Mixlib::ShellOut do end context 'with subprocess that takes longer than timeout' do - let(:cmd) { ruby_eval.call('sleep 2') } - let(:options) { { :timeout => 0.1 } } + let(:cmd) do + ruby_eval.call(<<-CODE) + STDOUT.sync = true + trap(:TERM) { puts "got term"; exit!(123) } + sleep 10 + CODE + end + let(:options) { { :timeout => 1 } } it "should raise CommandTimeout" do lambda { executed_cmd }.should raise_error(Mixlib::ShellOut::CommandTimeout) end + + it "should ask the process nicely to exit" do + lambda { executed_cmd }.should raise_error(Mixlib::ShellOut::CommandTimeout) + executed_cmd.stdout.should include("got term") + executed_cmd.exitstatus.should == 123 + end + + context "and the child is unresponsive" do + let(:cmd) do + ruby_eval.call(<<-CODE) + STDOUT.sync = true + trap(:TERM) { puts "nanana cant hear you" } + sleep 10 + CODE + end + + it "should KILL the wayward child" do + lambda { executed_cmd }.should raise_error(Mixlib::ShellOut::CommandTimeout) + executed_cmd.stdout.should include("nanana cant hear you") + executed_cmd.status.termsig.should == 9 + end + end end context 'with subprocess that exceeds buffersize' do -- cgit v1.2.1 From 99001519bb950cda8983a8f270b45845ce349a45 Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Fri, 1 Nov 2013 17:26:25 -0700 Subject: Cleanup control flow in main loop removes some complexity that was introduced with the fix to kill timed-out child processes --- lib/mixlib/shellout/unix.rb | 26 +++++++++++++------------- spec/mixlib/shellout_spec.rb | 16 ++++++++++------ 2 files changed, 23 insertions(+), 19 deletions(-) diff --git a/lib/mixlib/shellout/unix.rb b/lib/mixlib/shellout/unix.rb index f884832..546d3ee 100644 --- a/lib/mixlib/shellout/unix.rb +++ b/lib/mixlib/shellout/unix.rb @@ -38,6 +38,7 @@ module Mixlib # within +timeout+ seconds (default: 600s) def run_command @child_pid = fork_subprocess + @reaped = false configure_parent_process_file_descriptors @@ -70,13 +71,7 @@ module Mixlib end end - unless @status - # make one more pass to get the last of the output after the - # child process dies - if attempt_reap - redo - end - end + attempt_reap end self @@ -85,12 +80,11 @@ module Mixlib # is going to exit quickly, so we use the blocking variant of waitpid2 reap raise - rescue CommandTimeout - raise - rescue Exception - reap_errant_child - raise ensure + reap_errant_child if should_reap? + # make one more pass to get the last of the output after the + # child process dies + attempt_buffer_read # no matter what happens, turn the GC back on, and hope whatever busted # version of ruby we're on doesn't allocate some objects during the next # GC run. @@ -320,14 +314,20 @@ module Mixlib nil end + def should_reap? + # if we fail to fork, no child pid so nothing to reap + @child_pid && !@reaped + end + def reap results = Process.waitpid2(@child_pid) + @reaped = true @status = results.last end - def attempt_reap if results = Process.waitpid2(@child_pid, Process::WNOHANG) + @reaped = true @status = results.last else nil diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index d068dfc..ec2df8f 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -839,9 +839,11 @@ describe Mixlib::ShellOut do end it "should ask the process nicely to exit" do - lambda { executed_cmd }.should raise_error(Mixlib::ShellOut::CommandTimeout) - executed_cmd.stdout.should include("got term") - executed_cmd.exitstatus.should == 123 + # note: let blocks don't correctly memoize if an exception is raised, + # so can't use executed_cmd + lambda { shell_cmd.run_command }.should raise_error(Mixlib::ShellOut::CommandTimeout) + shell_cmd.stdout.should include("got term") + shell_cmd.exitstatus.should == 123 end context "and the child is unresponsive" do @@ -854,9 +856,11 @@ describe Mixlib::ShellOut do end it "should KILL the wayward child" do - lambda { executed_cmd }.should raise_error(Mixlib::ShellOut::CommandTimeout) - executed_cmd.stdout.should include("nanana cant hear you") - executed_cmd.status.termsig.should == 9 + # note: let blocks don't correctly memoize if an exception is raised, + # so can't use executed_cmd + lambda { shell_cmd.run_command}.should raise_error(Mixlib::ShellOut::CommandTimeout) + shell_cmd.stdout.should include("nanana cant hear you") + shell_cmd.status.termsig.should == 9 end end end -- cgit v1.2.1 From 4ff2d130c3d6e68a30340175b5ce0b164ce26220 Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Mon, 4 Nov 2013 08:40:47 -0800 Subject: Add logging about timed-out cmd termination when possible If a logger is configured, send `error` level messages about child process termination for timeout violations. --- lib/mixlib/shellout/unix.rb | 2 ++ spec/mixlib/shellout_spec.rb | 19 +++++++++++++++++++ 2 files changed, 21 insertions(+) diff --git a/lib/mixlib/shellout/unix.rb b/lib/mixlib/shellout/unix.rb index 546d3ee..2ffa5cd 100644 --- a/lib/mixlib/shellout/unix.rb +++ b/lib/mixlib/shellout/unix.rb @@ -302,9 +302,11 @@ module Mixlib def reap_errant_child return if attempt_reap + logger.error("Command execeded allowed execution time, sending TERM") if logger Process.kill(:TERM, @child_pid) sleep 3 return if attempt_reap + logger.error("Command did not exit from TERM, sending KILL") if logger Process.kill(:KILL, @child_pid) reap diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index ec2df8f..fa0ee51 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -1,4 +1,5 @@ require 'spec_helper' +require 'logger' describe Mixlib::ShellOut do let(:shell_cmd) { options ? shell_cmd_with_options : shell_cmd_without_options } @@ -862,6 +863,24 @@ describe Mixlib::ShellOut do shell_cmd.stdout.should include("nanana cant hear you") shell_cmd.status.termsig.should == 9 end + + context "and a logger is configured" do + let(:log_output) { StringIO.new } + let(:logger) { Logger.new(log_output) } + let(:options) { {:timeout => 1, :logger => logger} } + + it "should log messages about killing the child process", :focus do + # note: let blocks don't correctly memoize if an exception is raised, + # so can't use executed_cmd + lambda { shell_cmd.run_command}.should raise_error(Mixlib::ShellOut::CommandTimeout) + shell_cmd.stdout.should include("nanana cant hear you") + shell_cmd.status.termsig.should == 9 + + log_output.string.should include("Command execeded allowed execution time, sending TERM") + log_output.string.should include("Command did not exit from TERM, sending KILL") + end + + end end end -- cgit v1.2.1 From ed33d34fec6ed1bf2400500f4330a7fb4fb871cb Mon Sep 17 00:00:00 2001 From: danielsdeleo Date: Mon, 4 Nov 2013 11:29:30 -0800 Subject: Add termination info to error messages If no logger is configured, we still want to inform the user that the process was killed (and how). --- lib/mixlib/shellout.rb | 2 ++ lib/mixlib/shellout/unix.rb | 4 +++- spec/mixlib/shellout_spec.rb | 2 +- 3 files changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/mixlib/shellout.rb b/lib/mixlib/shellout.rb index a267162..66faa40 100644 --- a/lib/mixlib/shellout.rb +++ b/lib/mixlib/shellout.rb @@ -154,6 +154,7 @@ module Mixlib @environment = DEFAULT_ENVIRONMENT @cwd = nil @valid_exit_codes = [0] + @terminate_reason = nil if command_args.last.is_a?(Hash) parse_options(command_args.pop) @@ -191,6 +192,7 @@ module Mixlib # results when the command exited with an unexpected status. def format_for_exception msg = "" + msg << "#{@terminate_reason}\n" if @terminate_reason msg << "---- Begin output of #{command} ----\n" msg << "STDOUT: #{stdout.strip}\n" msg << "STDERR: #{stderr.strip}\n" diff --git a/lib/mixlib/shellout/unix.rb b/lib/mixlib/shellout/unix.rb index 2ffa5cd..15ead60 100644 --- a/lib/mixlib/shellout/unix.rb +++ b/lib/mixlib/shellout/unix.rb @@ -67,7 +67,7 @@ module Mixlib # read anything it wrote when we killed it attempt_buffer_read # raise - raise CommandTimeout, "command timed out:\n#{format_for_exception}" + raise CommandTimeout, "Command timed out after #{@execution_time.to_i}s:\n#{format_for_exception}" end end @@ -302,10 +302,12 @@ module Mixlib def reap_errant_child return if attempt_reap + @terminate_reason = "Command execeded allowed execution time, killed by TERM signal." logger.error("Command execeded allowed execution time, sending TERM") if logger Process.kill(:TERM, @child_pid) sleep 3 return if attempt_reap + @terminate_reason = "Command execeded allowed execution time, did not respond to TERM. Killed by KILL signal." logger.error("Command did not exit from TERM, sending KILL") if logger Process.kill(:KILL, @child_pid) reap diff --git a/spec/mixlib/shellout_spec.rb b/spec/mixlib/shellout_spec.rb index fa0ee51..71ecfef 100644 --- a/spec/mixlib/shellout_spec.rb +++ b/spec/mixlib/shellout_spec.rb @@ -869,7 +869,7 @@ describe Mixlib::ShellOut do let(:logger) { Logger.new(log_output) } let(:options) { {:timeout => 1, :logger => logger} } - it "should log messages about killing the child process", :focus do + it "should log messages about killing the child process" do # note: let blocks don't correctly memoize if an exception is raised, # so can't use executed_cmd lambda { shell_cmd.run_command}.should raise_error(Mixlib::ShellOut::CommandTimeout) -- cgit v1.2.1