From 637edda1324fac88117d5520f94377e5d303128c Mon Sep 17 00:00:00 2001 From: Adrian Villin Date: Mon, 6 May 2024 06:55:34 -0400 Subject: hs-test: logging improvements Type: test Change-Id: Iffefe085e846b6ba614b0d74c4ba9907080a9a59 Signed-off-by: Adrian Villin --- .gitignore | 1 + Makefile | 1 + extras/hs-test/Makefile | 8 +++++- extras/hs-test/container.go | 2 +- extras/hs-test/hst_suite.go | 53 ++++++++++++++++++++++++++---------- extras/hs-test/raw_session_test.go | 5 ++-- extras/hs-test/script/compress.sh | 34 +++++++++++++++++++++++ extras/hs-test/suite_nginx_test.go | 9 ++++-- extras/hs-test/suite_no_topo_test.go | 8 ++++-- extras/hs-test/suite_ns_test.go | 8 ++++-- extras/hs-test/suite_tap_test.go | 8 ++++-- extras/hs-test/suite_veth_test.go | 9 ++++-- extras/hs-test/test | 4 ++- extras/hs-test/vppinstance.go | 6 ++++ 14 files changed, 125 insertions(+), 31 deletions(-) create mode 100644 extras/hs-test/script/compress.sh 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() -- cgit 1.2.3-korg