test2json.go

     1  // Copyright 2017 The Go Authors. All rights reserved.
     2  // Use of this source code is governed by a BSD-style
     3  // license that can be found in the LICENSE file.
     4  
     5  // Package test2json implements conversion of test binary output to JSON.
     6  // It is used by cmd/test2json and cmd/go.
     7  //
     8  // See the cmd/test2json documentation for details of the JSON encoding.
     9  package test2json
    10  
    11  import (
    12  	"bytes"
    13  	"encoding/json"
    14  	"fmt"
    15  	"io"
    16  	"strconv"
    17  	"strings"
    18  	"time"
    19  	"unicode"
    20  	"unicode/utf8"
    21  )
    22  
    23  // Mode controls details of the conversion.
    24  type Mode int
    25  
    26  const (
    27  	Timestamp Mode = 1 << iota // include Time in events
    28  )
    29  
    30  // event is the JSON struct we emit.
    31  type event struct {
    32  	Time        *time.Time `json:",omitempty"`
    33  	Action      string
    34  	Package     string     `json:",omitempty"`
    35  	Test        string     `json:",omitempty"`
    36  	Elapsed     *float64   `json:",omitempty"`
    37  	Output      *textBytes `json:",omitempty"`
    38  	FailedBuild string     `json:",omitempty"`
    39  	Key         string     `json:",omitempty"`
    40  	Value       string     `json:",omitempty"`
    41  }
    42  
    43  // textBytes is a hack to get JSON to emit a []byte as a string
    44  // without actually copying it to a string.
    45  // It implements encoding.TextMarshaler, which returns its text form as a []byte,
    46  // and then json encodes that text form as a string (which was our goal).
    47  type textBytes []byte
    48  
    49  func (b textBytes) MarshalText() ([]byte, error) { return b, nil }
    50  
    51  // A Converter holds the state of a test-to-JSON conversion.
    52  // It implements io.WriteCloser; the caller writes test output in,
    53  // and the converter writes JSON output to w.
    54  type Converter struct {
    55  	w          io.Writer  // JSON output stream
    56  	pkg        string     // package to name in events
    57  	mode       Mode       // mode bits
    58  	start      time.Time  // time converter started
    59  	testName   string     // name of current test, for output attribution
    60  	report     []*event   // pending test result reports (nested for subtests)
    61  	result     string     // overall test result if seen
    62  	input      lineBuffer // input buffer
    63  	output     lineBuffer // output buffer
    64  	needMarker bool       // require ^V marker to introduce test framing line
    65  
    66  	// failedBuild is set to the package ID of the cause of a build failure,
    67  	// if that's what caused this test to fail.
    68  	failedBuild string
    69  }
    70  
    71  // inBuffer and outBuffer are the input and output buffer sizes.
    72  // They're variables so that they can be reduced during testing.
    73  //
    74  // The input buffer needs to be able to hold any single test
    75  // directive line we want to recognize, like:
    76  //
    77  //	<many spaces> --- PASS: very/nested/s/u/b/t/e/s/t
    78  //
    79  // If anyone reports a test directive line > 4k not working, it will
    80  // be defensible to suggest they restructure their test or test names.
    81  //
    82  // The output buffer must be >= utf8.UTFMax, so that it can
    83  // accumulate any single UTF8 sequence. Lines that fit entirely
    84  // within the output buffer are emitted in single output events.
    85  // Otherwise they are split into multiple events.
    86  // The output buffer size therefore limits the size of the encoding
    87  // of a single JSON output event. 1k seems like a reasonable balance
    88  // between wanting to avoid splitting an output line and not wanting to
    89  // generate enormous output events.
    90  var (
    91  	inBuffer  = 4096
    92  	outBuffer = 1024
    93  )
    94  
    95  // NewConverter returns a "test to json" converter.
    96  // Writes on the returned writer are written as JSON to w,
    97  // with minimal delay.
    98  //
    99  // The writes to w are whole JSON events ending in \n,
   100  // so that it is safe to run multiple tests writing to multiple converters
   101  // writing to a single underlying output stream w.
   102  // As long as the underlying output w can handle concurrent writes
   103  // from multiple goroutines, the result will be a JSON stream
   104  // describing the relative ordering of execution in all the concurrent tests.
   105  //
   106  // The mode flag adjusts the behavior of the converter.
   107  // Passing ModeTime includes event timestamps and elapsed times.
   108  //
   109  // The pkg string, if present, specifies the import path to
   110  // report in the JSON stream.
   111  func NewConverter(w io.Writer, pkg string, mode Mode) *Converter {
   112  	c := new(Converter)
   113  	*c = Converter{
   114  		w:     w,
   115  		pkg:   pkg,
   116  		mode:  mode,
   117  		start: time.Now(),
   118  		input: lineBuffer{
   119  			b:    make([]byte, 0, inBuffer),
   120  			line: c.handleInputLine,
   121  			part: c.output.write,
   122  		},
   123  		output: lineBuffer{
   124  			b:    make([]byte, 0, outBuffer),
   125  			line: c.writeOutputEvent,
   126  			part: c.writeOutputEvent,
   127  		},
   128  	}
   129  	c.writeEvent(&event{Action: "start"})
   130  	return c
   131  }
   132  
   133  // Write writes the test input to the converter.
   134  func (c *Converter) Write(b []byte) (int, error) {
   135  	c.input.write(b)
   136  	return len(b), nil
   137  }
   138  
   139  // Exited marks the test process as having exited with the given error.
   140  func (c *Converter) Exited(err error) {
   141  	if err == nil {
   142  		if c.result != "skip" {
   143  			c.result = "pass"
   144  		}
   145  	} else {
   146  		c.result = "fail"
   147  	}
   148  }
   149  
   150  // SetFailedBuild sets the package ID that is the root cause of a build failure
   151  // for this test. This will be reported in the final "fail" event's FailedBuild
   152  // field.
   153  func (c *Converter) SetFailedBuild(pkgID string) {
   154  	c.failedBuild = pkgID
   155  }
   156  
   157  const marker = byte(0x16) // ^V
   158  
   159  var (
   160  	// printed by test on successful run.
   161  	bigPass = []byte("PASS")
   162  
   163  	// printed by test after a normal test failure.
   164  	bigFail = []byte("FAIL")
   165  
   166  	// printed by 'go test' along with an error if the test binary terminates
   167  	// with an error.
   168  	bigFailErrorPrefix = []byte("FAIL\t")
   169  
   170  	// an === NAME line with no test name, if trailing spaces are deleted
   171  	emptyName     = []byte("=== NAME")
   172  	emptyNameLine = []byte("=== NAME  \n")
   173  
   174  	updates = [][]byte{
   175  		[]byte("=== RUN   "),
   176  		[]byte("=== PAUSE "),
   177  		[]byte("=== CONT  "),
   178  		[]byte("=== NAME  "),
   179  		[]byte("=== PASS  "),
   180  		[]byte("=== FAIL  "),
   181  		[]byte("=== SKIP  "),
   182  		[]byte("=== ATTR  "),
   183  	}
   184  
   185  	reports = [][]byte{
   186  		[]byte("--- PASS: "),
   187  		[]byte("--- FAIL: "),
   188  		[]byte("--- SKIP: "),
   189  		[]byte("--- BENCH: "),
   190  	}
   191  
   192  	fourSpace = []byte("    ")
   193  
   194  	skipLinePrefix = []byte("?   \t")
   195  	skipLineSuffix = []byte("\t[no test files]")
   196  )
   197  
   198  // handleInputLine handles a single whole test output line.
   199  // It must write the line to c.output but may choose to do so
   200  // before or after emitting other events.
   201  func (c *Converter) handleInputLine(line []byte) {
   202  	if len(line) == 0 {
   203  		return
   204  	}
   205  	sawMarker := false
   206  	if c.needMarker && line[0] != marker {
   207  		c.output.write(line)
   208  		return
   209  	}
   210  	if line[0] == marker {
   211  		c.output.flush()
   212  		sawMarker = true
   213  		line = line[1:]
   214  	}
   215  
   216  	// Trim is line without \n or \r\n.
   217  	trim := line
   218  	if len(trim) > 0 && trim[len(trim)-1] == '\n' {
   219  		trim = trim[:len(trim)-1]
   220  		if len(trim) > 0 && trim[len(trim)-1] == '\r' {
   221  			trim = trim[:len(trim)-1]
   222  		}
   223  	}
   224  
   225  	// === CONT followed by an empty test name can lose its trailing spaces.
   226  	if bytes.Equal(trim, emptyName) {
   227  		line = emptyNameLine
   228  		trim = line[:len(line)-1]
   229  	}
   230  
   231  	// Final PASS or FAIL.
   232  	if bytes.Equal(trim, bigPass) || bytes.Equal(trim, bigFail) || bytes.HasPrefix(trim, bigFailErrorPrefix) {
   233  		c.flushReport(0)
   234  		c.testName = ""
   235  		c.needMarker = sawMarker
   236  		c.output.write(line)
   237  		if bytes.Equal(trim, bigPass) {
   238  			c.result = "pass"
   239  		} else {
   240  			c.result = "fail"
   241  		}
   242  		return
   243  	}
   244  
   245  	// Special case for entirely skipped test binary: "?   \tpkgname\t[no test files]\n" is only line.
   246  	// Report it as plain output but remember to say skip in the final summary.
   247  	if bytes.HasPrefix(line, skipLinePrefix) && bytes.HasSuffix(trim, skipLineSuffix) && len(c.report) == 0 {
   248  		c.result = "skip"
   249  	}
   250  
   251  	// "=== RUN   "
   252  	// "=== PAUSE "
   253  	// "=== CONT  "
   254  	actionColon := false
   255  	origLine := line
   256  	ok := false
   257  	indent := 0
   258  	for _, magic := range updates {
   259  		if bytes.HasPrefix(line, magic) {
   260  			ok = true
   261  			break
   262  		}
   263  	}
   264  	if !ok {
   265  		// "--- PASS: "
   266  		// "--- FAIL: "
   267  		// "--- SKIP: "
   268  		// "--- BENCH: "
   269  		// but possibly indented.
   270  		for bytes.HasPrefix(line, fourSpace) {
   271  			line = line[4:]
   272  			indent++
   273  		}
   274  		for _, magic := range reports {
   275  			if bytes.HasPrefix(line, magic) {
   276  				actionColon = true
   277  				ok = true
   278  				break
   279  			}
   280  		}
   281  	}
   282  
   283  	// Not a special test output line.
   284  	if !ok {
   285  		// Lookup the name of the test which produced the output using the
   286  		// indentation of the output as an index into the stack of the current
   287  		// subtests.
   288  		// If the indentation is greater than the number of current subtests
   289  		// then the output must have included extra indentation. We can't
   290  		// determine which subtest produced this output, so we default to the
   291  		// old behaviour of assuming the most recently run subtest produced it.
   292  		if indent > 0 && indent <= len(c.report) {
   293  			c.testName = c.report[indent-1].Test
   294  		}
   295  		c.output.write(origLine)
   296  		return
   297  	}
   298  
   299  	// Parse out action and test name.
   300  	i := 0
   301  	if actionColon {
   302  		i = bytes.IndexByte(line, ':') + 1
   303  	}
   304  	if i == 0 {
   305  		i = len(updates[0])
   306  	}
   307  	action := strings.ToLower(strings.TrimSuffix(strings.TrimSpace(string(line[4:i])), ":"))
   308  	name := strings.TrimSpace(string(line[i:]))
   309  
   310  	e := &event{Action: action}
   311  	if line[0] == '-' { // PASS or FAIL report
   312  		// Parse out elapsed time.
   313  		if i := strings.Index(name, " ("); i >= 0 {
   314  			if strings.HasSuffix(name, "s)") {
   315  				t, err := strconv.ParseFloat(name[i+2:len(name)-2], 64)
   316  				if err == nil {
   317  					if c.mode&Timestamp != 0 {
   318  						e.Elapsed = &t
   319  					}
   320  				}
   321  			}
   322  			name = name[:i]
   323  		}
   324  		if len(c.report) < indent {
   325  			// Nested deeper than expected.
   326  			// Treat this line as plain output.
   327  			c.output.write(origLine)
   328  			return
   329  		}
   330  		// Flush reports at this indentation level or deeper.
   331  		c.needMarker = sawMarker
   332  		c.flushReport(indent)
   333  		e.Test = name
   334  		c.testName = name
   335  		c.report = append(c.report, e)
   336  		c.output.write(origLine)
   337  		return
   338  	}
   339  	if action == "attr" {
   340  		var rest string
   341  		name, rest, _ = strings.Cut(name, " ")
   342  		e.Key, e.Value, _ = strings.Cut(rest, " ")
   343  	}
   344  	// === update.
   345  	// Finish any pending PASS/FAIL reports.
   346  	c.needMarker = sawMarker
   347  	c.flushReport(0)
   348  	c.testName = name
   349  
   350  	if action == "name" {
   351  		// This line is only generated to get c.testName right.
   352  		// Don't emit an event.
   353  		return
   354  	}
   355  
   356  	if action == "pause" {
   357  		// For a pause, we want to write the pause notification before
   358  		// delivering the pause event, just so it doesn't look like the test
   359  		// is generating output immediately after being paused.
   360  		c.output.write(origLine)
   361  	}
   362  	c.writeEvent(e)
   363  	if action != "pause" {
   364  		c.output.write(origLine)
   365  	}
   366  
   367  	return
   368  }
   369  
   370  // flushReport flushes all pending PASS/FAIL reports at levels >= depth.
   371  func (c *Converter) flushReport(depth int) {
   372  	c.testName = ""
   373  	for len(c.report) > depth {
   374  		e := c.report[len(c.report)-1]
   375  		c.report = c.report[:len(c.report)-1]
   376  		c.writeEvent(e)
   377  	}
   378  }
   379  
   380  // Close marks the end of the go test output.
   381  // It flushes any pending input and then output (only partial lines at this point)
   382  // and then emits the final overall package-level pass/fail event.
   383  func (c *Converter) Close() error {
   384  	c.input.flush()
   385  	c.output.flush()
   386  	if c.result != "" {
   387  		e := &event{Action: c.result}
   388  		if c.mode&Timestamp != 0 {
   389  			dt := time.Since(c.start).Round(1 * time.Millisecond).Seconds()
   390  			e.Elapsed = &dt
   391  		}
   392  		if c.result == "fail" {
   393  			e.FailedBuild = c.failedBuild
   394  		}
   395  		c.writeEvent(e)
   396  	}
   397  	return nil
   398  }
   399  
   400  // writeOutputEvent writes a single output event with the given bytes.
   401  func (c *Converter) writeOutputEvent(out []byte) {
   402  	c.writeEvent(&event{
   403  		Action: "output",
   404  		Output: (*textBytes)(&out),
   405  	})
   406  }
   407  
   408  // writeEvent writes a single event.
   409  // It adds the package, time (if requested), and test name (if needed).
   410  func (c *Converter) writeEvent(e *event) {
   411  	e.Package = c.pkg
   412  	if c.mode&Timestamp != 0 {
   413  		t := time.Now()
   414  		e.Time = &t
   415  	}
   416  	if e.Test == "" {
   417  		e.Test = c.testName
   418  	}
   419  	js, err := json.Marshal(e)
   420  	if err != nil {
   421  		// Should not happen - event is valid for json.Marshal.
   422  		fmt.Fprintf(c.w, "testjson internal error: %v\n", err)
   423  		return
   424  	}
   425  	js = append(js, '\n')
   426  	c.w.Write(js)
   427  }
   428  
   429  // A lineBuffer is an I/O buffer that reacts to writes by invoking
   430  // input-processing callbacks on whole lines or (for long lines that
   431  // have been split) line fragments.
   432  //
   433  // It should be initialized with b set to a buffer of length 0 but non-zero capacity,
   434  // and line and part set to the desired input processors.
   435  // The lineBuffer will call line(x) for any whole line x (including the final newline)
   436  // that fits entirely in cap(b). It will handle input lines longer than cap(b) by
   437  // calling part(x) for sections of the line. The line will be split at UTF8 boundaries,
   438  // and the final call to part for a long line includes the final newline.
   439  type lineBuffer struct {
   440  	b    []byte       // buffer
   441  	mid  bool         // whether we're in the middle of a long line
   442  	line func([]byte) // line callback
   443  	part func([]byte) // partial line callback
   444  }
   445  
   446  // write writes b to the buffer.
   447  func (l *lineBuffer) write(b []byte) {
   448  	for len(b) > 0 {
   449  		// Copy what we can into l.b.
   450  		m := copy(l.b[len(l.b):cap(l.b)], b)
   451  		l.b = l.b[:len(l.b)+m]
   452  		b = b[m:]
   453  
   454  		// Process lines in l.b.
   455  		i := 0
   456  		for i < len(l.b) {
   457  			j, w := indexEOL(l.b[i:])
   458  			if j < 0 {
   459  				if !l.mid {
   460  					if j := bytes.IndexByte(l.b[i:], '\t'); j >= 0 {
   461  						if isBenchmarkName(bytes.TrimRight(l.b[i:i+j], " ")) {
   462  							l.part(l.b[i : i+j+1])
   463  							l.mid = true
   464  							i += j + 1
   465  						}
   466  					}
   467  				}
   468  				break
   469  			}
   470  			e := i + j + w
   471  			if l.mid {
   472  				// Found the end of a partial line.
   473  				l.part(l.b[i:e])
   474  				l.mid = false
   475  			} else {
   476  				// Found a whole line.
   477  				l.line(l.b[i:e])
   478  			}
   479  			i = e
   480  		}
   481  
   482  		// Whatever's left in l.b is a line fragment.
   483  		if i == 0 && len(l.b) == cap(l.b) {
   484  			// The whole buffer is a fragment.
   485  			// Emit it as the beginning (or continuation) of a partial line.
   486  			t := trimUTF8(l.b)
   487  			l.part(l.b[:t])
   488  			l.b = l.b[:copy(l.b, l.b[t:])]
   489  			l.mid = true
   490  		}
   491  
   492  		// There's room for more input.
   493  		// Slide it down in hope of completing the line.
   494  		if i > 0 {
   495  			l.b = l.b[:copy(l.b, l.b[i:])]
   496  		}
   497  	}
   498  }
   499  
   500  // indexEOL finds the index of a line ending,
   501  // returning its position and output width.
   502  // A line ending is either a \n or the empty string just before a ^V not beginning a line.
   503  // The output width for \n is 1 (meaning it should be printed)
   504  // but the output width for ^V is 0 (meaning it should be left to begin the next line).
   505  func indexEOL(b []byte) (pos, wid int) {
   506  	for i, c := range b {
   507  		if c == '\n' {
   508  			return i, 1
   509  		}
   510  		if c == marker && i > 0 { // test -v=json emits ^V at start of framing lines
   511  			return i, 0
   512  		}
   513  	}
   514  	return -1, 0
   515  }
   516  
   517  // flush flushes the line buffer.
   518  func (l *lineBuffer) flush() {
   519  	if len(l.b) > 0 {
   520  		// Must be a line without a \n, so a partial line.
   521  		l.part(l.b)
   522  		l.b = l.b[:0]
   523  	}
   524  }
   525  
   526  var benchmark = []byte("Benchmark")
   527  
   528  // isBenchmarkName reports whether b is a valid benchmark name
   529  // that might appear as the first field in a benchmark result line.
   530  func isBenchmarkName(b []byte) bool {
   531  	if !bytes.HasPrefix(b, benchmark) {
   532  		return false
   533  	}
   534  	if len(b) == len(benchmark) { // just "Benchmark"
   535  		return true
   536  	}
   537  	r, _ := utf8.DecodeRune(b[len(benchmark):])
   538  	return !unicode.IsLower(r)
   539  }
   540  
   541  // trimUTF8 returns a length t as close to len(b) as possible such that b[:t]
   542  // does not end in the middle of a possibly-valid UTF-8 sequence.
   543  //
   544  // If a large text buffer must be split before position i at the latest,
   545  // splitting at position trimUTF(b[:i]) avoids splitting a UTF-8 sequence.
   546  func trimUTF8(b []byte) int {
   547  	// Scan backward to find non-continuation byte.
   548  	for i := 1; i < utf8.UTFMax && i <= len(b); i++ {
   549  		if c := b[len(b)-i]; c&0xc0 != 0x80 {
   550  			switch {
   551  			case c&0xe0 == 0xc0:
   552  				if i < 2 {
   553  					return len(b) - i
   554  				}
   555  			case c&0xf0 == 0xe0:
   556  				if i < 3 {
   557  					return len(b) - i
   558  				}
   559  			case c&0xf8 == 0xf0:
   560  				if i < 4 {
   561  					return len(b) - i
   562  				}
   563  			}
   564  			break
   565  		}
   566  	}
   567  	return len(b)
   568  }
   569
View as plain text