diff --git a/.github/workflows/build.yaml b/.github/workflows/build.yaml index d7dd2a3..ac00f72 100644 --- a/.github/workflows/build.yaml +++ b/.github/workflows/build.yaml @@ -97,11 +97,11 @@ jobs: - name: Run self-test run: | set -euo pipefail - go test -json ./... 2>&1 | tee /tmp/gotest.log | go run ./cmd/gotestfmt + go test -json ./... 2>&1 | tee /tmp/gotest.log | go run ./cmd/gotestfmt -formatter "go run ./cmd/gotestfmt-formatter/main.go" - name: Run self-test (verbose) run: | set -euo pipefail - go test -json -v ./... 2>&1 | tee /tmp/gotest-verbose.log | go run ./cmd/gotestfmt + go test -json -v ./... 2>&1 | tee /tmp/gotest-verbose.log | go run ./cmd/gotestfmt -formatter "go run ./cmd/gotestfmt-formatter/main.go" - name: Upload test log uses: actions/upload-artifact@v2 with: diff --git a/.gotestfmt/github/package.gotpl b/.gotestfmt/github/package.gotpl index bfc5f26..698f993 100644 --- a/.gotestfmt/github/package.gotpl +++ b/.gotestfmt/github/package.gotpl @@ -43,7 +43,7 @@ we are creating a stylized header for each package. {{- "\n" -}} {{- with .Output -}} - {{- . -}} + {{- formatTestOutput . $settings -}} {{- "\n" -}} {{- end -}} diff --git a/.gotestfmt/gitlab/package.gotpl b/.gotestfmt/gitlab/package.gotpl index 89203a7..c20ac45 100644 --- a/.gotestfmt/gitlab/package.gotpl +++ b/.gotestfmt/gitlab/package.gotpl @@ -41,7 +41,7 @@ we are creating a stylized header for each package. {{- "\n" -}} {{- with .Output -}} - {{- . -}} + {{- formatTestOutput . $settings -}} {{- "\n" -}} {{- end -}} diff --git a/.gotestfmt/package.gotpl b/.gotestfmt/package.gotpl index 1cd3aef..c64a15a 100644 --- a/.gotestfmt/package.gotpl +++ b/.gotestfmt/package.gotpl @@ -35,7 +35,7 @@ This template contains the format for an individual package. {{ " " }}{{- .Name -}} {{- "\033" -}}[0;37m ({{if $settings.ShowTestStatus}}{{.Result}}; {{end}}{{ .Duration -}}){{- "\033" -}}[0m{{- "\n" -}} {{- with .Output -}} - {{- . -}} + {{- formatTestOutput . $settings -}} {{- "\n" -}} {{- end -}} {{- end -}} diff --git a/.gotestfmt/teamcity/package.gotpl b/.gotestfmt/teamcity/package.gotpl index f9e3b9b..2b0ddfe 100644 --- a/.gotestfmt/teamcity/package.gotpl +++ b/.gotestfmt/teamcity/package.gotpl @@ -32,7 +32,7 @@ we are creating a stylized header for each package. ##teamcity[blockOpened name='{{- $title -}}']{{- "\n" -}} {{- with .Output -}} - {{- . -}} + {{- formatTestOutput . $settings -}} {{- "\n" -}} {{- end -}} ##teamcity[blockClosed name='{{- $title -}}']{{- "\n" -}} diff --git a/README.md b/README.md index bc3e58a..32263ef 100644 --- a/README.md +++ b/README.md @@ -27,6 +27,7 @@ Tadam, your tests will now show up in a beautifully formatted fashion. Plug it i - [Add your own CI](#add-your-own-ci) - [FAQ](#faq) - [How do I make the output less verbose?](#how-do-i-make-the-output-less-verbose) + - [How do I format the log lines within a test?](#how-do) - [Can I use gotestfmt without `-json`?](#can-i-use-gotestfmt-without--json) - [Does gotestfmt work with Ginkgo?](#does-gotestfmt-work-with-ginkgo) - [I don't like `gotestfmt`. What else can I use?](#i-dont-like-gotestfmt-what-else-can-i-use) @@ -263,13 +264,14 @@ Test cases have the following format: Render settings are available in all templates. They have the following fields: -| Variable | Type | Description | -|----------------------------|--------|--------------------------------------------------------------------| -| `.HideSuccessfulDownloads` | `bool` | Hide successful package downloads from the output. | -| `.HideSuccessfulPackages` | `bool` | Hide all packages that have only successful tests from the output. | -| `.HideEmptyPackages` | `bool` | Hide the packages from the output that have no test cases. | -| `.HideSuccessfulTests` | `bool` | Hide all tests from the output that are successful. | -| `.ShowTestStatus` | `bool` | Show the test status next to the icons (`PASS`, `FAIL`, `SKIP`). | +| Variable | Type | Description | +|----------------------------|----------|---------------------------------------------------------------------------------------------------------------------| +| `.HideSuccessfulDownloads` | `bool` | Hide successful package downloads from the output. | +| `.HideSuccessfulPackages` | `bool` | Hide all packages that have only successful tests from the output. | +| `.HideEmptyPackages` | `bool` | Hide the packages from the output that have no test cases. | +| `.HideSuccessfulTests` | `bool` | Hide all tests from the output that are successful. | +| `.ShowTestStatus` | `bool` | Show the test status next to the icons (`PASS`, `FAIL`, `SKIP`). | +| `.Formatter` | `string` | Path to the formatter to be used. This formatter can be invoked by calling `formatTestOutput outputHere .Settings`. | ## FAQ @@ -285,6 +287,18 @@ By default, `gotestfmt` will output all tests and their logs. However, you can u ⚠️ This feature depends on the template you use. If you customized your template please make sure to check the [Render settings](#render-settings) object in your code. +### How do I format the log lines within a test? + +Gotestfmt starting with version 2.2.0 supports running external formatters: + +``` +go test -json -v ./... 2>&1 | gotestfmt -formatter "/path/to/your/formatter" +``` + +The formatter will be called for each individual test case separately and the entire output of the test case will be passed to the formatter on the standard input. The formatter can then write the modified test output to the standard output. The formatter has 10 seconds to finish the test case, otherwise it will be terminated. + +You can find a sample formatter written in Go in [cmd/gotestfmt-formatter/main.go](cmd/gotestfmt-formatter/main.go). + ### How do I know what the icons mean in the output? The icons are based on the output of `go test -json`. They map to the values from the [`test2json`](https://pkg.go.dev/cmd/test2json) package (PASS, FAIL, SKIP). diff --git a/_testsource/logging/go.mod b/_testsource/logging/go.mod new file mode 100644 index 0000000..c3113fa --- /dev/null +++ b/_testsource/logging/go.mod @@ -0,0 +1,7 @@ +module github.com/haveyoudebuggedit/example + +go 1.17 + +require k8s.io/klog/v2 v2.40.1 + +require github.com/go-logr/logr v1.2.0 // indirect diff --git a/_testsource/logging/go.sum b/_testsource/logging/go.sum new file mode 100644 index 0000000..653945b --- /dev/null +++ b/_testsource/logging/go.sum @@ -0,0 +1,4 @@ +github.com/go-logr/logr v1.2.0 h1:QK40JKJyMdUDz+h+xvCsru/bJhvG0UxvePV0ufL/AcE= +github.com/go-logr/logr v1.2.0/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbVz/1A= +k8s.io/klog/v2 v2.40.1 h1:P4RRucWk/lFOlDdkAr3mc7iWFkgKrZY9qZMAgek06S4= +k8s.io/klog/v2 v2.40.1/go.mod h1:y1WjHnz7Dj687irZUWR/WLkLc5N1YHtjLdmgWjndZn0= diff --git a/_testsource/logging/test.go b/_testsource/logging/test.go new file mode 100644 index 0000000..092abf0 --- /dev/null +++ b/_testsource/logging/test.go @@ -0,0 +1 @@ +package logging \ No newline at end of file diff --git a/_testsource/logging/test_test.go b/_testsource/logging/test_test.go new file mode 100644 index 0000000..e07457b --- /dev/null +++ b/_testsource/logging/test_test.go @@ -0,0 +1,19 @@ +package logging_test + +import ( + "testing" + + klog "k8s.io/klog/v2" +) + +func TestGoLogging(t *testing.T) { + t.Parallel() + t.Logf("Hello world!") +} + +func TestKLog(t *testing.T) { + t.Parallel() + klog.Info("This is an info message") + klog.Warning("This is a warning message") + klog.Error("This is an error message") +} diff --git a/cmd/gotestfmt-formatter/main.go b/cmd/gotestfmt-formatter/main.go new file mode 100644 index 0000000..08afd99 --- /dev/null +++ b/cmd/gotestfmt-formatter/main.go @@ -0,0 +1,39 @@ +package main + +import ( + "bufio" + "fmt" + "os" + "regexp" +) + +var goLogRegexp = regexp.MustCompile(`^\s+([^:]+):([0-9]+): (.*)$`) +var kLogRegexp = regexp.MustCompile(`^([IWE])([0-9]+)\s+([0-9:.]+)\s+([0-9]+)\s+([^:]+):([0-9]+)]\s+(.*)`) + +// main is a demo formatter that showcases how to write a formatter for gotestfmt. +func main() { + scanner := bufio.NewScanner(os.Stdin) + first := true + for scanner.Scan() { + line := scanner.Text() + if !first { + fmt.Println() + } + first = false + if goLogMatch := goLogRegexp.FindSubmatch([]byte(line)); len(goLogMatch) > 0 { + fmt.Printf(" ⚙ %s:%s: %s", goLogMatch[1], goLogMatch[2], goLogMatch[3]) + } else if kLogMatch := kLogRegexp.FindSubmatch([]byte(line)); len(kLogMatch) > 0 { + symbol := "⚙" + switch string(kLogMatch[1]) { + case "I": + case "W": + symbol = "⚠️" + case "E": + symbol = "❌" + } + fmt.Printf(" %s %s:%s: %s", symbol, kLogMatch[5], kLogMatch[6], kLogMatch[7]) + } else { + fmt.Printf(" %s", line) + } + } +} diff --git a/cmd/gotestfmt/main.go b/cmd/gotestfmt/main.go index e3513d8..e41d592 100644 --- a/cmd/gotestfmt/main.go +++ b/cmd/gotestfmt/main.go @@ -95,6 +95,7 @@ func main() { } ci := "" inputFile := "-" + formatter := "" hide := "" var showTestStatus bool @@ -122,6 +123,12 @@ func main() { showTestStatus, "Show the test status next to the icons (PASS, FAIL, SKIP).", ) + flag.StringVar( + &formatter, + "formatter", + formatter, + "Absolute path to an external program to format individual test output. This program will be called for each test case with a non-empty output and receive the test case output on stdin. It must produce the final output on stdout.", + ) flag.Parse() if ci != "" { @@ -143,6 +150,7 @@ func main() { } cfg.ShowTestStatus = showTestStatus + cfg.Formatter = formatter format, err := gotestfmt.New( dirs, diff --git a/renderer/renderer.go b/renderer/renderer.go index 833ef8b..60167fc 100644 --- a/renderer/renderer.go +++ b/renderer/renderer.go @@ -2,8 +2,13 @@ package renderer import ( "bytes" + "context" "fmt" + "os/exec" + "runtime" + "strings" "text/template" + "time" "github.com/haveyoudebuggedit/gotestfmt/v2/parser" ) @@ -93,9 +98,51 @@ type Package struct { Settings RenderSettings } +func formatTestOutput(testOutput string, cfg RenderSettings) string { + if cfg.Formatter == "" { + return testOutput + } + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + var shell []string + if runtime.GOOS == "windows" { + shell = []string{ + "cmd.exe", + "/C", + cfg.Formatter, + } + } else { + shell = []string{ + "/bin/bash", + "-c", + cfg.Formatter, + } + } + + stdout := &bytes.Buffer{} + stderr := &bytes.Buffer{} + + run := exec.CommandContext(ctx, shell[0], shell[1:]...) + run.Stdin = bytes.NewReader([]byte(testOutput)) + run.Stdout = stdout + run.Stderr = stderr + if err := run.Run(); err != nil { + panic(fmt.Errorf( + "failed to run test output formatter '%s', stderr was: %s (%w)", + strings.Join(shell, " "), + stderr.String(), + err, + )) + } + return stdout.String() +} + func renderTemplate(templateName string, templateText []byte, data interface{}) []byte { result := bytes.Buffer{} tpl := template.New(templateName) + tpl.Funcs(map[string]interface{}{ + "formatTestOutput": formatTestOutput, + }) tpl, err := tpl.Parse(string(templateText)) if err != nil { panic(fmt.Errorf("failed to parse template (%w)", err)) @@ -118,4 +165,6 @@ type RenderSettings struct { HideSuccessfulTests bool // ShowTestStatus adds words to indicate the test status next to the icons (PASS, FAIl, SKIP). ShowTestStatus bool + // Formatter is the path to an external program that is executed for each test output for format it. + Formatter string } diff --git a/testdata/logging b/testdata/logging new file mode 100644 index 0000000..d57194f --- /dev/null +++ b/testdata/logging @@ -0,0 +1,23 @@ +{"Time":"2022-01-07T12:03:22.543183249+01:00","Action":"run","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging"} +{"Time":"2022-01-07T12:03:22.543262565+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Output":"=== RUN TestGoLogging\n"} +{"Time":"2022-01-07T12:03:22.543278611+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Output":"=== PAUSE TestGoLogging\n"} +{"Time":"2022-01-07T12:03:22.543284348+01:00","Action":"pause","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging"} +{"Time":"2022-01-07T12:03:22.543289695+01:00","Action":"run","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog"} +{"Time":"2022-01-07T12:03:22.543295473+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"=== RUN TestKLog\n"} +{"Time":"2022-01-07T12:03:22.543301932+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"=== PAUSE TestKLog\n"} +{"Time":"2022-01-07T12:03:22.543307988+01:00","Action":"pause","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog"} +{"Time":"2022-01-07T12:03:22.543313716+01:00","Action":"cont","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging"} +{"Time":"2022-01-07T12:03:22.543319311+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Output":"=== CONT TestGoLogging\n"} +{"Time":"2022-01-07T12:03:22.54332638+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Output":" test_test.go:10: Hello world!\n"} +{"Time":"2022-01-07T12:03:22.54333562+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Output":"--- PASS: TestGoLogging (0.00s)\n"} +{"Time":"2022-01-07T12:03:22.543343368+01:00","Action":"pass","Package":"github.com/haveyoudebuggedit/example","Test":"TestGoLogging","Elapsed":0} +{"Time":"2022-01-07T12:03:22.543352152+01:00","Action":"cont","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog"} +{"Time":"2022-01-07T12:03:22.543358448+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"=== CONT TestKLog\n"} +{"Time":"2022-01-07T12:03:22.543364891+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"I0107 12:03:22.543194 228224 test_test.go:15] This is an info message\n"} +{"Time":"2022-01-07T12:03:22.543483254+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"W0107 12:03:22.543232 228224 test_test.go:16] This is a warning message\n"} +{"Time":"2022-01-07T12:03:22.543513075+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"E0107 12:03:22.543234 228224 test_test.go:17] This is an error message\n"} +{"Time":"2022-01-07T12:03:22.543521731+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Output":"--- PASS: TestKLog (0.00s)\n"} +{"Time":"2022-01-07T12:03:22.543526947+01:00","Action":"pass","Package":"github.com/haveyoudebuggedit/example","Test":"TestKLog","Elapsed":0} +{"Time":"2022-01-07T12:03:22.54353212+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Output":"PASS\n"} +{"Time":"2022-01-07T12:03:22.543555909+01:00","Action":"output","Package":"github.com/haveyoudebuggedit/example","Output":"ok \tgithub.com/haveyoudebuggedit/example\t0.001s\n"} +{"Time":"2022-01-07T12:03:22.543846378+01:00","Action":"pass","Package":"github.com/haveyoudebuggedit/example","Elapsed":0.002}