Fix teardown/startup timing issues

DRY the 'teardown' event emission, and make the timing deterministic in
the process.

Previously, the 'teardown' event was emitted after the parent's call to
printResult.  Since printResult calls process(), which can in turn start
another subtest in motion, this caused problems because the next test's
initialization function would fire _before_ the 'teardown' event.

This change shifts a method onto the queue that will emit the teardown
event for the child, so when the call to printResult calls 'process()',
that makes the right thing happen.

Fix #353

lib/test.js

@@ -292,12 +292,9 @@ Test.prototype.processSubtest = function (p) {
     this.debug(' > subtest buffered, finished')
     // finished!  do the thing!
     this.occupied = null
-    if (!p.passing() || !p.silent)
+    if (!p.passing() || !p.silent) {
+      this.queue.unshift(['emitSubTeardown', p])
       this.printResult(p.passing(), p.name, p.options, true)
-    try {
-      p.emit('teardown')
-    } catch (er) {
-      this.threw(er)
     }
   } else {
     this.occupied = p
@@ -308,6 +305,15 @@ Test.prototype.processSubtest = function (p) {
   }
 }
 
+Test.prototype.emitSubTeardown = function (p) {
+  try {
+    p.emit('teardown')
+  } catch (er) {
+    delete p.options.time
+    p.threw(er)
+  }
+}
+
 Test.prototype.writeSubComment = function (p, cb) {
   var comment = '# Subtest'
   if (p.name)
@@ -365,13 +371,9 @@ Test.prototype.onindentedend = function (p, er) {
   this.occupied = null
   this.debug('OIE(%s) b>shift into queue', this.name, this.queue)
   p.options.stack = ''
-  this.printResult(p.passing(), p.name, p.options, true)
 
-  try {
-    p.emit('teardown')
-  } catch (er) {
-    this.threw(er)
-  }
+  this.queue.unshift(['emitSubTeardown', p])
+  this.printResult(p.passing(), p.name, p.options, true)
 
   this.debug('OIE(%s) shifted into queue', this.name, this.queue)
   if (er)

test/test/teardown-throw-autocomplete--buffer.tap

@@ -16,7 +16,7 @@ not ok 1 - child ___/# time=[0-9.]+(ms)?/~~~ {
 
 not ok 2 - child teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-throw-autocomplete.js","line":12},"autoend":true,"source":"throw new Error('child teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-throw-autocomplete.js","line":12},"source":"throw new Error('child teardown')\n","test":"child"}
   ...
 
 1..2

test/test/teardown-throw-autocomplete.tap

@@ -16,7 +16,7 @@ not ok 1 - child ___/# time=[0-9.]+(ms)?/~~~
 
 not ok 2 - child teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-throw-autocomplete.js","line":12},"autoend":true,"source":"throw new Error('child teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-throw-autocomplete.js","line":12},"source":"throw new Error('child teardown')\n","test":"child"}
   ...
 
 1..2

test/test/teardown-timing--bail.tap

@@ -4,12 +4,13 @@ TAP version 13
     1..0
 ok 1 - step1 ___/# time=[0-9.]+(ms)?/~~~
 
-############## step2 startup
 ############## step1 teardown
+############## step2 startup
 # Subtest: step2
     1..0
 ok 2 - step2 ___/# time=[0-9.]+(ms)?/~~~
 
+############## step2 teardown
 ############## step3 startup
 # Subtest: step3
     1..0
@@ -22,7 +23,6 @@ ok 3 - step3 ___/# time=[0-9.]+(ms)?/~~~
 ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~
 
 ############## step4 teardown
-############## step2 teardown
 1..4
 ___/# time=[0-9.]+(ms)?/~~~
 

test/test/teardown-timing-throws--bail--buffer.tap

@@ -25,7 +25,7 @@ ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~ {
 ############## step4 teardown
 not ok 5 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"step1"}
   ...
 
 Bail out! # ############## step1 teardown

test/test/teardown-timing-throws--bail.tap

@@ -4,12 +4,13 @@ TAP version 13
     1..0
 ok 1 - step1 ___/# time=[0-9.]+(ms)?/~~~
 
-############## step2 startup
 ############## step1 teardown
+############## step2 startup
 # Subtest: step2
     1..0
 ok 2 - step2 ___/# time=[0-9.]+(ms)?/~~~
 
+############## step2 teardown
 ############## step3 startup
 # Subtest: step3
     1..0
@@ -24,7 +25,7 @@ ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~
 ############## step4 teardown
 not ok 5 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"step1"}
   ...
 
 Bail out! # ############## step1 teardown

test/test/teardown-timing-throws--buffer.tap

@@ -25,22 +25,22 @@ ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~ {
 ############## step4 teardown
 not ok 5 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"step1"}
   ...
 
 not ok 6 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":16},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":16},"source":"throw new Error('############## step1 teardown')\n","test":"step2"}
   ...
 
 not ok 7 - ############## step3 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":25},"source":"throw new Error('############## step3 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":25},"source":"throw new Error('############## step3 teardown')\n","test":"step3"}
   ...
 
 not ok 8 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":34},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":34},"source":"throw new Error('############## step1 teardown')\n","test":"step4"}
   ...
 
 1..8

test/test/teardown-timing-throws.tap

@@ -4,12 +4,13 @@ TAP version 13
     1..0
 ok 1 - step1 ___/# time=[0-9.]+(ms)?/~~~
 
-############## step2 startup
 ############## step1 teardown
+############## step2 startup
 # Subtest: step2
     1..0
 ok 2 - step2 ___/# time=[0-9.]+(ms)?/~~~
 
+############## step2 teardown
 ############## step3 startup
 # Subtest: step3
     1..0
@@ -24,23 +25,22 @@ ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~
 ############## step4 teardown
 not ok 5 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":7},"source":"throw new Error('############## step1 teardown')\n","test":"step1"}
   ...
 
-not ok 6 - ############## step3 teardown
+not ok 6 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":25},"source":"throw new Error('############## step3 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":16},"source":"throw new Error('############## step1 teardown')\n","test":"step2"}
   ...
 
-not ok 7 - ############## step1 teardown
+not ok 7 - ############## step3 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":34},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":25},"source":"throw new Error('############## step3 teardown')\n","test":"step3"}
   ...
 
-############## step2 teardown
 not ok 8 - ############## step1 teardown
   ---
-  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":16},"source":"throw new Error('############## step1 teardown')\n","test":"TAP"}
+  {"at":{"column":11,"file":"test/test/teardown-timing-throws.js","line":34},"source":"throw new Error('############## step1 teardown')\n","test":"step4"}
   ...
 
 1..8

test/test/teardown-timing.tap

@@ -4,12 +4,13 @@ TAP version 13
     1..0
 ok 1 - step1 ___/# time=[0-9.]+(ms)?/~~~
 
-############## step2 startup
 ############## step1 teardown
+############## step2 startup
 # Subtest: step2
     1..0
 ok 2 - step2 ___/# time=[0-9.]+(ms)?/~~~
 
+############## step2 teardown
 ############## step3 startup
 # Subtest: step3
     1..0
@@ -22,7 +23,6 @@ ok 3 - step3 ___/# time=[0-9.]+(ms)?/~~~
 ok 4 - step4 ___/# time=[0-9.]+(ms)?/~~~
 
 ############## step4 teardown
-############## step2 teardown
 1..4
 ___/# time=[0-9.]+(ms)?/~~~