Show the backtrace of the subprocess and signal it on timeout if there is a subprocess

Author: eregon

spec/mspec/lib/mspec/helpers/ruby_exe.rb

@@ -140,28 +140,44 @@ def ruby_exe(code = :not_given, opts = {})
   expected_status = opts.fetch(:exit_status, 0)
 
   begin
-    platform_is_not :opal do
-      command = ruby_cmd(code, opts)
-      output = `#{command}`
-      status = Process.last_status
-
-      exit_status = if status.exited?
-                      status.exitstatus
-                    elsif status.signaled?
-                      signame = Signal.signame status.termsig
-                      raise "No signal name?" unless signame
-                      :"SIG#{signame}"
-                    else
-                      raise SpecExpectationNotMetError, "#{exit_status.inspect} is neither exited? nor signaled?"
-                    end
-      if exit_status != expected_status
-        formatted_output = output.lines.map { |line| "  #{line}" }.join
-        raise SpecExpectationNotMetError,
-          "Expected exit status is #{expected_status.inspect} but actual is #{exit_status.inspect} for command ruby_exe(#{command.inspect})\nOutput:\n#{formatted_output}"
+    command = ruby_cmd(code, opts)
+
+    # Try to avoid the extra shell for 2>&1
+    # This is notably useful for TimeoutAction which can then signal the ruby subprocess and not the shell
+    popen_options = []
+    if command.end_with?(' 2>&1')
+      command = command[0...-5]
+      popen_options = [{ err: [:child, :out] }]
+    end
+
+    output = IO.popen(command, *popen_options) do |io|
+      pid = io.pid
+      MSpec.subprocesses << pid
+      begin
+        io.read
+      ensure
+        MSpec.subprocesses.delete(pid)
       end
+    end
 
-      output
+    status = Process.last_status
+
+    exit_status = if status.exited?
+                    status.exitstatus
+                  elsif status.signaled?
+                    signame = Signal.signame status.termsig
+                    raise "No signal name?" unless signame
+                    :"SIG#{signame}"
+                  else
+                    raise SpecExpectationNotMetError, "#{exit_status.inspect} is neither exited? nor signaled?"
+                  end
+    if exit_status != expected_status
+      formatted_output = output.lines.map { |line| "  #{line}" }.join
+      raise SpecExpectationNotMetError,
+        "Expected exit status is #{expected_status.inspect} but actual is #{exit_status.inspect} for command ruby_exe(#{command.inspect})\nOutput:\n#{formatted_output}"
     end
+
+    output
   ensure
     saved_env.each { |key, value| ENV[key] = value }
     env.keys.each do |key|

spec/mspec/lib/mspec/runner/actions/timeout.rb

@@ -3,6 +3,8 @@ def initialize(timeout)
     @timeout = timeout
     @queue = Queue.new
     @started = now
+    @fail = false
+    @error_message = "took longer than the configured timeout of #{@timeout}s"
   end
 
   def register
@@ -37,15 +39,25 @@ def start
             elapsed = now - @started
             if elapsed > @timeout
               if @current_state
-                STDERR.puts "\nExample took longer than the configured timeout of #{@timeout}s:"
+                STDERR.puts "\nExample #{@error_message}:"
                 STDERR.puts "#{@current_state.description}"
               else
-                STDERR.puts "\nSome code outside an example took longer than the configured timeout of #{@timeout}s"
+                STDERR.puts "\nSome code outside an example #{@error_message}"
               end
               STDERR.flush
 
               show_backtraces
-              exit 2
+              if MSpec.subprocesses.empty?
+                exit 2
+              else
+                # Do not exit but signal the subprocess so we can get their output
+                MSpec.subprocesses.each do |pid|
+                  Process.kill :SIGTERM, pid
+                end
+                @fail = true
+                @current_state = nil
+                break # stop this thread, will fail in #after
+              end
             end
           end
         end
@@ -65,6 +77,11 @@ def after(state = nil)
     @queue << -> do
       @current_state = nil
     end
+
+    if @fail
+      STDERR.puts "\n\nThe last example #{@error_message}. See above for the subprocess stacktrace."
+      exit 2
+    end
   end
 
   def finish
@@ -73,19 +90,38 @@ def finish
   end
 
   private def show_backtraces
-    if RUBY_ENGINE == 'truffleruby'
-      STDERR.puts 'Java stacktraces:'
-      Process.kill :SIGQUIT, Process.pid
-      sleep 1
-    end
+    java_stacktraces = -> pid {
+      if RUBY_ENGINE == 'truffleruby' || RUBY_ENGINE == 'jruby'
+        STDERR.puts 'Java stacktraces:'
+        Process.kill :SIGQUIT, pid
+        sleep 1
+      end
+    }
 
-    STDERR.puts "\nRuby backtraces:"
-    if defined?(Truffle::Debug.show_backtraces)
-      Truffle::Debug.show_backtraces
+    if MSpec.subprocesses.empty?
+      java_stacktraces.call Process.pid
+
+      STDERR.puts "\nRuby backtraces:"
+      if defined?(Truffle::Debug.show_backtraces)
+        Truffle::Debug.show_backtraces
+      else
+        Thread.list.each do |thread|
+          unless thread == Thread.current
+            STDERR.puts thread.inspect, thread.backtrace, ''
+          end
+        end
+      end
     else
-      Thread.list.each do |thread|
-        unless thread == Thread.current
-          STDERR.puts thread.inspect, thread.backtrace, ''
+      MSpec.subprocesses.each do |pid|
+        STDERR.puts "\nFor subprocess #{pid}"
+        java_stacktraces.call pid
+
+        if RUBY_ENGINE == 'truffleruby'
+          STDERR.puts "\nRuby backtraces:"
+          Process.kill :SIGALRM, pid
+          sleep 1
+        else
+          STDERR.puts "Don't know how to print backtraces of a subprocess on #{RUBY_ENGINE}"
         end
       end
     end

spec/mspec/lib/mspec/runner/mspec.rb

@@ -38,9 +38,10 @@ module MSpec
   @expectation  = nil
   @expectations = false
   @skips = []
+  @subprocesses = []
 
   class << self
-    attr_reader :file, :include, :exclude, :skips
+    attr_reader :file, :include, :exclude, :skips, :subprocesses
     attr_writer :repeat, :randomize
     attr_accessor :formatter
   end