Enhanced test debug information

Finishing prior effort to make test run easier to debug, this introduces a number of changes to the output:
- high-contrast emojis to make it easier to spot relevant sections
- 2 columns table formatting for commands informations
- better spacing
- lifecycle sections (cleanup, setup, run)
- clearly called out assertive output

Signed-off-by: apostasie <[email protected]>

Author: apostasie

mod/tigron/.golangci.yml

@@ -37,6 +37,7 @@ linters:
     - cyclop            # provided by revive
     - exhaustruct       # does not serve much of a purpose
     - errcheck          # provided by revive
+    - errchkjson        # forces handling of json err (eg: prevents _), which is too much
     - forcetypeassert   # provided by revive
     - funlen            # provided by revive
     - gocognit          # provided by revive
@@ -65,7 +66,7 @@ linters:
           arguments: [60]
         - name: function-length
           # Default is 50, 75
-          arguments: [80, 180]
+          arguments: [80, 200]
         - name: cyclomatic
           # Default is 10
           arguments: [30]
@@ -93,11 +94,17 @@ linters:
           files:
             - $all
           allow:
+            # Allowing go standard library and tigron itself
             - $gostd
             - github.com/containerd/nerdctl/mod/tigron
+            # We use creack as our base for pty
             - github.com/creack/pty
+            # Used for display width computation in internal/formatter
+            - golang.org/x/text/width
+            # errgroups and term (make raw) are used by internal/pipes
             - golang.org/x/sync
             - golang.org/x/term
+            # EXPERIMENTAL: for go routines leakage detection
             - go.uber.org/goleak
     staticcheck:
       checks:

mod/tigron/go.mod

@@ -5,8 +5,9 @@ go 1.23.0
 require (
 	github.com/creack/pty v1.1.24
 	go.uber.org/goleak v1.3.0
-	golang.org/x/sync v0.12.0
+	golang.org/x/sync v0.13.0
 	golang.org/x/term v0.30.0
+	golang.org/x/text v0.24.0
 )
 
 require golang.org/x/sys v0.31.0 // indirect

mod/tigron/go.sum

@@ -8,11 +8,13 @@ github.com/stretchr/testify v1.8.0 h1:pSgiaMZlXftHpm5L7V1+rVB+AZJydKsMxsQBIJw4PK
 github.com/stretchr/testify v1.8.0/go.mod h1:yNjHg4UonilssWZ8iaSj1OCr/vHnekPRkoO+kdMU+MU=
 go.uber.org/goleak v1.3.0 h1:2K3zAYmnTNqV73imy9J1T3WC+gmCePx2hEGkimedGto=
 go.uber.org/goleak v1.3.0/go.mod h1:CoHD4mav9JJNrW/WLlf7HGZPjdw8EucARQHekz1X6bE=
-golang.org/x/sync v0.12.0 h1:MHc5BpPuC30uJk597Ri8TV3CNZcTLu6B6z4lJy+g6Jw=
-golang.org/x/sync v0.12.0/go.mod h1:1dzgHSNfp02xaA81J2MS99Qcpr2w7fw1gpm99rleRqA=
+golang.org/x/sync v0.13.0 h1:AauUjRAJ9OSnvULf/ARrrVywoJDy0YS2AwQ98I37610=
+golang.org/x/sync v0.13.0/go.mod h1:1dzgHSNfp02xaA81J2MS99Qcpr2w7fw1gpm99rleRqA=
 golang.org/x/sys v0.31.0 h1:ioabZlmFYtWhL+TRYpcnNlLwhyxaM9kWTDEmfnprqik=
 golang.org/x/sys v0.31.0/go.mod h1:BJP2sWEmIv4KK5OTEluFJCKSidICx8ciO85XgH3Ak8k=
 golang.org/x/term v0.30.0 h1:PQ39fJZ+mfadBm0y5WlL4vlM7Sx1Hgf13sMIY2+QS9Y=
 golang.org/x/term v0.30.0/go.mod h1:NYYFdzHoI5wRh/h5tDMdMqCqPJZEuNqVR5xJLd/n67g=
+golang.org/x/text v0.24.0 h1:dd5Bzh4yt5KYA8f9CJHCP4FB4D51c2c6JvN37xJJkJ0=
+golang.org/x/text v0.24.0/go.mod h1:L8rBsPeo2pSS+xqN0d5u2ikmjtmoJbDBT1b7nHvFCdU=
 gopkg.in/yaml.v3 v3.0.1 h1:fxVm/GzAzEWqLHuvctI91KS9hhNmmWOoWu0XTYJS7CA=
 gopkg.in/yaml.v3 v3.0.1/go.mod h1:K4uyk7z7BCEPqu6E+C64Yfv1cQ7kz7rIZviUmN+EgEM=

mod/tigron/internal/formatter/formatter.go

@@ -19,77 +19,99 @@ package formatter
 import (
 	"fmt"
 	"strings"
-	"unicode/utf8"
+
+	"golang.org/x/text/width"
 )
 
 const (
 	maxLineLength = 110
 	maxLines      = 100
 	kMaxLength    = 7
+	spacer        = " "
 )
 
-func chunk(s string, length int) []string {
-	var chunks []string
-
-	lines := strings.Split(s, "\n")
-
-	for x := 0; x < maxLines && x < len(lines); x++ {
-		line := lines[x]
-		if utf8.RuneCountInString(line) < length {
-			chunks = append(chunks, line)
-
-			continue
-		}
-
-		for index := 0; index < utf8.RuneCountInString(line); index += length {
-			end := index + length
-			if end > utf8.RuneCountInString(line) {
-				end = utf8.RuneCountInString(line)
-			}
-
-			chunks = append(chunks, string([]rune(line)[index:end]))
-		}
-	}
-
-	if len(chunks) == maxLines {
-		chunks = append(chunks, "...")
-	}
-
-	return chunks
-}
-
-// Table formats a `n x 2` dataset into a series of rows.
-// FIXME: the problem with full-width emoji is that they are going to eff-up the maths and display
-// here...
-// Maybe the csv writer could be cheat-used to get the right widths.
+// Table formats a `n x 2` dataset into a series of n rows by 2 columns.
 //
 //nolint:mnd // Too annoying
-func Table(data [][]any) string {
+func Table(data [][]any, mark string) string {
 	var output string
 
 	for _, row := range data {
 		key := fmt.Sprintf("%v", row[0])
 		value := strings.ReplaceAll(fmt.Sprintf("%v", row[1]), "\t", "  ")
 
-		output += fmt.Sprintf("+%s+\n", strings.Repeat("-", maxLineLength-2))
-
-		if utf8.RuneCountInString(key) > kMaxLength {
-			key = string([]rune(key)[:kMaxLength-3]) + "..."
-		}
+		output += fmt.Sprintf("+%s+\n", strings.Repeat(mark, maxLineLength-2))
 
-		for _, line := range chunk(value, maxLineLength-kMaxLength-7) {
+		for _, line := range chunk(value, maxLineLength-kMaxLength-7, maxLines) {
 			output += fmt.Sprintf(
-				"| %-*s | %-*s |\n",
-				kMaxLength,
-				key,
-				maxLineLength-kMaxLength-7,
+				"| %s | %s |\n",
+				// Keys longer than one line of kMaxLength will be striped to one line
+				chunk(key, kMaxLength, 1)[0],
 				line,
 			)
 			key = ""
 		}
 	}
 
-	output += fmt.Sprintf("+%s+", strings.Repeat("-", maxLineLength-2))
+	output += fmt.Sprintf("+%s+", strings.Repeat(mark, maxLineLength-2))
 
 	return output
 }
+
+// chunk does take a string and split it in lines of maxLength size, accounting for characters display width.
+func chunk(s string, maxLength, maxLines int) []string {
+	chunks := []string{}
+
+	runes := []rune(s)
+
+	size := 0
+	start := 0
+
+	for index := range runes {
+		var segment string
+
+		switch width.LookupRune(runes[index]).Kind() {
+		case width.EastAsianWide, width.EastAsianFullwidth:
+			size += 2
+		case width.EastAsianAmbiguous, width.Neutral, width.EastAsianHalfwidth, width.EastAsianNarrow:
+			size++
+		default:
+			size++
+		}
+
+		switch {
+		case runes[index] == '\n':
+			// Met a line-break. Pad to size (removing the line break)
+			segment = string(runes[start:index])
+			segment += strings.Repeat(spacer, maxLength-size+1)
+			start = index + 1
+			size = 0
+		case size == maxLength:
+			// Line is full. Add the segment.
+			segment = string(runes[start : index+1])
+			start = index + 1
+			size = 0
+		case size > maxLength:
+			// Last char was double width. Push it back to next line, and pad with a single space.
+			segment = string(runes[start:index]) + spacer
+			start = index
+			size = 2
+		case index == len(runes)-1:
+			// End of string. Pad it to size.
+			segment = string(runes[start : index+1])
+			segment += strings.Repeat(spacer, maxLength-size)
+		default:
+			continue
+		}
+
+		chunks = append(chunks, segment)
+	}
+
+	if len(chunks) > maxLines {
+		chunks = append(chunks[0:maxLines], "...")
+	} else if len(chunks) == 0 {
+		chunks = []string{strings.Repeat(spacer, maxLength)}
+	}
+
+	return chunks
+}

mod/tigron/internal/mimicry/print.go

@@ -40,7 +40,7 @@ func PrintCall(call *Call) string {
 	}
 
 	output := []string{
-		formatter.Table(debug),
+		formatter.Table(debug, "-"),
 		sectionSeparator,
 	}
 

mod/tigron/test/case.go

@@ -17,10 +17,13 @@
 package test
 
 import (
+	"encoding/json"
+	"fmt"
 	"slices"
 	"testing"
 
 	"github.com/containerd/nerdctl/mod/tigron/internal/assertive"
+	"github.com/containerd/nerdctl/mod/tigron/internal/formatter"
 )
 
 // Case describes an entire test-case, including data, setup and cleanup routines, command and
@@ -62,27 +65,33 @@ type Case struct {
 	parent  *Case
 }
 
+const (
+	startDecorator  = "🚀"
+	cleanDecorator  = "🧽"
+	setupDecorator  = "🏗"
+	subinDecorator  = "⤵️"
+	suboutDecorator = "↩️"
+)
+
 // Run prepares and executes the test, and any possible subtests.
-//
-//nolint:gocognit
 func (test *Case) Run(t *testing.T) {
 	t.Helper()
 	// Run the test
 	//nolint:thelper
 	testRun := func(subT *testing.T) {
 		subT.Helper()
 
-		assertive.True(subT, test.t == nil, "You cannot run a test multiple times")
+		silentT := assertive.WithSilentSuccess(subT)
+
+		assertive.True(silentT, test.t == nil, "You cannot run a test multiple times")
+		assertive.True(silentT, test.Description != "" || test.parent == nil,
+			"A subtest description cannot be empty")
+		assertive.True(silentT, test.Command == nil || test.Expected != nil,
+			"Expectations for a test command cannot be nil. You may want to use `Setup` instead"+
+				"of `Command`.")
 
 		// Attach testing.T
 		test.t = subT
-		assertive.True(
-			test.t,
-			test.Description != "" || test.parent == nil,
-			"A test description cannot be empty",
-		)
-		assertive.True(test.t, test.Command == nil || test.Expected != nil,
-			"Expectations for a test command cannot be nil. You may want to use Setup instead.")
 
 		// Ensure we have env
 		if test.Env == nil {
@@ -168,49 +177,83 @@ func (test *Case) Run(t *testing.T) {
 		}
 
 		// Execute cleanups now
-		test.t.Log("")
-		test.t.Log("======================== Pre-test cleanup ========================")
-
-		for _, cleanup := range cleanups {
-			cleanup(test.Data, test.helpers)
-		}
-
-		// Register the cleanups, in reverse
-		test.t.Cleanup(func() {
-			test.t.Log("")
-			test.t.Log("======================== Post-test cleanup ========================")
-
-			slices.Reverse(cleanups)
+		if len(cleanups) > 0 {
+			test.t.Log(
+				"\n\n" + formatter.Table(
+					[][]any{{cleanDecorator, fmt.Sprintf("%q: initial cleanup", test.t.Name())}},
+					"=",
+				) + "\n",
+			)
 
 			for _, cleanup := range cleanups {
 				cleanup(test.Data, test.helpers)
 			}
-		})
 
-		// Run the setups
-		test.t.Log("")
-		test.t.Log("======================== Test setup ========================")
+			// Register the cleanups, in reverse
+			test.t.Cleanup(func() {
+				test.t.Helper()
+				test.t.Log(
+					"\n\n" + formatter.Table(
+						[][]any{{cleanDecorator, fmt.Sprintf("%q: post-cleanup", test.t.Name())}},
+						"=",
+					) + "\n",
+				)
+
+				slices.Reverse(cleanups)
 
-		for _, setup := range setups {
-			setup(test.Data, test.helpers)
+				for _, cleanup := range cleanups {
+					cleanup(test.Data, test.helpers)
+				}
+			})
+		}
+
+		// Run the setups
+		if len(setups) > 0 {
+			test.t.Log(
+				"\n\n" + formatter.Table(
+					[][]any{{setupDecorator, fmt.Sprintf("%q: setup", test.t.Name())}},
+					"=",
+				) + "\n",
+			)
+
+			for _, setup := range setups {
+				setup(test.Data, test.helpers)
+			}
 		}
 
 		// Run the command if any, with expectations
 		// Note: if we have a command, we already know we DO have Expected
-		test.t.Log("")
-		test.t.Log("======================== Test Run ========================")
-
 		if test.Command != nil {
-			test.Command(test.Data, test.helpers).Run(test.Expected(test.Data, test.helpers))
+			cmd := test.Command(test.Data, test.helpers)
+
+			debugConfig, _ := json.MarshalIndent(test.Config.(*config).config, "", "  ")
+			debugData, _ := json.MarshalIndent(test.Data.(*data).labels, "", "  ")
+
+			test.t.Log(
+				"\n\n" + formatter.Table(
+					[][]any{
+						{startDecorator, fmt.Sprintf("%q: starting test!", test.t.Name())},
+						{"cwd", test.Data.TempDir()},
+						{"config", string(debugConfig)},
+						{"data", string(debugData)},
+					},
+					"=",
+				) + "\n",
+			)
+
+			cmd.Run(test.Expected(test.Data, test.helpers))
 		}
 
-		// Now go for the subtests
-		test.t.Log("")
-		test.t.Log("======================== Processing subtests ========================")
+		if len(test.SubTests) > 0 {
+			// Now go for the subtests
+			test.t.Logf("\n%s️ %q: into subtests prep", subinDecorator, test.t.Name())
+
+			for _, subTest := range test.SubTests {
+				subTest.parent = test
+				subTest.Run(test.t)
+			}
 
-		for _, subTest := range test.SubTests {
-			subTest.parent = test
-			subTest.Run(test.t)
+			test.t.Logf("\n%s️ %q: done with subtests prep", suboutDecorator, test.t.Name())
 		}
 	}