Use Vagrant::Util::Subprocess for acceptance tests

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

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

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
 

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"$/)

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
+      # Add the options to be passed on
-      # we use pipes so that we can select() on it and block and stream
+      argN << options
-      # 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
 
-      stderr, stderr_writer = IO.pipe
+      # Execute, logging out the stdout/stderr as we get it
-      process.io.stderr = stderr_writer
+      Vagrant::Util::Subprocess.execute(command, *argN) do |type, data|
-      process.duplex = true
+        @logger.debug("#{type}: #{data}") if type == :stdout || type == :stderr
-
+        yield type, data if block_given?
-      @env.each do |k, v|
-        process.environment[k] = v
       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
-

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

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
 

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