Enhance debugging output

Following on assertive debugging info cleanup, this revamp how we display failures.
- previously, every assert failure would receive the entire execution information  - we no longer do that and instead print out command information first, separately
- a lot of headers were printed about different stages (setup, cleanup), even when there was nothing done in these stages, resulting in a lot of noise
- the new display embraces a more structured, tabled output, that should significantly enhance legibility

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

Author: apostasie

mod/tigron/.golangci.yml

@@ -46,6 +46,7 @@ linters:
     - gomodguard      # we use depguard instead
     - ireturn         # too annoying with not enough value
     - lll             # provided by golines
+    - nestif          # already provided ten different ways with revive cognitive complexity, etc
     - nonamedreturns  # named returns are occasionally useful
     - prealloc        # premature optimization
     - promlinter      # no prometheus
@@ -64,7 +65,7 @@ linters:
           arguments: [60]
         - name: function-length
           # Default is 50, 75
-          arguments: [80, 160]
+          arguments: [80, 180]
         - name: cyclomatic
           # Default is 10
           arguments: [30]

mod/tigron/expect/comparators.go

@@ -30,59 +30,59 @@ import (
 
 // All can be used as a parameter for expected.Output to group a set of comparators.
 func All(comparators ...test.Comparator) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
 
 		for _, comparator := range comparators {
-			comparator(stdout, info, t)
+			comparator(stdout, "", t)
 		}
 	}
 }
 
 // Contains can be used as a parameter for expected.Output and ensures a comparison string is found contained in the
 // output.
 func Contains(compare string) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
-		assertive.Contains(assertive.WithFailLater(t), stdout, compare, info)
+		assertive.Contains(assertive.WithFailLater(t), stdout, compare, "Inspecting output (contains)")
 	}
 }
 
 // DoesNotContain is to be used for expected.Output to ensure a comparison string is NOT found in the output.
 func DoesNotContain(compare string) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
-		assertive.DoesNotContain(assertive.WithFailLater(t), stdout, compare, info)
+		assertive.DoesNotContain(assertive.WithFailLater(t), stdout, compare, "Inspecting output (does not contain)")
 	}
 }
 
 // Equals is to be used for expected.Output to ensure it is exactly the output.
 func Equals(compare string) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
-		assertive.IsEqual(assertive.WithFailLater(t), stdout, compare, info)
+		assertive.IsEqual(assertive.WithFailLater(t), stdout, compare, "Inspecting output (equals)")
 	}
 }
 
 // Match is to be used for expected.Output to ensure we match a regexp.
 func Match(reg *regexp.Regexp) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
-		assertive.Match(assertive.WithFailLater(t), stdout, reg, info)
+		assertive.Match(assertive.WithFailLater(t), stdout, reg, "Inspecting output (match)")
 	}
 }
 
 // JSON allows to verify that the output can be marshalled into T, and optionally can be further verified by a provided
 // method.
 func JSON[T any](obj T, verifier func(T, string, tig.T)) test.Comparator {
-	return func(stdout, info string, t *testing.T) {
+	return func(stdout, _ string, t *testing.T) {
 		t.Helper()
 
 		err := json.Unmarshal([]byte(stdout), &obj)
-		assertive.ErrorIsNil(assertive.WithFailLater(t), err, "failed to unmarshal JSON from stdout")
+		assertive.ErrorIsNil(assertive.WithFailLater(t), err, "Unmarshalling JSON from stdout must succeed")
 
 		if verifier != nil && err == nil {
-			verifier(obj, info, t)
+			verifier(obj, "Inspecting output (JSON)", t)
 		}
 	}
 }

mod/tigron/internal/assertive/assertive.go

@@ -31,12 +31,12 @@ import (
 	"github.com/containerd/nerdctl/mod/tigron/tig"
 )
 
-// TODO: once debugging output will be cleaned-up, reintroduce hexdump.
-
 const (
+	markLineLength           = 20
 	expectedSuccessDecorator = "✅️ does verify:\t\t"
-	expectedFailDecorator    = "❌ does not verify:\t"
+	expectedFailDecorator    = "❌ FAILED!\t\t"
 	receivedDecorator        = "👀 testing:\t\t"
+	annotationDecorator      = "🖊️"
 	hyperlinkDecorator       = "🔗"
 )
 
@@ -205,49 +205,79 @@ func evaluate(testing tig.T, isSuccess bool, actual, expected any, msg ...string
 func decorate(testing tig.T, isSuccess bool, actual, expected any, msg ...string) {
 	testing.Helper()
 
-	header := "\t"
+	if _, ok := testing.(*silentSuccess); !isSuccess || !ok {
+		head := strings.Repeat("<", markLineLength)
+		footer := strings.Repeat(">", markLineLength)
+		header := "\t"
 
-	hyperlink := getTopFrameFile()
-	if hyperlink != "" {
-		msg = append([]string{hyperlink + "\n"}, msg...)
-	}
+		custom := fmt.Sprintf("\t%s %s", annotationDecorator, strings.Join(msg, "\n"))
 
-	msg = append(msg, fmt.Sprintf("\t%s`%v`", receivedDecorator, actual))
+		msg = append([]string{"\n" + head}, custom)
 
-	if isSuccess {
-		msg = append(msg,
-			fmt.Sprintf("\t%s%v", expectedSuccessDecorator, expected),
-		)
-	} else {
-		msg = append(msg,
-			fmt.Sprintf("\t%s%v", expectedFailDecorator, expected),
-		)
-	}
+		hyperlink := getTopFrameFile()
+		if hyperlink != "" {
+			msg = append([]string{hyperlink}, msg...)
+		}
 
-	if _, ok := testing.(*silentSuccess); !isSuccess || !ok {
-		testing.Log(header + strings.Join(msg, "\n") + "\n")
+		msg = append(msg, fmt.Sprintf("\t%s`%v`", receivedDecorator, actual))
+
+		if isSuccess {
+			msg = append(msg,
+				fmt.Sprintf("\t%s%v", expectedSuccessDecorator, expected),
+			)
+		} else {
+			msg = append(msg,
+				fmt.Sprintf("\t%s%v", expectedFailDecorator, expected),
+			)
+		}
+
+		testing.Log(header + strings.Join(msg, "\n") + "\n" + footer + "\n")
 	}
 }
 
+// XXX FIXME #expert
+// Because of how golang testing works, the upper frame is the one from where t.Run is being called,
+// as (presumably) the passed function is starting with its own stack in a go routine.
+// In the case of subtests, t.Run being called from inside Tigron will make it so that the top frame
+// is case.go around line 233 (where we call Command.Run(), which is the one calling assertive).
+// To possibly address this:
+// plan a. just drop entirely OSC8 links and source extracts and trash all of this
+// plan b. get the top frame from the root test, and pass it to subtests on a custom property, the somehow into here
+// plan c. figure out a hack to call t.Run from the test file without ruining the Tigron UX
+// Dereference t.Run? Return a closure to be called from the top? w/o disabling inlining in the right place?
+// Short term, blacklisting /tigron (and /nerdtest) will at least prevent the wrong links from appearing in the output.
 func getTopFrameFile() string {
-	// Get the frames.
+	// Get the frames. Skip the first two frames - current one and caller.
 	//nolint:mnd // Whatever mnd...
-	pc := make([]uintptr, 20)
+	pc := make([]uintptr, 40)
 	//nolint:mnd // Whatever mnd...
 	n := runtime.Callers(2, pc)
 	callersFrames := runtime.CallersFrames(pc[:n])
 
-	var file string
+	var (
+		file       string
+		lineNumber int
+		frame      runtime.Frame
+	)
 
-	var lineNumber int
+	more := true
+	for more {
+		frame, more = callersFrames.Next()
 
-	var frame runtime.Frame
-	for range 20 {
-		frame, _ = callersFrames.Next()
+		// Once we are in the go main stack, bail out
 		if !strings.Contains(frame.Function, "/") {
 			break
 		}
 
+		// XXX see note above
+		if strings.Contains(frame.File, "/tigron") {
+			continue
+		}
+
+		if strings.Contains(frame.File, "/nerdtest") {
+			continue
+		}
+
 		file = frame.File
 		lineNumber = frame.Line
 	}
@@ -282,6 +312,6 @@ func getTopFrameFile() string {
 	return hyperlinkDecorator + " " + (&formatter.OSC8{
 		Text:     line,
 		Location: "file://" + file,
-		Line:     frame.Line,
+		Line:     lineNumber,
 	}).String()
 }

mod/tigron/internal/com/command_test.go

@@ -372,7 +372,9 @@ func TestTimeoutDelayed(t *testing.T) {
 	assertive.ErrorIsNil(t, err, "Err")
 
 	start := time.Now()
+
 	time.Sleep(2 * time.Second)
+
 	res, err := command.Wait()
 	end := time.Now()
 

mod/tigron/internal/formatter/formatter.go

@@ -64,32 +64,26 @@ func chunk(s string, length int) []string {
 // Maybe the csv writer could be cheat-used to get the right widths.
 //
 //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))
+		output += fmt.Sprintf("+%s+\n", strings.Repeat(mark, maxLineLength-2))
 
 		if utf8.RuneCountInString(key) > kMaxLength {
 			key = string([]rune(key)[:kMaxLength-3]) + "..."
 		}
 
 		for _, line := range chunk(value, maxLineLength-kMaxLength-7) {
-			output += fmt.Sprintf(
-				"| %-*s | %-*s |\n",
-				kMaxLength,
-				key,
-				maxLineLength-kMaxLength-7,
-				line,
-			)
+			output += fmt.Sprintf("| %-*s | %-*s |\n", kMaxLength, key, maxLineLength-kMaxLength-7, line)
 			key = ""
 		}
 	}
 
-	output += fmt.Sprintf("+%s+", strings.Repeat("-", maxLineLength-2))
+	output += fmt.Sprintf("+%s+", strings.Repeat(mark, maxLineLength-2))
 
 	return output
 }

mod/tigron/internal/mimicry/mocker.go

@@ -137,8 +137,7 @@ func (mi *Core) Register(fun, handler any) {
 
 func getFunID(fun any) string {
 	// The point of keeping only the func name is to avoid type mismatch dependent on what interface
-	// is used by the
-	// consumer.
+	// is used by the consumer.
 	origin := runtime.FuncForPC(reflect.ValueOf(fun).Pointer()).Name()
 	seg := strings.Split(origin, ".")
 	origin = seg[len(seg)-1]

mod/tigron/internal/mimicry/print.go

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