Fixes #30: Test output formatter (#31)

.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:

.gotestfmt/github/package.gotpl

@@ -43,7 +43,7 @@ we are creating a stylized header for each package.
                 {{- "\n" -}}
 
                 {{- with .Output -}}
-                    {{- . -}}
+                    {{- formatTestOutput . $settings -}}
                     {{- "\n" -}}
                 {{- end -}}
 

.gotestfmt/gitlab/package.gotpl

@@ -41,7 +41,7 @@ we are creating a stylized header for each package.
                 {{- "\n" -}}
 
                 {{- with .Output -}}
-                    {{- . -}}
+                    {{- formatTestOutput . $settings -}}
                     {{- "\n" -}}
                 {{- end -}}
 

.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 -}}

.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" -}}

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).

_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

_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=

_testsource/logging/test.go

@@ -0,0 +1 @@
+package logging

_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")
+}

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)
+		}
+	}
+}

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,

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
 }

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}