Proposal: Cleanly fail testscript from within Defer

[williammartin]

Description

I'm writing scripts that look something like the following:

# Create a repository with a file so it has a default branch
exec gh repo create $ORG/$SCRIPT_NAME-$RANDOM_STRING --add-readme --private

# Defer repo cleanup
defer gh repo delete --yes $ORG/$SCRIPT_NAME-$RANDOM_STRING

...

Where the defer implementation mimics that of Go. I always want defer to run regardless of whether the script fails on a later assertion. I initially implemented it like so:

"defer": func(ts *testscript.TestScript, neg bool, args []string) {
	if neg {
		ts.Fatalf("unsupported: ! defer")
	}

	ts.Defer(func() {
		ts.Check(ts.Exec(args[0], args[1:]...))
	})
}

What I noticed however, was that when the defer failed (e.g. token didn't have privilege to delete the repo), the test fell over like so:

panic: fail now! [recovered]
        panic: fail now!

goroutine 8 [running]:
testing.tRunner.func1.2({0x102853c80, 0x103517bb0})
...

Which isn't very helpful. Looking through the testscript code I can see that each line is run with a defer that recovers a specific panic raised by Fatalf.. However, the functions stacked up by Defer are just deferred to the end of the run method with no regard for whether they might panic..

Noodling around with the code I think it's possible to make this work with a patch like:

diff --git a/testscript/testscript.go b/testscript/testscript.go
index e402483..d4e39cd 100644
--- a/testscript/testscript.go
+++ b/testscript/testscript.go
@@ -561,6 +561,7 @@ func (ts *TestScript) run() {
 	}
 
 	failed := false
+	defer ts.applyScriptUpdates()
 	defer func() {
 		// On a normal exit from the test loop, background processes are cleaned up
 		// before we print PASS. If we return early (e.g., due to a test failure),
@@ -584,8 +585,27 @@ func (ts *TestScript) run() {
 		ts.t.Log(ts.abbrev(ts.log.String()))
 	}()
 	defer func() {
+		// If we reached here but we've failed (probably because ContinueOnError
+		// was set), don't wipe the log and print "PASS".
+		if failed {
+			ts.t.FailNow()
+		}
+
+		// Final phase ended.
+		rewind()
+		markTime()
+		if !ts.stopped {
+			fmt.Fprintf(&ts.log, "PASS\n")
+		}
+	}()
+
+	defer func() {
+		defer catchFailNow(func() {
+			failed = true
+		})
 		ts.deferred()
 	}()
+
 	script := ts.setup()
 
 	// With -v or -testwork, start log with full environment.
@@ -595,7 +615,6 @@ func (ts *TestScript) run() {
 		fmt.Fprintf(&ts.log, "\n")
 		ts.mark = ts.log.Len()
 	}
-	defer ts.applyScriptUpdates()
 
 	// Run script.
 	// See testdata/script/README for documentation of script form.
@@ -655,19 +674,6 @@ func (ts *TestScript) run() {
 	// Moreover, it's relatively common for a process to fail when interrupted.
 	// Once we've reached the end of the script, ignore the status of background commands.
 	ts.waitBackground(false)
-
-	// If we reached here but we've failed (probably because ContinueOnError
-	// was set), don't wipe the log and print "PASS".
-	if failed {
-		ts.t.FailNow()
-	}
-
-	// Final phase ended.
-	rewind()
-	markTime()
-	if !ts.stopped {
-		fmt.Fprintf(&ts.log, "PASS\n")
-	}
 }
 
 func (ts *TestScript) runLine(line string) (runOK bool) {

The intention here is that we defer the previous end-of-run behaviour so that it runs after the user supplied Defers. I think this works but it's definitely at the expense of maintainability. I also moved the defer ts.applyScriptUpdates() to ensure it runs after the previous end-of-run behaviour, though I must admit I'm not sure whether it is important.

Would you be open to something like this? I think that anyone using ts.Fatalf directly or indirectly in a Defer now would be having a bad time, so I'm not sure there's any real breaking change here, though it could be opt in via a new field. Do you have any other suggestions even if they are hacky? I could maybe come up with some horrible cleanup solution in the TestXYZ functions themselves but it's definitely more desirable to keep them in-script.

Cheers!

[williammartin]

This is kind of the best I've got so far:

"defer": func(ts *testscript.TestScript, neg bool, args []string) {
	if neg {
		ts.Fatalf("unsupported: ! defer")
	}

	if tsEnv.skipDefer {
		return
	}

	ts.Defer(func() {
		if err := ts.Exec(args[0], args[1:]...); err != nil {
			deferredStdout := ts.ReadFile("stdout")
			deferredStderr := ts.ReadFile("stderr")

			t.Logf("deferred command failed: %s with [stdout] %s, [stderr] %s", err, deferredStdout, deferredStderr)
			t.Fail()
		}
	})
}

Where I've closed over t from the TestXYZ command.

Which give or take seems to work, but I don't have a clear picture of what's going to fall over if one script errors here and it fails the top level t (not even its own subtest).

[williammartin]

An improvement on the previous approach is to store the T in the env.Values during setup which is specific to the script, and then grab it to use for FailNow. This seems to be captured well enough for testscript to print the log, though honestly I'm a bit surprised it does. In any case it seems to do the trick, even if it's a bit arcane:

In setup:

ts.Values[keyT] = ts.T()

The defer command impl:

"defer": func(ts *testscript.TestScript, neg bool, args []string) {
	if neg {
		ts.Fatalf("unsupported: ! defer")
	}

	tb, ok := ts.Value(keyT).(testing.TB)
	if !ok {
		panic("no testing.TB in testscript environment")
	}

	ts.Defer(func() {
		if err := ts.Exec(args[0], args[1:]...); err != nil {
			tb.FailNow()
		}
	})
},