hs-test: logging improvements

Type: test

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

diff --git a/.gitignore b/.gitignore
index 5c707a8..5537f0d 100644 (file)
--- 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 edd632e..6675b51 100644 (file)
--- 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 54b95c3..6ee89bc 100644 (file)
--- 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 c82f1fc..45f41d2 100644 (file)
--- 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 bb49924..725fee7 100644 (file)
--- 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 cf74c62..5c66df0 100644 (file)
--- 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 (file)
index 0000000..92a2fbd
--- /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 2d1caf1..c559496 100644 (file)
--- 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 6df06c7..625dca9 100644 (file)
--- 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 86d9b78..85b9091 100644 (file)
--- 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 25c1e25..ebf0f9b 100644 (file)
--- 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 f4c3684..d47bf8c 100644 (file)
--- 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 94162b8..fd17feb 100755 (executable)
--- 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 7ddec7e..9b400cf 100644 (file)
--- 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()