testing: escapes framing markers

Uses `^[` to escape the framing marker `^V` used to delimit test output. A test
that itself executes a go test binary, or otherwise emits that control
character, previously would corrupt the test2json parse of the enclosing run.

Updates #62728.

Change-Id: I0e8790a05fd7af469cd7ee2e8ccc13786cc372dc
Reviewed-on: https://go-review.googlesource.com/c/go/+/751940
LUCI-TryBot-Result: Go LUCI <golang-scoped@luci-project-accounts.iam.gserviceaccount.com>
Reviewed-by: Michael Matloob <matloob@google.com>
Reviewed-by: Damien Neil <dneil@google.com>

3 files changed, 219 insertions, 27 deletions

diff --git a/src/cmd/internal/test2json/test2json.go b/src/cmd/internal/test2json/test2json.go
index f28051e177..ec392f2dea 100644
--- a/src/cmd/internal/test2json/test2json.go
+++ b/src/cmd/internal/test2json/test2json.go
@@ -53,16 +53,18 @@ func (b textBytes) MarshalText() ([]byte, error) { return b, nil }
 // It implements io.WriteCloser; the caller writes test output in,
 // and the converter writes JSON output to w.
 type Converter struct {
-	w          io.Writer  // JSON output stream
-	pkg        string     // package to name in events
-	mode       Mode       // mode bits
-	start      time.Time  // time converter started
-	testName   string     // name of current test, for output attribution
-	report     []*event   // pending test result reports (nested for subtests)
-	result     string     // overall test result if seen
-	input      lineBuffer // input buffer
-	output     lineBuffer // output buffer
-	needMarker bool       // require ^V marker to introduce test framing line
+	w           io.Writer  // JSON output stream
+	pkg         string     // package to name in events
+	mode        Mode       // mode bits
+	start       time.Time  // time converter started
+	testName    string     // name of current test, for output attribution
+	report      []*event   // pending test result reports (nested for subtests)
+	result      string     // overall test result if seen
+	input       lineBuffer // input buffer
+	output      lineBuffer // output buffer
+	markFraming bool       // require ^V marker to introduce test framing line
+	markEscape  bool       // the next character should be considered to be escaped
+	isFraming   bool       // indicates the output being written is framing
 
 	// failedBuild is set to the package ID of the cause of a build failure,
 	// if that's what caused this test to fail.
@@ -97,6 +99,11 @@ var (
 // Writes on the returned writer are written as JSON to w,
 // with minimal delay.
 //
+// Writes on the returned writer are expected to contain markers. Test framing
+// such as "=== RUN" and friends are expected to be prefixed with ^V (\x22).
+// Other occurrences of this control character (e.g. calls to T.Log) must be
+// escaped with ^[ (\x1b).
+//
 // The writes to w are whole JSON events ending in \n,
 // so that it is safe to run multiple tests writing to multiple converters
 // writing to a single underlying output stream w.
@@ -155,7 +162,10 @@ func (c *Converter) SetFailedBuild(pkgID string) {
 	c.failedBuild = pkgID
 }
 
-const marker = byte(0x16) // ^V
+const (
+	markFraming byte = 'V' &^ '@' // ^V: framing
+	markEscape  byte = '[' &^ '@' // ^[: escape
+)
 
 var (
 	// printed by test on successful run.
@@ -205,11 +215,11 @@ func (c *Converter) handleInputLine(line []byte) {
 		return
 	}
 	sawMarker := false
-	if c.needMarker && line[0] != marker {
+	if c.markFraming && line[0] != markFraming {
 		c.output.write(line)
 		return
 	}
-	if line[0] == marker {
+	if line[0] == markFraming {
 		c.output.flush()
 		sawMarker = true
 		line = line[1:]
@@ -234,8 +244,8 @@ func (c *Converter) handleInputLine(line []byte) {
 	if bytes.Equal(trim, bigPass) || bytes.Equal(trim, bigFail) || bytes.HasPrefix(trim, bigFailErrorPrefix) {
 		c.flushReport(0)
 		c.testName = ""
-		c.needMarker = sawMarker
-		c.output.write(line)
+		c.markFraming = sawMarker
+		c.writeFraming(line)
 		if bytes.Equal(trim, bigPass) {
 			c.result = "pass"
 		} else {
@@ -323,12 +333,12 @@ func (c *Converter) handleInputLine(line []byte) {
 			return
 		}
 		// Flush reports at this indentation level or deeper.
-		c.needMarker = sawMarker
+		c.markFraming = sawMarker
 		c.flushReport(indent)
 		e.Test = name
 		c.testName = name
 		c.report = append(c.report, e)
-		c.output.write(origLine)
+		c.writeFraming(origLine)
 		return
 	}
 	switch action {
@@ -341,7 +351,7 @@ func (c *Converter) handleInputLine(line []byte) {
 	}
 	// === update.
 	// Finish any pending PASS/FAIL reports.
-	c.needMarker = sawMarker
+	c.markFraming = sawMarker
 	c.flushReport(0)
 	c.testName = name
 
@@ -355,16 +365,24 @@ func (c *Converter) handleInputLine(line []byte) {
 		// For a pause, we want to write the pause notification before
 		// delivering the pause event, just so it doesn't look like the test
 		// is generating output immediately after being paused.
-		c.output.write(origLine)
+		c.writeFraming(origLine)
 	}
 	c.writeEvent(e)
 	if action != "pause" {
-		c.output.write(origLine)
+		c.writeFraming(origLine)
 	}
 
 	return
 }
 
+func (c *Converter) writeFraming(line []byte) {
+	// This is a less than ideal way to 'pass' state around, but it's the best
+	// we can do without substantially modifying the line buffer.
+	c.isFraming = true
+	defer func() { c.isFraming = false }()
+	c.output.write(line)
+}
+
 // flushReport flushes all pending PASS/FAIL reports at levels >= depth.
 func (c *Converter) flushReport(depth int) {
 	c.testName = ""
@@ -397,6 +415,28 @@ func (c *Converter) Close() error {
 
 // writeOutputEvent writes a single output event with the given bytes.
 func (c *Converter) writeOutputEvent(out []byte) {
+	// Check for markers.
+	//
+	// An escape mark and the character it escapes may be passed in separate
+	// buffers. We must maintain state between calls to account for this, thus
+	// [Converter.markEscape] is set on one loop iteration and used to skip a
+	// character on the next.
+	for i := 0; i < len(out); i++ {
+		if c.markEscape {
+			c.markEscape = false
+			continue
+		}
+
+		if out[i] == markEscape {
+			// Elide the mark
+			out = append(out[:i], out[i+1:]...)
+			i--
+
+			// Skip the next character
+			c.markEscape = true
+		}
+	}
+
 	c.writeEvent(&event{
 		Action: "output",
 		Output: (*textBytes)(&out),
@@ -435,10 +475,11 @@ func (c *Converter) writeEvent(e *event) {
 // calling part(x) for sections of the line. The line will be split at UTF8 boundaries,
 // and the final call to part for a long line includes the final newline.
 type lineBuffer struct {
-	b    []byte       // buffer
-	mid  bool         // whether we're in the middle of a long line
-	line func([]byte) // line callback
-	part func([]byte) // partial line callback
+	b       []byte       // buffer
+	mid     bool         // whether we're in the middle of a long line
+	line    func([]byte) // line callback
+	part    func([]byte) // partial line callback
+	escaped bool
 }
 
 // write writes b to the buffer.
@@ -452,7 +493,7 @@ func (l *lineBuffer) write(b []byte) {
 		// Process lines in l.b.
 		i := 0
 		for i < len(l.b) {
-			j, w := indexEOL(l.b[i:])
+			j, w := l.indexEOL(l.b[i:])
 			if j < 0 {
 				if !l.mid {
 					if j := bytes.IndexByte(l.b[i:], '\t'); j >= 0 {
@@ -500,12 +541,26 @@ func (l *lineBuffer) write(b []byte) {
 // A line ending is either a \n or the empty string just before a ^V not beginning a line.
 // The output width for \n is 1 (meaning it should be printed)
 // but the output width for ^V is 0 (meaning it should be left to begin the next line).
-func indexEOL(b []byte) (pos, wid int) {
+func (l *lineBuffer) indexEOL(b []byte) (pos, wid int) {
 	for i, c := range b {
+		// Escape has no effect on \n
 		if c == '\n' {
 			return i, 1
 		}
-		if c == marker && i > 0 { // test -v=json emits ^V at start of framing lines
+
+		// Ignore this character if the previous one was ^[
+		if l.escaped {
+			l.escaped = false
+			continue
+		}
+
+		// If this character is `^[`, set the escaped flag and continue
+		if c == markEscape {
+			l.escaped = true
+			continue
+		}
+
+		if c == markFraming && i > 0 { // test -v=json emits ^V at start of framing lines
 			return i, 0
 		}
 	}
diff --git a/src/cmd/internal/test2json/testdata/frameescape.json b/src/cmd/internal/test2json/testdata/frameescape.json
new file mode 100644
index 0000000000..c959089b92
--- /dev/null
+++ b/src/cmd/internal/test2json/testdata/frameescape.json
@@ -0,0 +1,137 @@
+{"Action":"start"}
+{"Action":"run","Test":"TestAscii"}
+{"Action":"output","Test":"TestAscii","Output":"=== RUN   TestAscii\n"}
+{"Action":"run","Test":"TestAscii/Log"}
+{"Action":"output","Test":"TestAscii/Log","Output":"=== RUN   TestAscii/Log\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0000\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0001\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0002\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0003\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0004\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0005\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0006\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0007\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \b\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \t\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"        \n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u000b\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \f\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \r\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u000e\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u000f\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0010\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0011\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0012\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0013\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0014\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0015\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0016\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0017\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0018\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0019\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001a\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001b\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001c\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001d\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001e\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u001f\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8:  \n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: !\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \"\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: #\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: $\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: %\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u0026\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: '\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: (\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: )\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: *\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: +\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ,\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: -\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: .\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: /\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 0\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 1\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 2\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 3\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 4\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 5\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 6\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 7\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 8\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: 9\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: :\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ;\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u003c\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: =\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \u003e\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ?\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: @\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: A\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: B\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: C\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: D\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: E\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: F\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: G\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: H\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: I\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: J\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: K\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: L\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: M\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: N\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: O\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: P\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: Q\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: R\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: S\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: T\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: U\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: V\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: W\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: X\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: Y\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: Z\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: [\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \\\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ]\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ^\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: _\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: `\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: a\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: b\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: c\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: d\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: e\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: f\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: g\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: h\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: i\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: j\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: k\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: l\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: m\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: n\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: o\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: p\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: q\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: r\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: s\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: t\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: u\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: v\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: w\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: x\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: y\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: z\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: {\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: |\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: }\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: ~\n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"    x_test.go:8: \n"}
+{"Action":"output","Test":"TestAscii/Log","Output":"--- PASS: TestAscii/Log (0.00s)\n"}
+{"Action":"pass","Test":"TestAscii/Log"}
+{"Action":"output","Test":"TestAscii","Output":"--- PASS: TestAscii (0.00s)\n"}
diff --git a/src/cmd/internal/test2json/testdata/frameescape.test b/src/cmd/internal/test2json/testdata/frameescape.test
new file mode 100644
index 0000000000..46abdfe1ea
--- /dev/null
+++ b/src/cmd/internal/test2json/testdata/frameescape.test