diff --git a/lib/vagrant/util/subprocess.rb b/lib/vagrant/util/subprocess.rb index b28736154..04501e97e 100644 --- a/lib/vagrant/util/subprocess.rb +++ b/lib/vagrant/util/subprocess.rb @@ -16,11 +16,16 @@ module Vagrant end def initialize(*command) + @options = command.last.is_a?(Hash) ? command.pop : {} @command = command @logger = Log4r::Logger.new("vagrant::util::subprocess") end def execute + # Get the timeout, if we have one + timeout = @options[:timeout] + workdir = @options[:workdir] || Dir.pwd + # Build the ChildProcess @logger.info("Starting process: #{@command.inspect}") process = ChildProcess.build(*@command) @@ -33,9 +38,18 @@ module Vagrant process.io.stderr = stderr_writer process.duplex = true + # Set the environment on the process if we must + if @options[:env] + @options[:env].each do |k, v| + process.environment[k] = v + end + end + # Start the process begin - process.start + Dir.chdir(workdir) do + process.start + end rescue Exception => e if defined?(RUBY_ENGINE) && RUBY_ENGINE == "jruby" if e.is_a?(NativeException) @@ -58,11 +72,17 @@ module Vagrant # Create a dictionary to store all the output we see. io_data = { stdout => "", stderr => "" } + # Record the start time for timeout purposes + start_time = Time.now.to_i + @logger.debug("Selecting on IO") while true - results = IO.select([stdout, stderr], [process.io.stdin], nil, 5) + results = IO.select([stdout, stderr], [process.io.stdin], nil, timeout || 5) readers, writers = results + # Check if we have exceeded our timeout + raise TimeoutExceeded, process.pid if timeout && (Time.now.to_i - start_time) > timeout + # Check the readers to see if they're ready if !readers.empty? readers.each do |r| @@ -98,7 +118,16 @@ module Vagrant end # Wait for the process to end. - process.poll_for_exit(32000) + begin + remaining = (timeout || 32000) - (Time.now.to_i - start_time) + remaining = 0 if remaining < 0 + @logger.debug("Waiting for process to exit. Remaining to timeout: #{remaining}") + + process.poll_for_exit(remaining) + rescue ChildProcess::TimeoutError + raise TimeoutExceeded, process.pid + end + @logger.debug("Exit status: #{process.exit_code}") # Read the final output data, since it is possible we missed a small @@ -171,6 +200,17 @@ module Vagrant # An error which occurs when a process fails to start. class ProcessFailedToStart < StandardError; end + # An error which occurs when the process doesn't end within + # the given timeout. + class TimeoutExceeded < StandardError + attr_reader :pid + + def initialize(pid) + super() + @pid = pid + end + end + # Container class to store the results of executing a subprocess. class Result attr_reader :exit_code diff --git a/test/acceptance/base.rb b/test/acceptance/base.rb index 1f7e170c7..44f04fa79 100644 --- a/test/acceptance/base.rb +++ b/test/acceptance/base.rb @@ -11,6 +11,7 @@ require "acceptance/support/shared/base_context" require "acceptance/support/config" require "acceptance/support/virtualbox" require "acceptance/support/matchers/match_output" +require "acceptance/support/matchers/succeed" # Do not buffer output $stdout.sync = true diff --git a/test/acceptance/box_test.rb b/test/acceptance/box_test.rb index b8b24ff17..803cd47c1 100644 --- a/test/acceptance/box_test.rb +++ b/test/acceptance/box_test.rb @@ -13,7 +13,7 @@ describe "vagrant box" do # Add the box, which we expect to succeed result = execute("vagrant", "box", "add", "foo", box_path("default")) - result.should be_success + result.should succeed # Verify that the box now shows up in the list of available boxes result = execute("vagrant", "box", "list") @@ -22,7 +22,7 @@ describe "vagrant box" do it "gives an error if the file doesn't exist" do result = execute("vagrant", "box", "add", "foo", "/tmp/nope/nope/nope/nonono.box") - result.should_not be_success + result.should_not succeed result.stderr.should match_output(:box_path_doesnt_exist) end @@ -33,7 +33,7 @@ describe "vagrant box" do end result = execute("vagrant", "box", "add", "foo", invalid.to_s) - result.should_not be_success + result.should_not succeed result.stderr.should match_output(:box_invalid) end @@ -49,7 +49,7 @@ describe "vagrant box" do execute("vagrant", "box", "add", "foo", box_path("default")) execute("vagrant", "box", "remove", "foo") result = execute("vagrant", "box", "list") - result.should be_success + result.should succeed result.stdout.should match_output(:no_boxes) end diff --git a/test/acceptance/init_test.rb b/test/acceptance/init_test.rb index 8a05799d2..2afb2f992 100644 --- a/test/acceptance/init_test.rb +++ b/test/acceptance/init_test.rb @@ -8,7 +8,7 @@ describe "vagrant init" do vagrantfile.exist?.should_not be, "Vagrantfile shouldn't exist initially" result = execute("vagrant", "init") - result.should be_success + result.should succeed vagrantfile.exist?.should be, "Vagrantfile should exist" end @@ -16,7 +16,7 @@ describe "vagrant init" do vagrantfile = environment.workdir.join("Vagrantfile") result = execute("vagrant", "init", "foo") - result.should be_success + result.should succeed vagrantfile.read.should match(/config.vm.box = "foo"$/) end @@ -24,7 +24,7 @@ describe "vagrant init" do vagrantfile = environment.workdir.join("Vagrantfile") result = execute("vagrant", "init", "foo", "bar") - result.should be_success + result.should succeed contents = vagrantfile.read contents.should match(/config.vm.box = "foo"$/) diff --git a/test/acceptance/support/isolated_environment.rb b/test/acceptance/support/isolated_environment.rb index c71623b44..a36df8c87 100644 --- a/test/acceptance/support/isolated_environment.rb +++ b/test/acceptance/support/isolated_environment.rb @@ -1,6 +1,8 @@ require "log4r" require "childprocess" +require "vagrant/util/subprocess" + require "acceptance/support/virtualbox" require "support/isolated_environment" @@ -27,96 +29,26 @@ module Acceptance # Any command executed will therefore see our temporary directory # as the home directory. def execute(command, *argN) + # Create the command command = replace_command(command) - # Get the hash options passed to this method + @logger.info("Executing: #{[command].concat(argN).inspect}") + + # Determine the options options = argN.last.is_a?(Hash) ? argN.pop : {} - timeout = options.delete(:timeout) + options = { + :workdir => @workdir, + :env => @env + }.merge(options) - # Build a child process to run this command. For the stdout/stderr - # we use pipes so that we can select() on it and block and stream - # data in as it comes. - @logger.info("Executing: #{command} #{argN.inspect}. Output will stream in...") - process = ChildProcess.build(command, *argN) - stdout, stdout_writer = IO.pipe - process.io.stdout = stdout_writer + # Add the options to be passed on + argN << options - stderr, stderr_writer = IO.pipe - process.io.stderr = stderr_writer - process.duplex = true - - @env.each do |k, v| - process.environment[k] = v + # Execute, logging out the stdout/stderr as we get it + Vagrant::Util::Subprocess.execute(command, *argN) do |type, data| + @logger.debug("#{type}: #{data}") if type == :stdout || type == :stderr + yield type, data if block_given? end - - Dir.chdir(@workdir.to_s) do - process.start - process.io.stdin.sync = true - end - - # Close our side of the pipes, since we're just reading - stdout_writer.close - stderr_writer.close - - # Create a hash to store all the data we see. - io_data = { stdout => "", stderr => "" } - - # Record the start time for timeout purposes - start_time = Time.now.to_i - - @logger.debug("Selecting on IO...") - while true - results = IO.select([stdout, stderr], - [process.io.stdin], nil, timeout || 5) - - # Check if we have exceeded our timeout from waiting on a select() - raise TimeoutExceeded, process.pid if timeout && (Time.now.to_i - start_time) > timeout - - # Check the readers first to see if they're ready - readers = results[0] - if !readers.empty? - begin - readers.each do |r| - data = r.read_nonblock(1024) - io_data[r] += data - io_name = r == stdout ? "stdout" : "stderr" - @logger.debug(data) - yield io_name.to_sym, data if block_given? - end - rescue IO::WaitReadable - # This just means the IO wasn't actually ready and we should - # wait some more. So we just let this pass through. - rescue EOFError - # Process exited, so break out of this while loop - break - end - end - - # Check if the process exited in order to break the loop before - # we try to see if any stdin is ready. - break if process.exited? - - # Check the writers to see if they're ready, and notify any listeners - if !results[1].empty? - yield :stdin, process.io.stdin if block_given? - end - end - - # Continually try to wait for the process to end, but do so asynchronously - # so that we can also check to see if we have exceeded a timeout. - begin - # If a timeout is not set, we set a very large timeout to - # simulate "forever" - @logger.debug("Waiting for process to exit...") - remaining = (timeout || 32000) - (Time.now.to_i - start_time) - remaining = 0 if remaining < 0 - process.poll_for_exit(remaining) - rescue ChildProcess::TimeoutError - raise TimeoutExceeded, process.pid - end - - @logger.debug("Exit status: #{process.exit_code}") - return ExecuteProcess.new(process.exit_code, io_data[stdout], io_data[stderr]) end # Closes the environment, cleans up the temporary directories, etc. @@ -143,7 +75,7 @@ module Acceptance # reason it will simply freeze, although the VM is successfully # "aborted." The timeout gets around this strange behavior. execute("VBoxManage", "controlvm", data[:uuid], "poweroff", :timeout => 5) - rescue TimeoutExceeded => e + rescue Vagrant::Util::Subprocess::TimeoutExceeded => e @logger.info("Failed to poweroff VM '#{data[:uuid]}'. Killing process.") # Kill the process and wait a bit for it to disappear @@ -168,35 +100,4 @@ module Acceptance return command end end - - # This class represents a process which has run via the IsolatedEnvironment. - # This is a readonly structure that can be used to inspect the exit status, - # stdout, stderr, etc. from the process which ran. - class ExecuteProcess - attr_reader :exit_status - attr_reader :stdout - attr_reader :stderr - - def initialize(exit_status, stdout, stderr) - @exit_status = exit_status - @stdout = stdout - @stderr = stderr - end - - def success? - @exit_status == 0 - end - end - - # This exception is raised if the timeout for a process is exceeded. - class TimeoutExceeded < StandardError - attr_reader :pid - - def initialize(pid) - @pid = pid - - super() - end - end end - diff --git a/test/acceptance/support/matchers/succeed.rb b/test/acceptance/support/matchers/succeed.rb new file mode 100644 index 000000000..ac751dc7b --- /dev/null +++ b/test/acceptance/support/matchers/succeed.rb @@ -0,0 +1,14 @@ +# Matcher that verifies that a process succeeds. +RSpec::Matchers.define :succeed do + match do |thing| + thing.exit_code.should == 0 + end + + failure_message_for_should do |actual| + "expected process to succeed. exit code: #{actual.exit_code}" + end + + failure_message_for_should_not do |actual| + "expected process to fail. exit code: #{actual.exit_code}" + end +end diff --git a/test/acceptance/support/shared/base_context.rb b/test/acceptance/support/shared/base_context.rb index 28753a8b7..b511e8766 100644 --- a/test/acceptance/support/shared/base_context.rb +++ b/test/acceptance/support/shared/base_context.rb @@ -45,7 +45,7 @@ shared_context "acceptance" do # exit status was successful. def assert_execute(*args, &block) result = execute(*args, &block) - assert(result.success?, "expected '#{args.join(" ")}' to succeed") + assert(result.exit_code == 0, "expected '#{args.join(" ")}' to succeed") result end diff --git a/test/acceptance/support/shared/command_examples.rb b/test/acceptance/support/shared/command_examples.rb index e3d0f7551..be26b6062 100644 --- a/test/acceptance/support/shared/command_examples.rb +++ b/test/acceptance/support/shared/command_examples.rb @@ -9,7 +9,7 @@ shared_examples "a command that requires a Vagrantfile" do |*args| it "fails if no Vagrantfile is found" do result = execute(*command) - result.should_not be_success + result.should_not succeed result.stderr.should match_output(:no_vagrantfile) end end @@ -27,7 +27,7 @@ shared_examples "a command that requires a virtual machine" do |*args| assert_execute("vagrant", "init") result = execute(*command) - result.should_not be_success + result.should_not succeed result.stderr.should match_output(:error_vm_must_be_created) end end