cmd/devp2p, internal/utesting: implement TAP output (#21760)

TAP is a text format for test results. Parsers for it are available in many languages,
making it easy to consume. I want TAP output from our protocol tests because the
Hive wrapper around them needs to know about the test names and their individual
results and logs. It would also be possible to just write this info as JSON, but I don't
want to invent a new format.

This also improves the normal console output for tests (when running without --tap).
It now prints -- RUN lines before any output from the test, and indents the log output
by one space.

cmd/devp2p/discv4cmd.go

@@ -19,14 +19,12 @@ package main
 import (
 	"fmt"
 	"net"
-	"os"
 	"strings"
 	"time"
 
 	"github.com/ethereum/go-ethereum/cmd/devp2p/internal/v4test"
 	"github.com/ethereum/go-ethereum/common"
 	"github.com/ethereum/go-ethereum/crypto"
-	"github.com/ethereum/go-ethereum/internal/utesting"
 	"github.com/ethereum/go-ethereum/p2p/discover"
 	"github.com/ethereum/go-ethereum/p2p/enode"
 	"github.com/ethereum/go-ethereum/params"
@@ -82,7 +80,13 @@ var (
 		Name:   "test",
 		Usage:  "Runs tests against a node",
 		Action: discv4Test,
-		Flags:  []cli.Flag{remoteEnodeFlag, testPatternFlag, testListen1Flag, testListen2Flag},
+		Flags: []cli.Flag{
+			remoteEnodeFlag,
+			testPatternFlag,
+			testTAPFlag,
+			testListen1Flag,
+			testListen2Flag,
+		},
 	}
 )
 
@@ -113,20 +117,6 @@ var (
 		Usage:  "Enode of the remote node under test",
 		EnvVar: "REMOTE_ENODE",
 	}
-	testPatternFlag = cli.StringFlag{
-		Name:  "run",
-		Usage: "Pattern of test suite(s) to run",
-	}
-	testListen1Flag = cli.StringFlag{
-		Name:  "listen1",
-		Usage: "IP address of the first tester",
-		Value: v4test.Listen1,
-	}
-	testListen2Flag = cli.StringFlag{
-		Name:  "listen2",
-		Usage: "IP address of the second tester",
-		Value: v4test.Listen2,
-	}
 )
 
 func discv4Ping(ctx *cli.Context) error {
@@ -213,6 +203,7 @@ func discv4Crawl(ctx *cli.Context) error {
 	return nil
 }
 
+// discv4Test runs the protocol test suite.
 func discv4Test(ctx *cli.Context) error {
 	// Configure test package globals.
 	if !ctx.IsSet(remoteEnodeFlag.Name) {
@@ -221,18 +212,7 @@ func discv4Test(ctx *cli.Context) error {
 	v4test.Remote = ctx.String(remoteEnodeFlag.Name)
 	v4test.Listen1 = ctx.String(testListen1Flag.Name)
 	v4test.Listen2 = ctx.String(testListen2Flag.Name)
-
+	return runTests(ctx, v4test.AllTests)
-	// Filter and run test cases.
-	tests := v4test.AllTests
-	if ctx.IsSet(testPatternFlag.Name) {
-		tests = utesting.MatchTests(tests, ctx.String(testPatternFlag.Name))
-	}
-	results := utesting.RunTests(tests, os.Stdout)
-	if fails := utesting.CountFailures(results); fails > 0 {
-		return fmt.Errorf("%v/%v tests passed.", len(tests)-fails, len(tests))
-	}
-	fmt.Printf("%v/%v passed\n", len(tests), len(tests))
-	return nil
 }
 
 // startV4 starts an ephemeral discovery V4 node.

cmd/devp2p/discv5cmd.go

@@ -18,13 +18,10 @@ package main
 
 import (
 	"fmt"
-	"os"
 	"time"
 
 	"github.com/ethereum/go-ethereum/cmd/devp2p/internal/v5test"
 	"github.com/ethereum/go-ethereum/common"
-	"github.com/ethereum/go-ethereum/internal/utesting"
-	"github.com/ethereum/go-ethereum/log"
 	"github.com/ethereum/go-ethereum/p2p/discover"
 	"gopkg.in/urfave/cli.v1"
 )
@@ -62,7 +59,12 @@ var (
 		Name:   "test",
 		Usage:  "Runs protocol tests against a node",
 		Action: discv5Test,
-		Flags:  []cli.Flag{testPatternFlag, testListen1Flag, testListen2Flag},
+		Flags: []cli.Flag{
+			testPatternFlag,
+			testTAPFlag,
+			testListen1Flag,
+			testListen2Flag,
+		},
 	}
 	discv5ListenCommand = cli.Command{
 		Name:   "listen",
@@ -114,28 +116,14 @@ func discv5Crawl(ctx *cli.Context) error {
 	return nil
 }
 
+// discv5Test runs the protocol test suite.
 func discv5Test(ctx *cli.Context) error {
-	// Disable logging unless explicitly enabled.
-	if !ctx.GlobalIsSet("verbosity") && !ctx.GlobalIsSet("vmodule") {
-		log.Root().SetHandler(log.DiscardHandler())
-	}
-
-	// Filter and run test cases.
 	suite := &v5test.Suite{
 		Dest:    getNodeArg(ctx),
 		Listen1: ctx.String(testListen1Flag.Name),
 		Listen2: ctx.String(testListen2Flag.Name),
 	}
-	tests := suite.AllTests()
+	return runTests(ctx, suite.AllTests())
-	if ctx.IsSet(testPatternFlag.Name) {
-		tests = utesting.MatchTests(tests, ctx.String(testPatternFlag.Name))
-	}
-	results := utesting.RunTests(tests, os.Stdout)
-	if fails := utesting.CountFailures(results); fails > 0 {
-		return fmt.Errorf("%v/%v tests passed.", len(tests)-fails, len(tests))
-	}
-	fmt.Printf("%v/%v passed\n", len(tests), len(tests))
-	return nil
 }
 
 func discv5Listen(ctx *cli.Context) error {

cmd/devp2p/rlpxcmd.go

@@ -19,11 +19,9 @@ package main
 import (
 	"fmt"
 	"net"
-	"os"
 
 	"github.com/ethereum/go-ethereum/cmd/devp2p/internal/ethtest"
 	"github.com/ethereum/go-ethereum/crypto"
-	"github.com/ethereum/go-ethereum/internal/utesting"
 	"github.com/ethereum/go-ethereum/p2p"
 	"github.com/ethereum/go-ethereum/p2p/rlpx"
 	"github.com/ethereum/go-ethereum/rlp"
@@ -47,9 +45,12 @@ var (
 	rlpxEthTestCommand = cli.Command{
 		Name:      "eth-test",
 		Usage:     "Runs tests against a node",
-		ArgsUsage: "<node> <path_to_chain.rlp_file>",
+		ArgsUsage: "<node> <chain.rlp> <genesis.json>",
 		Action:    rlpxEthTest,
-		Flags:     []cli.Flag{testPatternFlag},
+		Flags: []cli.Flag{
+			testPatternFlag,
+			testTAPFlag,
+		},
 	}
 )
 
@@ -88,22 +89,11 @@ func rlpxPing(ctx *cli.Context) error {
 	return nil
 }
 
+// rlpxEthTest runs the eth protocol test suite.
 func rlpxEthTest(ctx *cli.Context) error {
 	if ctx.NArg() < 3 {
 		exit("missing path to chain.rlp as command-line argument")
 	}
-
 	suite := ethtest.NewSuite(getNodeArg(ctx), ctx.Args()[1], ctx.Args()[2])
-
+	return runTests(ctx, suite.AllTests())
-	// Filter and run test cases.
-	tests := suite.AllTests()
-	if ctx.IsSet(testPatternFlag.Name) {
-		tests = utesting.MatchTests(tests, ctx.String(testPatternFlag.Name))
-	}
-	results := utesting.RunTests(tests, os.Stdout)
-	if fails := utesting.CountFailures(results); fails > 0 {
-		return fmt.Errorf("%v of %v tests passed.", len(tests)-fails, len(tests))
-	}
-	fmt.Printf("all tests passed\n")
-	return nil
 }

cmd/devp2p/runtest.go

@@ -0,0 +1,69 @@
+// Copyright 2020 The go-ethereum Authors
+// This file is part of go-ethereum.
+//
+// go-ethereum is free software: you can redistribute it and/or modify
+// it under the terms of the GNU General Public License as published by
+// the Free Software Foundation, either version 3 of the License, or
+// (at your option) any later version.
+//
+// go-ethereum is distributed in the hope that it will be useful,
+// but WITHOUT ANY WARRANTY; without even the implied warranty of
+// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+// GNU General Public License for more details.
+//
+// You should have received a copy of the GNU General Public License
+// along with go-ethereum. If not, see <http://www.gnu.org/licenses/>.
+
+package main
+
+import (
+	"os"
+
+	"github.com/ethereum/go-ethereum/cmd/devp2p/internal/v4test"
+	"github.com/ethereum/go-ethereum/internal/utesting"
+	"github.com/ethereum/go-ethereum/log"
+	"gopkg.in/urfave/cli.v1"
+)
+
+var (
+	testPatternFlag = cli.StringFlag{
+		Name:  "run",
+		Usage: "Pattern of test suite(s) to run",
+	}
+	testTAPFlag = cli.BoolFlag{
+		Name:  "tap",
+		Usage: "Output TAP",
+	}
+	// These two are specific to the discovery tests.
+	testListen1Flag = cli.StringFlag{
+		Name:  "listen1",
+		Usage: "IP address of the first tester",
+		Value: v4test.Listen1,
+	}
+	testListen2Flag = cli.StringFlag{
+		Name:  "listen2",
+		Usage: "IP address of the second tester",
+		Value: v4test.Listen2,
+	}
+)
+
+func runTests(ctx *cli.Context, tests []utesting.Test) error {
+	// Filter test cases.
+	if ctx.IsSet(testPatternFlag.Name) {
+		tests = utesting.MatchTests(tests, ctx.String(testPatternFlag.Name))
+	}
+	// Disable logging unless explicitly enabled.
+	if !ctx.GlobalIsSet("verbosity") && !ctx.GlobalIsSet("vmodule") {
+		log.Root().SetHandler(log.DiscardHandler())
+	}
+	// Run the tests.
+	var run = utesting.RunTests
+	if ctx.Bool(testTAPFlag.Name) {
+		run = utesting.RunTAP
+	}
+	results := run(tests, os.Stdout)
+	if utesting.CountFailures(results) > 0 {
+		os.Exit(1)
+	}
+	return nil
+}

internal/utesting/utesting.go

@@ -25,6 +25,7 @@ import (
 	"bytes"
 	"fmt"
 	"io"
+	"io/ioutil"
 	"regexp"
 	"runtime"
 	"sync"
@@ -63,32 +64,165 @@ func MatchTests(tests []Test, expr string) []Test {
 // RunTests executes all given tests in order and returns their results.
 // If the report writer is non-nil, a test report is written to it in real time.
 func RunTests(tests []Test, report io.Writer) []Result {
-	results := make([]Result, len(tests))
+	if report == nil {
-	for i, test := range tests {
+		report = ioutil.Discard
-		var output io.Writer
-		buffer := new(bytes.Buffer)
-		output = buffer
-		if report != nil {
-			output = io.MultiWriter(buffer, report)
 	}
+	results := run(tests, newConsoleOutput(report))
+	fails := CountFailures(results)
+	fmt.Fprintf(report, "%v/%v tests passed.\n", len(tests)-fails, len(tests))
+	return results
+}
+
+// RunTAP runs the given tests and writes Test Anything Protocol output
+// to the report writer.
+func RunTAP(tests []Test, report io.Writer) []Result {
+	return run(tests, newTAP(report, len(tests)))
+}
+
+func run(tests []Test, output testOutput) []Result {
+	var results = make([]Result, len(tests))
+	for i, test := range tests {
+		buffer := new(bytes.Buffer)
+		logOutput := io.MultiWriter(buffer, output)
+
+		output.testStart(test.Name)
 		start := time.Now()
 		results[i].Name = test.Name
-		results[i].Failed = run(test, output)
+		results[i].Failed = runTest(test, logOutput)
 		results[i].Duration = time.Since(start)
 		results[i].Output = buffer.String()
-		if report != nil {
+		output.testResult(results[i])
-			printResult(results[i], report)
-		}
 	}
 	return results
 }
 
-func printResult(r Result, w io.Writer) {
+// testOutput is implemented by output formats.
+type testOutput interface {
+	testStart(name string)
+	Write([]byte) (int, error)
+	testResult(Result)
+}
+
+// consoleOutput prints test results similarly to go test.
+type consoleOutput struct {
+	out         io.Writer
+	indented    *indentWriter
+	curTest     string
+	wroteHeader bool
+}
+
+func newConsoleOutput(w io.Writer) *consoleOutput {
+	return &consoleOutput{
+		out:      w,
+		indented: newIndentWriter(" ", w),
+	}
+}
+
+// testStart signals the start of a new test.
+func (c *consoleOutput) testStart(name string) {
+	c.curTest = name
+	c.wroteHeader = false
+}
+
+// Write handles test log output.
+func (c *consoleOutput) Write(b []byte) (int, error) {
+	if !c.wroteHeader {
+		// This is the first output line from the test. Print a "-- RUN" header.
+		fmt.Fprintln(c.out, "-- RUN", c.curTest)
+		c.wroteHeader = true
+	}
+	return c.indented.Write(b)
+}
+
+// testResult prints the final test result line.
+func (c *consoleOutput) testResult(r Result) {
+	c.indented.flush()
 	pd := r.Duration.Truncate(100 * time.Microsecond)
 	if r.Failed {
-		fmt.Fprintf(w, "-- FAIL %s (%v)\n", r.Name, pd)
+		fmt.Fprintf(c.out, "-- FAIL %s (%v)\n", r.Name, pd)
 	} else {
-		fmt.Fprintf(w, "-- OK %s (%v)\n", r.Name, pd)
+		fmt.Fprintf(c.out, "-- OK %s (%v)\n", r.Name, pd)
+	}
+}
+
+// tapOutput produces Test Anything Protocol v13 output.
+type tapOutput struct {
+	out      io.Writer
+	indented *indentWriter
+	counter  int
+}
+
+func newTAP(out io.Writer, numTests int) *tapOutput {
+	fmt.Fprintf(out, "1..%d\n", numTests)
+	return &tapOutput{
+		out:      out,
+		indented: newIndentWriter("# ", out),
+	}
+}
+
+func (t *tapOutput) testStart(name string) {
+	t.counter++
+}
+
+// Write does nothing for TAP because there is no real-time output of test logs.
+func (t *tapOutput) Write(b []byte) (int, error) {
+	return len(b), nil
+}
+
+func (t *tapOutput) testResult(r Result) {
+	status := "ok"
+	if r.Failed {
+		status = "not ok"
+	}
+	fmt.Fprintln(t.out, status, t.counter, r.Name)
+	t.indented.Write([]byte(r.Output))
+	t.indented.flush()
+}
+
+// indentWriter indents all written text.
+type indentWriter struct {
+	out    io.Writer
+	indent string
+	inLine bool
+}
+
+func newIndentWriter(indent string, out io.Writer) *indentWriter {
+	return &indentWriter{out: out, indent: indent}
+}
+
+func (w *indentWriter) Write(b []byte) (n int, err error) {
+	for len(b) > 0 {
+		if !w.inLine {
+			if _, err = io.WriteString(w.out, w.indent); err != nil {
+				return n, err
+			}
+			w.inLine = true
+		}
+
+		end := bytes.IndexByte(b, '\n')
+		if end == -1 {
+			nn, err := w.out.Write(b)
+			n += nn
+			return n, err
+		}
+
+		line := b[:end+1]
+		nn, err := w.out.Write(line)
+		n += nn
+		if err != nil {
+			return n, err
+		}
+		b = b[end+1:]
+		w.inLine = false
+	}
+	return n, err
+}
+
+// flush ensures the current line is terminated.
+func (w *indentWriter) flush() {
+	if w.inLine {
+		fmt.Println(w.out)
+		w.inLine = false
 	}
 }
 
@@ -106,11 +240,11 @@ func CountFailures(rr []Result) int {
 // Run executes a single test.
 func Run(test Test) (bool, string) {
 	output := new(bytes.Buffer)
-	failed := run(test, output)
+	failed := runTest(test, output)
 	return failed, output.String()
 }
 
-func run(test Test, output io.Writer) bool {
+func runTest(test Test, output io.Writer) bool {
 	t := &T{output: output}
 	done := make(chan struct{})
 	go func() {
@@ -137,6 +271,9 @@ type T struct {
 	output io.Writer
 }
 
+// Helper exists for compatibility with testing.T.
+func (t *T) Helper() {}
+
 // FailNow marks the test as having failed and stops its execution by calling
 // runtime.Goexit (which then runs all deferred calls in the current goroutine).
 func (t *T) FailNow() {

internal/utesting/utesting_test.go

@@ -17,6 +17,8 @@
 package utesting
 
 import (
+	"bytes"
+	"regexp"
 	"strings"
 	"testing"
 )
@@ -53,3 +55,85 @@ func TestTest(t *testing.T) {
 		t.Fatalf("wrong result for panicking test: %#v", results[2])
 	}
 }
+
+var outputTests = []Test{
+	{
+		Name: "TestWithLogs",
+		Fn: func(t *T) {
+			t.Log("output line 1")
+			t.Log("output line 2\noutput line 3")
+		},
+	},
+	{
+		Name: "TestNoLogs",
+		Fn:   func(t *T) {},
+	},
+	{
+		Name: "FailWithLogs",
+		Fn: func(t *T) {
+			t.Log("output line 1")
+			t.Error("failed 1")
+		},
+	},
+	{
+		Name: "FailMessage",
+		Fn: func(t *T) {
+			t.Error("failed 2")
+		},
+	},
+	{
+		Name: "FailNoOutput",
+		Fn: func(t *T) {
+			t.Fail()
+		},
+	},
+}
+
+func TestOutput(t *testing.T) {
+	var buf bytes.Buffer
+	RunTests(outputTests, &buf)
+
+	want := regexp.MustCompile(`
+^-- RUN TestWithLogs
+ output line 1
+ output line 2
+ output line 3
+-- OK TestWithLogs \([^)]+\)
+-- OK TestNoLogs \([^)]+\)
+-- RUN FailWithLogs
+ output line 1
+ failed 1
+-- FAIL FailWithLogs \([^)]+\)
+-- RUN FailMessage
+ failed 2
+-- FAIL FailMessage \([^)]+\)
+-- FAIL FailNoOutput \([^)]+\)
+2/5 tests passed.
+$`[1:])
+	if !want.MatchString(buf.String()) {
+		t.Fatalf("output does not match: %q", buf.String())
+	}
+}
+
+func TestOutputTAP(t *testing.T) {
+	var buf bytes.Buffer
+	RunTAP(outputTests, &buf)
+
+	want := `
+1..5
+ok 1 TestWithLogs
+# output line 1
+# output line 2
+# output line 3
+ok 2 TestNoLogs
+not ok 3 FailWithLogs
+# output line 1
+# failed 1
+not ok 4 FailMessage
+# failed 2
+not ok 5 FailNoOutput
+`
+	if buf.String() != want[1:] {
+		t.Fatalf("output does not match: %q", buf.String())
+	}
+}