Add [Late] test to collect CRI-O goroutine dumps via SIGUSR1

This test runs after all other tests to capture CRI-O's goroutine state
on every node, providing visibility into stuck operations after the
suite has exercised CRI-O under load.

The test sends SIGUSR1 to CRI-O on each node, reads the resulting
goroutine dump from /tmp/crio-goroutine-stacks-*.log, and fails hard
if any goroutine is stuck in an image pull (IO wait > 30 min in
docker.(*bodyReader).Read -> net.(*conn).Read).

Signed-off-by: Ayato Tokubi <atokubi@redhat.com>

Author: bitoku

test/extended/node/crio_goroutinedump.go

@@ -0,0 +1,149 @@
+package node
+
+import (
+	"fmt"
+	"regexp"
+	"strconv"
+	"strings"
+
+	g "github.com/onsi/ginkgo/v2"
+	o "github.com/onsi/gomega"
+	ote "github.com/openshift-eng/openshift-tests-extension/pkg/ginkgo"
+	exutil "github.com/openshift/origin/test/extended/util"
+)
+
+// goroutineHeaderRe matches Go goroutine dump headers, e.g.:
+//
+//	goroutine 64418 [IO wait, 189 minutes]:
+//	goroutine 1 [running]:
+var goroutineHeaderRe = regexp.MustCompile(`goroutine \d+ \[`)
+
+// ioWaitDurationRe extracts the wait duration in minutes from an IO wait goroutine header, e.g.:
+//
+//	goroutine 64418 [IO wait, 189 minutes]:
+var ioWaitDurationRe = regexp.MustCompile(`goroutine \d+ \[IO wait, (\d+) minutes\]:`)
+
+// findStuckImagePulls checks a goroutine dump for goroutines that indicate
+// a stuck image pull: IO wait > 30 minutes with net.(*conn).Read called by
+// image/v5/docker.(*bodyReader).Read.
+func findStuckImagePulls(dump string) []string {
+	// Split the dump into individual goroutine blocks.
+	// Each block starts with "goroutine <id> [".
+	blocks := goroutineHeaderRe.Split(dump, -1)
+	headers := goroutineHeaderRe.FindAllString(dump, -1)
+
+	var stuck []string
+	for i, header := range headers {
+		block := header + blocks[i+1]
+
+		// Check: state is "IO wait" with duration > 30 minutes
+		match := ioWaitDurationRe.FindStringSubmatch(block)
+		if match == nil {
+			continue
+		}
+		minutes, err := strconv.Atoi(match[1])
+		if err != nil || minutes <= 30 {
+			continue
+		}
+
+		// Check: stack contains net.(*conn).Read
+		connReadIdx := strings.Index(block, "net.(*conn).Read")
+		if connReadIdx < 0 {
+			continue
+		}
+
+		// Check: image/v5/docker.(*bodyReader).Read appears as an
+		// ascendant (caller) of net.(*conn).Read. In a goroutine dump
+		// callers appear below callees, so bodyReader must come after
+		// conn.Read in the text.
+		bodyReaderIdx := strings.Index(block, "image/v5/docker.(*bodyReader).Read")
+		if bodyReaderIdx < 0 || bodyReaderIdx <= connReadIdx {
+			continue
+		}
+
+		stuck = append(stuck, strings.TrimSpace(block))
+	}
+	return stuck
+}
+
+var _ = g.Describe("[sig-node][Late]", func() {
+	defer g.GinkgoRecover()
+	oc := exutil.NewCLIWithoutNamespace("crio-goroutine-dump")
+
+	g.It("CRI-O should report goroutine stacks on all nodes",
+		ote.Informing(), func(ctx g.SpecContext) {
+
+			nodes, err := exutil.GetAllClusterNodes(oc)
+			o.Expect(err).NotTo(o.HaveOccurred())
+			o.Expect(nodes).NotTo(o.BeEmpty(), "expected at least one node")
+
+			// Send SIGUSR1 to CRI-O and read the newly created dump file.
+			// CRI-O writes goroutine stacks to /tmp/crio-goroutine-stacks-<timestamp>.log.
+			// We snapshot existing files before signalling and wait for a new one
+			// to appear, avoiding stale reads from previous runs.
+			shellCmd := `CRIO_PID=$(pgrep -x crio 2>/dev/null) && \
+if [ -z "$CRIO_PID" ]; then echo "CRIO_NOT_FOUND"; exit 0; fi && \
+MARKER=$(mktemp) && \
+kill -USR1 $CRIO_PID && \
+for i in $(seq 1 10); do \
+  NEW=$(find /tmp -maxdepth 1 -name 'crio-goroutine-stacks-*.log' -newer "$MARKER" 2>/dev/null | head -1) && \
+  if [ -n "$NEW" ]; then rm -f "$MARKER"; cat "$NEW"; exit 0; fi; \
+  sleep 1; \
+done && \
+rm -f "$MARKER" && echo "DUMP_TIMEOUT" && exit 1`
+
+			var dumps []string
+			var stuckPulls []string
+			var failedNodes []string
+			for _, node := range nodes {
+				g.By(fmt.Sprintf("Sending SIGUSR1 to CRI-O on node %s", node.Name))
+
+				output, err := exutil.DebugNodeRetryWithOptionsAndChroot(
+					oc, node.Name, "default",
+					"sh", "-c", shellCmd,
+				)
+				if err != nil {
+					failedNodes = append(failedNodes,
+						fmt.Sprintf("%s: debug pod failed: %v", node.Name, err))
+					continue
+				}
+
+				if strings.Contains(output, "CRIO_NOT_FOUND") {
+					failedNodes = append(failedNodes,
+						fmt.Sprintf("%s: CRI-O process not found", node.Name))
+					continue
+				}
+
+				if strings.Contains(output, "DUMP_TIMEOUT") {
+					failedNodes = append(failedNodes,
+						fmt.Sprintf("%s: timed out waiting for new goroutine dump file", node.Name))
+					continue
+				}
+
+				o.Expect(goroutineHeaderRe.MatchString(output)).To(o.BeTrue(),
+					"expected goroutine stacks in CRI-O dump from node %s, got:\n%s", node.Name, output)
+
+				dumps = append(dumps, fmt.Sprintf("=== node/%s ===\n%s", node.Name, output))
+
+				for _, goroutine := range findStuckImagePulls(output) {
+					stuckPulls = append(stuckPulls, fmt.Sprintf("node/%s:\n%s", node.Name, goroutine))
+				}
+			}
+
+			// Fail if any node did not produce a dump
+			o.Expect(failedNodes).To(o.BeEmpty(),
+				"failed to collect CRI-O goroutine dump from nodes:\n%s",
+				strings.Join(failedNodes, "\n"))
+
+			// Fail hard if any goroutine is stuck in an image pull
+			o.Expect(stuckPulls).To(o.BeEmpty(),
+				"found CRI-O goroutines stuck in image pull (IO wait > 30 min):\n%s",
+				strings.Join(stuckPulls, "\n\n"))
+
+			// Always fail so goroutine dumps are visible in test results.
+			// The test is marked Informing so this won't block merges.
+			if len(dumps) > 0 {
+				g.Fail(fmt.Sprintf("CRI-O goroutine dumps collected:\n%s", strings.Join(dumps, "\n\n")))
+			}
+		})
+})