hs-test: logging improvements

Type: test

Change-Id: Iffefe085e846b6ba614b0d74c4ba9907080a9a59
Signed-off-by: Adrian Villin <avillin@cisco.com>

14 files changed, 125 insertions, 31 deletions

diff --git a/.gitignore b/.gitignore
index 5c707a8364a..5537f0dd791 100644
--- a/.gitignore
+++ b/.gitignore
@@ -123,6 +123,7 @@ compile_commands.json
 /extras/hs-test/hs-test
 /extras/hs-test/http_server
 /extras/hs-test/.build.ok
+/extras/hs-test/summary/
 
 # ./configure
 /CMakeFiles
diff --git a/Makefile b/Makefile
index edd632e42d5..6675b510153 100644
--- a/Makefile
+++ b/Makefile
@@ -86,6 +86,7 @@ DEB_DEPENDS += nasm
 DEB_DEPENDS += iperf ethtool  # for 'make test TEST=vm_vpp_interfaces'
 DEB_DEPENDS += libpcap-dev
 DEB_DEPENDS += tshark
+DEB_DEPENDS += jq # for extracting test summary from .json report (hs-test)
 
 LIBFFI=libffi6 # works on all but 20.04 and debian-testing
 
diff --git a/extras/hs-test/Makefile b/extras/hs-test/Makefile
index 54b95c3d1cd..6ee89bc2770 100644
--- a/extras/hs-test/Makefile
+++ b/extras/hs-test/Makefile
@@ -95,9 +95,11 @@ build-vpp-debug:
 
 .PHONY: test
 test: .deps.ok .build.ok
-	@bash ./test --persist=$(PERSIST) --verbose=$(VERBOSE) \
+	-bash ./test --persist=$(PERSIST) --verbose=$(VERBOSE) \
 		--unconfigure=$(UNCONFIGURE) --debug=$(DEBUG) --test=$(TEST) --cpus=$(CPUS) \
 		--vppsrc=$(VPPSRC) --parallel=$(PARALLEL) --repeat=$(REPEAT)
+	$(call jq-summary)
+	@bash ./script/compress.sh
 
 .PHONY: test-debug
 test-debug: .deps.ok .build_debug.ok
@@ -142,3 +144,7 @@ install-deps:
 fixstyle:
 	@gofmt -w .
 	@go mod tidy
+
+# splitting this into multiple lines breaks the command
+jq-summary = @jq -r '.[0] | .SpecReports[] | select(.State == "failed") | select(.Failure != null) | "TestName: \(.LeafNodeText)\nMessage:\n\(.Failure.Message)\n Full Stack Trace:\n\(.Failure.Location.FullStackTrace)\n"' summary/report.json > summary/failed-summary.log \
+	&& echo "Summary generated -> failed-summary.log"
diff --git a/extras/hs-test/container.go b/extras/hs-test/container.go
index c82f1fc03a7..45f41d26a87 100644
--- a/extras/hs-test/container.go
+++ b/extras/hs-test/container.go
@@ -77,7 +77,7 @@ func newContainer(suite *HstSuite, yamlInput ContainerConfig) (*Container, error
 	}
 
 	if _, ok := yamlInput["volumes"]; ok {
-		workingVolumeDir := logDir + CurrentSpecReport().LeafNodeText + container.suite.pid + volumeDir
+		workingVolumeDir := logDir + CurrentSpecReport().LeafNodeText + volumeDir
 		workDirReplacer := strings.NewReplacer("$HST_DIR", workDir)
 		volDirReplacer := strings.NewReplacer("$HST_VOLUME_DIR", workingVolumeDir)
 		for _, volu := range yamlInput["volumes"].([]interface{}) {
diff --git a/extras/hs-test/hst_suite.go b/extras/hs-test/hst_suite.go
index bb499246bf9..725fee73f24 100644
--- a/extras/hs-test/hst_suite.go
+++ b/extras/hs-test/hst_suite.go
@@ -5,7 +5,8 @@ import (
 	"errors"
 	"flag"
 	"fmt"
-	"log/slog"
+	"io"
+	"log"
 	"os"
 	"os/exec"
 	"strings"
@@ -39,9 +40,17 @@ type HstSuite struct {
 	cpuContexts      []*CpuContext
 	cpuPerVpp        int
 	pid              string
+	logger			 *log.Logger
+	logFile			 *os.File
 }
 
 func (s *HstSuite) SetupSuite() {
+	s.createLogger()
+	s.log("Suite Setup")
+	RegisterFailHandler(func(message string, callerSkip ...int) {
+		s.hstFail()
+		Fail(message, callerSkip...)
+	})
 	var err error
 	s.pid = fmt.Sprint(os.Getpid())
 	s.cpuAllocator, err = CpuAllocator()
@@ -63,10 +72,13 @@ func (s *HstSuite) AddCpuContext(cpuCtx *CpuContext) {
 }
 
 func (s *HstSuite) TearDownSuite() {
+	defer s.logFile.Close()
+	s.log("Suite Teardown")
 	s.unconfigureNetworkTopology()
 }
 
 func (s *HstSuite) TearDownTest() {
+	s.log("Test Teardown")
 	if *isPersistent {
 		return
 	}
@@ -85,10 +97,7 @@ func (s *HstSuite) skipIfUnconfiguring() {
 }
 
 func (s *HstSuite) SetupTest() {
-	RegisterFailHandler(func(message string, callerSkip ...int) {
-		s.hstFail()
-		Fail(message, callerSkip...)
-	})
+	s.log("Test Setup")
 	s.skipIfUnconfiguring()
 	s.setupVolumes()
 	s.setupContainers()
@@ -110,7 +119,7 @@ func (s *HstSuite) setupContainers() {
 	}
 }
 
-func logVppInstance(container *Container, maxLines int) {
+func (s *HstSuite) logVppInstance(container *Container, maxLines int) {
 	if container.vppInstance == nil {
 		return
 	}
@@ -136,26 +145,26 @@ func logVppInstance(container *Container, maxLines int) {
 		}
 	}
 
-	fmt.Println("vvvvvvvvvvvvvvv " + container.name + " [VPP instance]:")
+	s.log("vvvvvvvvvvvvvvv " + container.name + " [VPP instance]:")
 	for _, line := range lines {
-		fmt.Println(line)
+		s.log(line)
 	}
-	fmt.Printf("^^^^^^^^^^^^^^^\n\n")
+	s.log("^^^^^^^^^^^^^^^\n\n")
 }
 
 func (s *HstSuite) hstFail() {
-	fmt.Println("Containers: " + fmt.Sprint(s.containers))
+	s.log("Containers: " + fmt.Sprint(s.containers))
 	for _, container := range s.containers {
 		out, err := container.log(20)
 		if err != nil {
 			fmt.Printf("An error occured while obtaining '%s' container logs: %s\n", container.name, fmt.Sprint(err))
 			continue
 		}
-		fmt.Printf("\nvvvvvvvvvvvvvvv " +
+		s.log("\nvvvvvvvvvvvvvvv " +
 			container.name + ":\n" +
 			out +
 			"^^^^^^^^^^^^^^^\n\n")
-		logVppInstance(container, 20)
+		s.logVppInstance(container, 20)
 	}
 }
 
@@ -187,9 +196,25 @@ func (s *HstSuite) assertNotEmpty(object interface{}, msgAndArgs ...interface{})
 	Expect(object).ToNot(BeEmpty(), msgAndArgs...)
 }
 
+func (s *HstSuite) createLogger(){
+	suiteName := CurrentSpecReport().ContainerHierarchyTexts[0]
+	var err error
+	s.logFile, err = os.Create("summary/" + suiteName + ".log")
+	if err != nil {
+		Fail("Unable to create log file.")
+	}
+	s.logger = log.New(io.Writer(s.logFile), "", log.LstdFlags)
+}
+
+// Logs to files by default, logs to stdout when VERBOSE=true with GinkgoWriter
+// to keep console tidy
 func (s *HstSuite) log(arg any) {
+	logs := strings.Split(fmt.Sprint(arg), "\n")
+	for _, line := range logs {
+		s.logger.Println(line)
+	}
 	if *isVerbose {
-		slog.Info(fmt.Sprint(arg))
+		GinkgoWriter.Println(arg)
 	}
 }
 
@@ -266,7 +291,7 @@ func (s *HstSuite) loadContainerTopology(topologyName string) {
 	for _, elem := range yamlTopo.Volumes {
 		volumeMap := elem["volume"].(VolumeConfig)
 		hostDir := volumeMap["host-dir"].(string)
-		workingVolumeDir := logDir + CurrentSpecReport().LeafNodeText + s.pid + volumeDir
+		workingVolumeDir := logDir + CurrentSpecReport().LeafNodeText + volumeDir
 		volDirReplacer := strings.NewReplacer("$HST_VOLUME_DIR", workingVolumeDir)
 		hostDir = volDirReplacer.Replace(hostDir)
 		s.volumes = append(s.volumes, hostDir)
diff --git a/extras/hs-test/raw_session_test.go b/extras/hs-test/raw_session_test.go
index cf74c62cd3e..5c66df0b1ce 100644
--- a/extras/hs-test/raw_session_test.go
+++ b/extras/hs-test/raw_session_test.go
@@ -1,16 +1,15 @@
 package main
 
 func init() {
-	registerVethTests(VppEchoQuicTest, VppEchoTcpTest, VppEchoUdpTest)
+	registerVethTests(VppEchoQuicTest, VppEchoTcpTest)
 }
 
 func VppEchoQuicTest(s *VethsSuite) {
 	s.testVppEcho("quic")
 }
 
-// udp echo currently broken in vpp, skipping
+// TODO: udp echo currently broken in vpp
 func VppEchoUdpTest(s *VethsSuite) {
-	s.skip("Broken")
 	s.testVppEcho("udp")
 }
 
diff --git a/extras/hs-test/script/compress.sh b/extras/hs-test/script/compress.sh
new file mode 100644
index 00000000000..92a2fbd6789
--- /dev/null
+++ b/extras/hs-test/script/compress.sh
@@ -0,0 +1,34 @@
+#!/usr/bin/env bash
+
+if [ "${COMPRESS_FAILED_TEST_LOGS}" == "yes" -a -s "${HS_SUMMARY}/failed-summary.log" ]
+then
+    echo -n "Copying docker logs..."
+    dirs=$(jq -r '.[0] | .SpecReports[] | select(.State == "failed") | .LeafNodeText' ${HS_SUMMARY}/report.json)
+    for dirName in $dirs; do
+        logDir=/tmp/hs-test/$dirName
+        if [ -d "$logDir" ]; then
+            mkdir -p $WORKSPACE/archives/summary
+            cp -r $logDir $WORKSPACE/archives/summary/
+        fi
+    done
+    echo "Done."
+
+    if [ -n "$WORKSPACE" ]
+    then
+        echo -n "Copying failed test logs into build log archive directory ($WORKSPACE/archives)... "
+        mkdir -p $WORKSPACE/archives/summary
+        cp -a ${HS_SUMMARY}/* $WORKSPACE/archives/summary
+    echo "Done."
+    fi
+
+    echo -n "Compressing files in $WORKSPACE/archives from test runs... "
+    cd $WORKSPACE/archives
+    find . -type f \( -name "*.json" -o -name "*.log" \) -exec gzip {} \;
+    echo "Done."
+
+else
+    echo "Not compressing files in temporary directories from test runs."
+    exit 0
+fi
+
+exit 1
\ No newline at end of file
diff --git a/extras/hs-test/suite_nginx_test.go b/extras/hs-test/suite_nginx_test.go
index 2d1caf152f4..c559496e71b 100644
--- a/extras/hs-test/suite_nginx_test.go
+++ b/extras/hs-test/suite_nginx_test.go
@@ -98,7 +98,9 @@ var _ = Describe("NginxSuite", Ordered, ContinueOnFailure, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
@@ -118,11 +120,14 @@ var _ = Describe("NginxSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 	AfterEach(func() {
 		s.TearDownTest()
 	})
+
 	for _, test := range nginxSoloTests {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], Label("SOLO"), func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, Label("SOLO"), func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
diff --git a/extras/hs-test/suite_no_topo_test.go b/extras/hs-test/suite_no_topo_test.go
index 6df06c7e60e..625dca9f3cf 100644
--- a/extras/hs-test/suite_no_topo_test.go
+++ b/extras/hs-test/suite_no_topo_test.go
@@ -74,7 +74,9 @@ var _ = Describe("NoTopoSuite", Ordered, ContinueOnFailure, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
@@ -99,7 +101,9 @@ var _ = Describe("NoTopoSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], Label("SOLO"), func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, Label("SOLO"), func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
diff --git a/extras/hs-test/suite_ns_test.go b/extras/hs-test/suite_ns_test.go
index 86d9b78a010..85b90911c2f 100644
--- a/extras/hs-test/suite_ns_test.go
+++ b/extras/hs-test/suite_ns_test.go
@@ -83,7 +83,9 @@ var _ = Describe("NsSuite", Ordered, ContinueOnFailure, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
@@ -108,7 +110,9 @@ var _ = Describe("NsSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], Label("SOLO"), func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, Label("SOLO"), func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
diff --git a/extras/hs-test/suite_tap_test.go b/extras/hs-test/suite_tap_test.go
index 25c1e25a215..ebf0f9b3cbc 100644
--- a/extras/hs-test/suite_tap_test.go
+++ b/extras/hs-test/suite_tap_test.go
@@ -48,7 +48,9 @@ var _ = Describe("TapSuite", Ordered, ContinueOnFailure, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
@@ -73,7 +75,9 @@ var _ = Describe("TapSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], Label("SOLO"), func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, Label("SOLO"), func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
diff --git a/extras/hs-test/suite_veth_test.go b/extras/hs-test/suite_veth_test.go
index f4c3684f031..d47bf8c52a9 100644
--- a/extras/hs-test/suite_veth_test.go
+++ b/extras/hs-test/suite_veth_test.go
@@ -107,7 +107,9 @@ var _ = Describe("VethsSuite", Ordered, ContinueOnFailure, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
@@ -123,7 +125,6 @@ var _ = Describe("VethsSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 	})
 	AfterAll(func() {
 		s.TearDownSuite()
-
 	})
 	AfterEach(func() {
 		s.TearDownTest()
@@ -134,7 +135,9 @@ var _ = Describe("VethsSuiteSolo", Ordered, ContinueOnFailure, Serial, func() {
 		test := test
 		pc := reflect.ValueOf(test).Pointer()
 		funcValue := runtime.FuncForPC(pc)
-		It(strings.Split(funcValue.Name(), ".")[2], Label("SOLO"), func(ctx SpecContext) {
+		testName := strings.Split(funcValue.Name(), ".")[2]
+		It(testName, Label("SOLO"), func(ctx SpecContext) {
+			s.log(testName + ": BEGIN")
 			test(&s)
 		}, SpecTimeout(time.Minute*5))
 	}
diff --git a/extras/hs-test/test b/extras/hs-test/test
index 94162b87759..fd17feb2c50 100755
--- a/extras/hs-test/test
+++ b/extras/hs-test/test
@@ -86,4 +86,6 @@ if [ $single_test -eq 0 ] && [ $debug_set -eq 1 ]; then
     exit 1
 fi
 
-sudo -E go run github.com/onsi/ginkgo/v2/ginkgo --no-color --trace $ginkgo_args -- $args
+mkdir -p summary
+
+sudo -E go run github.com/onsi/ginkgo/v2/ginkgo --no-color --trace --json-report=summary/report.json $ginkgo_args -- $args
diff --git a/extras/hs-test/vppinstance.go b/extras/hs-test/vppinstance.go
index 7ddec7e0ed4..9b400cfcb77 100644
--- a/extras/hs-test/vppinstance.go
+++ b/extras/hs-test/vppinstance.go
@@ -2,6 +2,7 @@ package main
 
 import (
 	"fmt"
+	"io"
 	"os"
 	"os/exec"
 	"os/signal"
@@ -10,6 +11,7 @@ import (
 	"syscall"
 	"time"
 
+	"github.com/sirupsen/logrus"
 	"github.com/edwarnicke/exechelper"
 	. "github.com/onsi/ginkgo/v2"
 
@@ -106,6 +108,10 @@ func (vpp *VppInstance) getEtcDir() string {
 }
 
 func (vpp *VppInstance) start() error {
+	// Replace default logger in govpp with our own
+	govppLogger := logrus.New()
+	govppLogger.SetOutput(io.MultiWriter(vpp.getSuite().logger.Writer(), GinkgoWriter))
+	core.SetLogger(govppLogger)
 	// Create folders
 	containerWorkDir := vpp.container.getContainerWorkDir()