diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 7a76980a4..c2b298aec 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -96,12 +96,11 @@ jobs: - name: Precache base images run: go run ./cmd/ci-precache - name: Run integration tests - run: go test -v -json ./test | go run ./cmd/test2json2gha + run: go test -v -json ./test | go run ./cmd/test2json2gha --slow 5s - name: dump logs if: failure() run: sudo journalctl -u docker - unit: runs-on: ubuntu-22.04 steps: diff --git a/cmd/test2json2gha/event.go b/cmd/test2json2gha/event.go new file mode 100644 index 000000000..e52128cfc --- /dev/null +++ b/cmd/test2json2gha/event.go @@ -0,0 +1,56 @@ +package main + +import ( + "os" + "time" + + "github.com/pkg/errors" +) + +// TestEvent is the go test2json event data structure we receive from `go test` +// This is defined in https://pkg.go.dev/cmd/test2json#hdr-Output_Format +type TestEvent struct { + Time time.Time + Action string + Package string + Test string + Elapsed float64 // seconds + Output string +} + +// TestResult is where we collect all the data about a test +type TestResult struct { + output *os.File + failed bool + pkg string + name string + elapsed float64 + skipped bool +} + +func (r *TestResult) Close() { + r.output.Close() +} + +func handlEvent(te *TestEvent, tr *TestResult) error { + if te.Output != "" { + _, err := tr.output.Write([]byte(te.Output)) + if err != nil { + return errors.Wrap(err, "error collecting test event output") + } + } + + tr.pkg = te.Package + tr.name = te.Test + if te.Elapsed > 0 { + tr.elapsed = te.Elapsed + } + + if te.Action == "fail" { + tr.failed = true + } + if te.Action == "skip" { + tr.skipped = true + } + return nil +} diff --git a/cmd/test2json2gha/main.go b/cmd/test2json2gha/main.go index b4679535c..556dcfb8f 100644 --- a/cmd/test2json2gha/main.go +++ b/cmd/test2json2gha/main.go @@ -4,6 +4,7 @@ import ( "bufio" "bytes" "encoding/json" + "flag" "fmt" "io" "log/slog" @@ -15,6 +16,7 @@ import ( "time" "github.com/pkg/errors" + "github.com/vearutop/dynhist-go" ) func main() { @@ -23,6 +25,11 @@ func main() { panic(err) } + var slowThreshold time.Duration + flag.DurationVar(&slowThreshold, "slow", 500*time.Millisecond, "Threshold to mark test as slow") + + flag.Parse() + logger := slog.New(slog.NewTextHandler(os.Stderr, nil)) slog.SetDefault(logger) @@ -38,7 +45,7 @@ func main() { cleanup := func() { os.RemoveAll(tmp) } - anyFail, err := do(os.Stdin, os.Stdout, mod) + anyFail, err := do(os.Stdin, os.Stdout, mod, slowThreshold) if err != nil { fmt.Fprintf(os.Stderr, "%+v", err) cleanup() @@ -53,31 +60,7 @@ func main() { } } -// TestEvent is the go test2json event data structure we receive from `go test` -// This is defined in https://pkg.go.dev/cmd/test2json#hdr-Output_Format -type TestEvent struct { - Time time.Time - Action string - Package string - Test string - Elapsed float64 // seconds - Output string -} - -// TestResult is where we collect all the data about a test -type TestResult struct { - output *os.File - failed bool - pkg string - name string - elapsed float64 -} - -func (r *TestResult) Close() { - r.output.Close() -} - -func do(in io.Reader, out io.Writer, modName string) (bool, error) { +func do(in io.Reader, out io.Writer, modName string, slowThreshold time.Duration) (bool, error) { dec := json.NewDecoder(in) te := &TestEvent{} @@ -128,14 +111,36 @@ func do(in io.Reader, out io.Writer, modName string) (bool, error) { } buf := bufio.NewWriter(out) - var anyFail bool + + summaryF := getSummaryFile() + defer summaryF.Close() + + var failCount, skipCount int + var elapsed float64 + + failBuf := bytes.NewBuffer(nil) + hist := &dynhist.Collector{ + PrintSum: true, + WeightFunc: dynhist.ExpWidth(1.2, 0.9), + BucketsLimit: 10, + } + + slowBuf := bytes.NewBuffer(nil) + slow := slowThreshold.Seconds() for _, tr := range outs { + if tr.skipped { + skipCount++ + } + if tr.failed { - anyFail = true + failCount++ } - if err := writeResult(tr, buf, modName); err != nil { + hist.Add(tr.elapsed) + elapsed += tr.elapsed + + if err := writeResult(tr, buf, failBuf, slowBuf, slow, modName); err != nil { slog.Error("Error writing result", "error", err) continue } @@ -145,28 +150,41 @@ func do(in io.Reader, out io.Writer, modName string) (bool, error) { } } - return anyFail, nil -} + fmt.Fprintln(summaryF, "## Test metrics") + fmt.Fprintln(summaryF, mdBold("Skipped:"), skipCount, "\t", mdBold("Failed:"), failCount, "\t", mdBold("Total:"), len(outs), "\t", mdBold("Elapsed:"), fmt.Sprintf("%.3fs", elapsed)) -func handlEvent(te *TestEvent, tr *TestResult) error { - if te.Output != "" { - _, err := tr.output.Write([]byte(te.Output)) - if err != nil { - return errors.Wrap(err, "error collecting test event output") - } + fmt.Fprintln(summaryF, mdPreformat(hist.String())) + + if failBuf.Len() > 0 { + fmt.Fprintln(summaryF, "## Failures") + fmt.Fprintln(summaryF, failBuf.String()) + } + + if slowBuf.Len() > 0 { + fmt.Fprintln(summaryF, "## Slow Tests") + fmt.Fprintln(summaryF, slowBuf.String()) } - tr.pkg = te.Package - tr.name = te.Test - tr.elapsed = te.Elapsed + return failCount > 0, nil +} + +func (c *nopWriteCloser) Close() error { return nil } - if te.Action == "fail" { - tr.failed = true +func getSummaryFile() io.WriteCloser { + v := os.Getenv("GITHUB_STEP_SUMMARY") + if v == "" { + return &nopWriteCloser{io.Discard} } - return nil + + f, err := os.OpenFile(v, os.O_WRONLY|os.O_APPEND, 0) + if err != nil { + slog.Error("Error opening step summary file", "error", err) + return &nopWriteCloser{io.Discard} + } + return f } -func writeResult(tr *TestResult, out io.Writer, modName string) error { +func writeResult(tr *TestResult, out, summary, slowBuf io.Writer, slow float64, modName string) error { if tr.name == "" { return nil } @@ -190,31 +208,44 @@ func writeResult(tr *TestResult, out io.Writer, modName string) error { prefix = "\u274c " } - dur := time.Duration(tr.elapsed * float64(time.Second)) - fmt.Fprintln(out, "::group::"+prefix+group, dur) + fmt.Fprintf(out, "::group::%s %.3fs\n", prefix+group, tr.elapsed) defer func() { fmt.Fprintln(out, "::endgroup::") }() - dt, err := io.ReadAll(tr.output) - if err != nil { - return fmt.Errorf("error reading test output: %w", err) + var rdr io.Reader = tr.output + + if tr.elapsed > slow { + buf := bytes.NewBuffer(nil) + rdr = io.TeeReader(rdr, buf) + defer func() { + if buf.Len() > 0 { + fmt.Fprintln(slowBuf, mdLog(fmt.Sprintf("%s %.3fs", tr.name, tr.elapsed), buf)) + } + }() } if !tr.failed { - if _, err := out.Write(dt); err != nil { + if _, err := io.Copy(out, rdr); err != nil { return fmt.Errorf("error writing test output to output stream: %w", err) } return nil } - scanner := bufio.NewScanner(bytes.NewReader(dt)) + failBuf := bytes.NewBuffer(nil) + rdr = io.TeeReader(rdr, failBuf) + defer func() { + fmt.Fprintln(summary, mdLog(tr.name+fmt.Sprintf(" %3.f", tr.elapsed), failBuf)) + }() + + scanner := bufio.NewScanner(rdr) var ( file, line string ) buf := bytes.NewBuffer(nil) + for scanner.Scan() { txt := scanner.Text() f, l, ok := getTestOutputLoc(txt) @@ -235,6 +266,7 @@ func writeResult(tr *TestResult, out io.Writer, modName string) error { file = filepath.Join(pkg, file) fmt.Fprintf(out, "::error file=%s,line=%s::%s\n", file, line, buf) + return nil } diff --git a/cmd/test2json2gha/main_test.go b/cmd/test2json2gha/main_test.go new file mode 100644 index 000000000..27af1fbdd --- /dev/null +++ b/cmd/test2json2gha/main_test.go @@ -0,0 +1,26 @@ +package main + +import ( + "testing" + "time" +) + +func TestFail(t *testing.T) { + t.Log("This is for checking what a test failure looks like") + t.Fatal("This is a failure") +} + +func TestAnotherFail(t *testing.T) { + t.Log("This is for checking what a test failure looks like") + t.Fatal("This is yet another failure!") +} + +func TestSlow(t *testing.T) { + time.Sleep(10 * time.Second) + t.Log("This is a slow test!") +} + +func TestAnothrSlow(t *testing.T) { + time.Sleep(5 * time.Second) + t.Log("This is yet another slow test!") +} diff --git a/cmd/test2json2gha/markdown.go b/cmd/test2json2gha/markdown.go new file mode 100644 index 000000000..4f85e8e51 --- /dev/null +++ b/cmd/test2json2gha/markdown.go @@ -0,0 +1,34 @@ +package main + +import ( + "fmt" + "io" + "strings" +) + +func mdBold(v string) string { + return "**" + v + "**" +} + +func mdDetails(s string) string { + return fmt.Sprintf("\n
\n%s\n
\n", s) +} + +func mdSummary(s string) string { + return "" + s + "\n" +} + +func mdPreformat(s string) string { + return fmt.Sprintf("\n```\n%s\n```\n", s) +} + +type nopWriteCloser struct { + io.Writer +} + +func mdLog(head string, content fmt.Stringer) string { + sb := &strings.Builder{} + sb.WriteString(mdSummary(head)) + sb.WriteString(mdPreformat(content.String())) + return mdDetails(sb.String()) +} diff --git a/go.mod b/go.mod index 217a7fc42..0b66f6781 100644 --- a/go.mod +++ b/go.mod @@ -18,6 +18,7 @@ require ( github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.9.0 github.com/tonistiigi/fsutil v0.0.0-20240424095704-91a3fc46842c + github.com/vearutop/dynhist-go v1.2.3 go.opentelemetry.io/otel v1.21.0 go.opentelemetry.io/otel/sdk v1.21.0 golang.org/x/exp v0.0.0-20240909161429-701f63a606c0 diff --git a/go.sum b/go.sum index cdbcf8a9e..aa6b97585 100644 --- a/go.sum +++ b/go.sum @@ -17,6 +17,8 @@ github.com/anchore/go-struct-converter v0.0.0-20221118182256-c68fdcfa2092 h1:aM1 github.com/anchore/go-struct-converter v0.0.0-20221118182256-c68fdcfa2092/go.mod h1:rYqSE9HbjzpHTI74vwPvae4ZVYZd1lue2ta6xHPdblA= github.com/bahlo/generic-list-go v0.2.0 h1:5sz/EEAK+ls5wF+NeqDpk5+iNdMDXrh3z3nPnH1Wvgk= github.com/bahlo/generic-list-go v0.2.0/go.mod h1:2KvAjgMlE5NNynlg/5iLrrCCZ2+5xWbdbCW3pNTGyYg= +github.com/bool64/dev v0.2.28 h1:6ayDfrB/jnNr2iQAZHI+uT3Qi6rErSbJYQs1y8rSrwM= +github.com/bool64/dev v0.2.28/go.mod h1:iJbh1y/HkunEPhgebWRNcs8wfGq7sjvJ6W5iabL8ACg= github.com/buger/jsonparser v1.1.1 h1:2PnMjfWD7wBILjqQbt530v576A/cAbQvEW9gGIpYMUs= github.com/buger/jsonparser v1.1.1/go.mod h1:6RYKKt7H4d4+iWqouImQ9R2FZql3VbhNgx27UK13J/0= github.com/cenkalti/backoff/v4 v4.2.1 h1:y4OZtCnogmCPw98Zjyt5a6+QwPLGkiQsYW5oUqylYbM= @@ -192,6 +194,8 @@ github.com/tonistiigi/vt100 v0.0.0-20240514184818-90bafcd6abab h1:H6aJ0yKQ0gF49Q github.com/tonistiigi/vt100 v0.0.0-20240514184818-90bafcd6abab/go.mod h1:ulncasL3N9uLrVann0m+CDlJKWsIAP34MPcOJF6VRvc= github.com/vbatts/tar-split v0.11.5 h1:3bHCTIheBm1qFTcgh9oPu+nNBtX+XJIupG/vacinCts= github.com/vbatts/tar-split v0.11.5/go.mod h1:yZbwRsSeGjusneWgA781EKej9HF8vme8okylkAeNKLk= +github.com/vearutop/dynhist-go v1.2.3 h1:EIMWszSDm6b7zmqySgx8zW2qNctE3IXUJggGlDFwJBE= +github.com/vearutop/dynhist-go v1.2.3/go.mod h1:liiiYiwAi8ixC3DbkxooEhASTF6ysJSXy+piCrBtxEg= github.com/wk8/go-ordered-map/v2 v2.1.8 h1:5h/BUHu93oj4gIdvHHHGsScSTMijfx5PeYkE/fJgbpc= github.com/wk8/go-ordered-map/v2 v2.1.8/go.mod h1:5nJHM5DyteebpVlHnWMV0rPz6Zp7+xBAnxjb1X5vnTw= github.com/yuin/goldmark v1.1.27/go.mod h1:3hX8gzYuyVAZsxl0MRgGTJEmQBFcNTphYh9decYSb74=