From 5d20fbbb6fb90f06bd5592f2c926f21dc8aa6fa2 Mon Sep 17 00:00:00 2001 From: Felix Lange Date: Wed, 4 Nov 2020 15:02:58 +0100 Subject: [PATCH] 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 | 38 ++----- cmd/devp2p/discv5cmd.go | 28 ++--- cmd/devp2p/rlpxcmd.go | 24 ++--- cmd/devp2p/runtest.go | 69 ++++++++++++ internal/utesting/utesting.go | 167 ++++++++++++++++++++++++++--- internal/utesting/utesting_test.go | 84 +++++++++++++++ 6 files changed, 329 insertions(+), 81 deletions(-) create mode 100644 cmd/devp2p/runtest.go diff --git a/cmd/devp2p/discv4cmd.go b/cmd/devp2p/discv4cmd.go index 467c20deb..3b6dc09a1 100644 --- a/cmd/devp2p/discv4cmd.go +++ b/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) - - // 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 + return runTests(ctx, v4test.AllTests) } // startV4 starts an ephemeral discovery V4 node. diff --git a/cmd/devp2p/discv5cmd.go b/cmd/devp2p/discv5cmd.go index 1d7442144..e20d7c9cf 100644 --- a/cmd/devp2p/discv5cmd.go +++ b/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() - 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 + return runTests(ctx, suite.AllTests()) } func discv5Listen(ctx *cli.Context) error { diff --git a/cmd/devp2p/rlpxcmd.go b/cmd/devp2p/rlpxcmd.go index 17019aee0..d90eb4687 100644 --- a/cmd/devp2p/rlpxcmd.go +++ b/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: " ", + ArgsUsage: " ", 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]) - - // 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 + return runTests(ctx, suite.AllTests()) } diff --git a/cmd/devp2p/runtest.go b/cmd/devp2p/runtest.go new file mode 100644 index 000000000..4168f8555 --- /dev/null +++ b/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 . + +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 +} diff --git a/internal/utesting/utesting.go b/internal/utesting/utesting.go index 4de0ecf99..ef05a90e4 100644 --- a/internal/utesting/utesting.go +++ b/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 { + report = ioutil.Discard + } + 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 { - var output io.Writer buffer := new(bytes.Buffer) - output = buffer - if report != nil { - output = io.MultiWriter(buffer, report) - } + 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 { - printResult(results[i], report) - } + output.testResult(results[i]) } 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() { diff --git a/internal/utesting/utesting_test.go b/internal/utesting/utesting_test.go index 1403a5c8f..31c7911c5 100644 --- a/internal/utesting/utesting_test.go +++ b/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()) + } +}