From: adrianvillin <avillin@cisco.com>
Date: Mon, 12 Feb 2024 07:44:53 +0000 (-0500)
Subject: hs-test: improved logging
X-Git-Tag: v24.10-rc0~249
X-Git-Url: https://gerrit.fd.io/r/gitweb?a=commitdiff_plain;h=7c675471e87c72be272c078fd481844e4efa64d0;p=vpp.git

hs-test: improved logging

- improved readability of some error messages
- printing container logs to stdout on test failure (last 20 lines)

Type: test

Change-Id: Idbb358bdd89aa7b1a6bdc9d96bf029d4c299ce64
Signed-off-by: adrianvillin <avillin@cisco.com>
---

diff --git a/extras/hs-test/container.go b/extras/hs-test/container.go
index 86f511c2b46..10b5933b17f 100644
--- a/extras/hs-test/container.go
+++ b/extras/hs-test/container.go
@@ -285,7 +285,7 @@ func (c *Container) exec(command string, arguments ...any) string {
 	c.suite.T().Helper()
 	c.suite.log(containerExecCommand)
 	byteOutput, err := exechelper.CombinedOutput(containerExecCommand)
-	c.suite.assertNil(err)
+	c.suite.assertNil(err, err)
 	return string(byteOutput)
 }
 
@@ -324,12 +324,18 @@ func (c *Container) saveLogs() {
 	f.Close()
 }
 
-func (c *Container) log() string {
-	cmd := "docker logs " + c.name
+// Outputs logs from docker containers. Set 'maxLines' to 0 to output the full log.
+func (c *Container) log(maxLines int) (string, error) {
+	var cmd string
+	if maxLines == 0 {
+		cmd = "docker logs " + c.name
+	} else {
+		cmd = fmt.Sprintf("docker logs --tail %d %s", maxLines, c.name)
+	}
+
 	c.suite.log(cmd)
 	o, err := exechelper.CombinedOutput(cmd)
-	c.suite.assertNil(err)
-	return string(o)
+	return string(o), err
 }
 
 func (c *Container) stop() error {
@@ -346,14 +352,14 @@ func (c *Container) createConfig(targetConfigName string, templateName string, v
 	template := template.Must(template.ParseFiles(templateName))
 
 	f, err := os.CreateTemp(logDir, "hst-config")
-	c.suite.assertNil(err)
+	c.suite.assertNil(err, err)
 	defer os.Remove(f.Name())
 
 	err = template.Execute(f, values)
-	c.suite.assertNil(err)
+	c.suite.assertNil(err, err)
 
 	err = f.Close()
-	c.suite.assertNil(err)
+	c.suite.assertNil(err, err)
 
 	c.copy(f.Name(), targetConfigName)
 }
diff --git a/extras/hs-test/echo_test.go b/extras/hs-test/echo_test.go
index fc221aa9ab5..160613742f2 100644
--- a/extras/hs-test/echo_test.go
+++ b/extras/hs-test/echo_test.go
@@ -40,5 +40,5 @@ func (s *VethsSuite) TestTcpWithLoss() {
 		serverVeth.ip4AddressString())
 	s.log(output)
 	s.assertNotEqual(len(output), 0)
-	s.assertNotContains(output, "failed: timeout")
+	s.assertNotContains(output, "failed: timeout", output)
 }
diff --git a/extras/hs-test/hst_suite.go b/extras/hs-test/hst_suite.go
index 7f93b15f50a..908c046d082 100644
--- a/extras/hs-test/hst_suite.go
+++ b/extras/hs-test/hst_suite.go
@@ -1,6 +1,7 @@
 package main
 
 import (
+	"bufio"
 	"errors"
 	"flag"
 	"fmt"
@@ -102,7 +103,54 @@ func (s *HstSuite) setupContainers() {
 	}
 }
 
+func logVppInstance(container *Container, maxLines int){
+	if container.vppInstance == nil{
+		return
+	}
+
+	logSource := container.getHostWorkDir() + defaultLogFilePath
+	file, err := os.Open(logSource)
+
+	if err != nil{
+		return
+	}
+	defer file.Close()
+
+	scanner := bufio.NewScanner(file)
+	var lines []string
+	var counter int
+
+	for scanner.Scan(){
+		lines = append(lines, scanner.Text())
+		counter++
+		if counter > maxLines {
+			lines = lines[1:]
+			counter--
+		}
+	}
+
+	fmt.Println("vvvvvvvvvvvvvvv " + container.name + " [VPP instance]:")
+	for _, line := range lines{
+		fmt.Println(line)
+	}
+	fmt.Printf("^^^^^^^^^^^^^^^\n\n")
+
+}
+
 func (s *HstSuite) hstFail() {
+	fmt.Println("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))
+			break
+		}
+		fmt.Printf("\nvvvvvvvvvvvvvvv " +
+					container.name + ":\n" +
+					out +
+					"^^^^^^^^^^^^^^^\n\n")
+		logVppInstance(container, 20)
+	}
 	s.T().FailNow()
 }
 
@@ -369,7 +417,7 @@ func (s *HstSuite) startHttpServer(running chan struct{}, done chan struct{}, ad
 	err := cmd.Start()
 	s.log(cmd)
 	if err != nil {
-		fmt.Println("Failed to start http server")
+		fmt.Println("Failed to start http server: " + fmt.Sprint(err))
 		return
 	}
 	running <- struct{}{}
diff --git a/extras/hs-test/http_test.go b/extras/hs-test/http_test.go
index 9872f8db560..e710f38835b 100644
--- a/extras/hs-test/http_test.go
+++ b/extras/hs-test/http_test.go
@@ -20,7 +20,7 @@ func (s *NsSuite) TestHttpTps() {
 	go s.startWget(finished, client_ip, port, "test_file_10M", "client")
 	// wait for client
 	err := <-finished
-	s.assertNil(err)
+	s.assertNil(err, err)
 }
 
 func (s *VethsSuite) TestHttpCli() {
@@ -56,7 +56,7 @@ func (s *NoTopoSuite) TestNginxHttp3() {
 	args := fmt.Sprintf("curl --noproxy '*' --local-port 55444 --http3-only -k https://%s:8443/%s", serverAddress, query)
 	curlCont.extraRunningArgs = args
 	o, err := curlCont.combinedOutput()
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.assertContains(o, "<http>", "<http> not found in the result!")
 }
 
@@ -69,7 +69,7 @@ func (s *NoTopoSuite) TestHttpStaticProm() {
 	s.log(vpp.vppctl("prom enable"))
 	go s.startWget(finished, serverAddress, "80", query, "")
 	err := <-finished
-	s.assertNil(err)
+	s.assertNil(err, err)
 }
 
 func (s *NoTopoSuite) TestNginxAsServer() {
@@ -126,7 +126,7 @@ func runNginxPerf(s *NoTopoSuite, mode, ab_or_wrk string) error {
 		o, err := abCont.combinedOutput()
 		rps := parseString(o, "Requests per second:")
 		s.log(rps, err)
-		s.assertNil(err)
+		s.assertNil(err, "err: '%s', output: '%s'", err, o)
 	} else {
 		wrkCont := s.getContainerByName("wrk")
 		args := fmt.Sprintf("-c %d -t 2 -d 30 http://%s:80/64B.json", nClients,
@@ -135,7 +135,7 @@ func runNginxPerf(s *NoTopoSuite, mode, ab_or_wrk string) error {
 		o, err := wrkCont.combinedOutput()
 		rps := parseString(o, "requests")
 		s.log(rps, err)
-		s.assertNil(err)
+		s.assertNil(err, "err: '%s', output: '%s'", err, o)
 	}
 	return nil
 }
diff --git a/extras/hs-test/ldp_test.go b/extras/hs-test/ldp_test.go
index b6249cdd257..1ccf8592863 100644
--- a/extras/hs-test/ldp_test.go
+++ b/extras/hs-test/ldp_test.go
@@ -36,7 +36,7 @@ func (s *VethsSuite) TestLDPreloadIperfVpp() {
 		append("use-mq-eventfd").
 		append(clientAppSocketApi).close().
 		saveToFile(clientVclFileName)
-	s.assertNil(err)
+	s.assertNil(err, err)
 
 	serverAppSocketApi := fmt.Sprintf("app-socket-api %s/var/run/app_ns_sockets/default",
 		serverContainer.getHostWorkDir())
@@ -49,7 +49,7 @@ func (s *VethsSuite) TestLDPreloadIperfVpp() {
 		append("use-mq-eventfd").
 		append(serverAppSocketApi).close().
 		saveToFile(serverVclFileName)
-	s.assertNil(err)
+	s.assertNil(err, err)
 
 	s.log("attaching server to vpp")
 
@@ -57,7 +57,7 @@ func (s *VethsSuite) TestLDPreloadIperfVpp() {
 	go s.startServerApp(srvCh, stopServerCh, srvEnv)
 
 	err = <-srvCh
-	s.assertNil(err)
+	s.assertNil(err, err)
 
 	s.log("attaching client to vpp")
 	var clnRes = make(chan string, 1)
@@ -68,7 +68,7 @@ func (s *VethsSuite) TestLDPreloadIperfVpp() {
 
 	// wait for client's result
 	err = <-clnCh
-	s.assertNil(err)
+	s.assertNil(err, err)
 
 	// stop server
 	stopServerCh <- struct{}{}
diff --git a/extras/hs-test/linux_iperf_test.go b/extras/hs-test/linux_iperf_test.go
index c03403c9e26..47ebd0363ab 100644
--- a/extras/hs-test/linux_iperf_test.go
+++ b/extras/hs-test/linux_iperf_test.go
@@ -11,7 +11,7 @@ func (s *TapSuite) TestLinuxIperf() {
 
 	go s.startServerApp(srvCh, stopServerCh, nil)
 	err := <-srvCh
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.log("server running")
 
 	ipAddress := s.netInterfaces[tapInterfaceName].ip4AddressString()
@@ -19,6 +19,6 @@ func (s *TapSuite) TestLinuxIperf() {
 	s.log("client running")
 	s.log(<-clnRes)
 	err = <-clnCh
-	s.assertNil(err)
+	s.assertNil(err, "err: '%s', ip: '%s'", err, ipAddress)
 	s.log("Test completed")
 }
diff --git a/extras/hs-test/netconfig.go b/extras/hs-test/netconfig.go
index 897be6cfa65..c76a0fda5f5 100644
--- a/extras/hs-test/netconfig.go
+++ b/extras/hs-test/netconfig.go
@@ -298,8 +298,7 @@ func setDevUpDown(dev, ns string, isUp bool) error {
 	cmd := appendNetns(c, ns)
 	err := cmd.Run()
 	if err != nil {
-		s := fmt.Sprintf("error bringing %s device %s!", dev, op)
-		return errors.New(s)
+		return fmt.Errorf("error bringing %s device %s! (cmd: '%s')", dev, op, cmd)
 	}
 	return nil
 }
@@ -314,7 +313,7 @@ func addDelNetns(name string, isAdd bool) error {
 	cmd := exec.Command("ip", "netns", op, name)
 	_, err := cmd.CombinedOutput()
 	if err != nil {
-		return errors.New("add/del netns failed")
+		return fmt.Errorf("add/del netns failed (cmd: '%s')", cmd)
 	}
 	return nil
 }
@@ -356,7 +355,7 @@ func addDelBridge(brName, ns string, isAdd bool) error {
 	cmd := appendNetns(c, ns)
 	err := cmd.Run()
 	if err != nil {
-		s := fmt.Sprintf("%s %s failed!", op, brName)
+		s := fmt.Sprintf("%s %s failed! err: '%s'", op, brName, err)
 		return errors.New(s)
 	}
 	return nil
@@ -373,8 +372,7 @@ func addBridge(brName string, ifs []string, ns string) error {
 		cmd := appendNetns(c, ns)
 		err = cmd.Run()
 		if err != nil {
-			s := fmt.Sprintf("error adding %s to bridge %s: %v", v, brName, err)
-			return errors.New(s)
+			return fmt.Errorf("error adding %s to bridge %s: %s", v, brName, err)
 		}
 	}
 	err = setDevUp(brName, ns)
diff --git a/extras/hs-test/proxy_test.go b/extras/hs-test/proxy_test.go
index 7b7321eba6d..cdb516a108b 100644
--- a/extras/hs-test/proxy_test.go
+++ b/extras/hs-test/proxy_test.go
@@ -15,7 +15,7 @@ func testProxyHttpTcp(s *NsSuite, proto string) error {
 
 	// create test file
 	err := exechelper.Run(fmt.Sprintf("ip netns exec server truncate -s %s %s", srcFile, srcFile))
-	s.assertNil(err, "failed to run truncate command")
+	s.assertNil(err, "failed to run truncate command: " + fmt.Sprint(err))
 	defer func() { os.Remove(srcFile) }()
 
 	s.log("test file created...")
@@ -39,7 +39,7 @@ func testProxyHttpTcp(s *NsSuite, proto string) error {
 	c += fmt.Sprintf("%s:555/%s", clientVeth.ip4AddressString(), srcFile)
 	s.log(c)
 	_, err = exechelper.CombinedOutput(c)
-	s.assertNil(err, "failed to run wget")
+	s.assertNil(err, "failed to run wget: '%s', cmd: %s", err, c)
 	stopServer <- struct{}{}
 
 	defer func() { os.Remove(outputFile) }()
@@ -66,19 +66,20 @@ func (s *NsSuite) TestVppProxyHttpTcp() {
 	proto := "tcp"
 	configureVppProxy(s, proto)
 	err := testProxyHttpTcp(s, proto)
-	s.assertNil(err)
+	s.assertNil(err, err)
 }
 
 func (s *NsSuite) TestVppProxyHttpTls() {
 	proto := "tls"
 	configureVppProxy(s, proto)
 	err := testProxyHttpTcp(s, proto)
-	s.assertNil(err)
+	s.assertNil(err, err)
 }
 
 func configureEnvoyProxy(s *NsSuite) {
 	envoyContainer := s.getContainerByName("envoy")
-	envoyContainer.create()
+	err := envoyContainer.create()
+	s.assertNil(err, "Error creating envoy container: %s", err)
 
 	serverVeth := s.netInterfaces[serverInterface]
 	address := struct {
@@ -97,5 +98,5 @@ func configureEnvoyProxy(s *NsSuite) {
 func (s *NsSuite) TestEnvoyProxyHttpTcp() {
 	configureEnvoyProxy(s)
 	err := testProxyHttpTcp(s, "tcp")
-	s.assertNil(err)
+	s.assertNil(err, err)
 }
diff --git a/extras/hs-test/suite_ns_test.go b/extras/hs-test/suite_ns_test.go
index 2c1ac34b414..4e8f497076a 100644
--- a/extras/hs-test/suite_ns_test.go
+++ b/extras/hs-test/suite_ns_test.go
@@ -34,11 +34,11 @@ func (s *NsSuite) SetupTest() {
 	s.assertNil(vpp.start())
 
 	idx, err := vpp.createAfPacket(s.netInterfaces[serverInterface])
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.assertNotEqual(0, idx)
 
 	idx, err = vpp.createAfPacket(s.netInterfaces[clientInterface])
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.assertNotEqual(0, idx)
 
 	container.exec("chmod 777 -R %s", container.getContainerWorkDir())
diff --git a/extras/hs-test/suite_veth_test.go b/extras/hs-test/suite_veth_test.go
index de4812d7f97..8593c88740a 100644
--- a/extras/hs-test/suite_veth_test.go
+++ b/extras/hs-test/suite_veth_test.go
@@ -36,8 +36,8 @@ func (s *VethsSuite) SetupTest() {
 	serverContainer := s.getContainerByName("server-vpp")
 
 	cpus := s.AllocateCpus()
-	serverVpp, _ := serverContainer.newVppInstance(cpus, sessionConfig)
-	s.assertNotNil(serverVpp)
+	serverVpp, err := serverContainer.newVppInstance(cpus, sessionConfig)
+	s.assertNotNil(serverVpp, err)
 
 	s.setupServerVpp()
 
@@ -45,8 +45,8 @@ func (s *VethsSuite) SetupTest() {
 	clientContainer := s.getContainerByName("client-vpp")
 
 	cpus = s.AllocateCpus()
-	clientVpp, _ := clientContainer.newVppInstance(cpus, sessionConfig)
-	s.assertNotNil(clientVpp)
+	clientVpp, err := clientContainer.newVppInstance(cpus, sessionConfig)
+	s.assertNotNil(clientVpp, err)
 
 	s.setupClientVpp()
 }
@@ -57,7 +57,7 @@ func (s *VethsSuite) setupServerVpp() {
 
 	serverVeth := s.netInterfaces[serverInterfaceName]
 	idx, err := serverVpp.createAfPacket(serverVeth)
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.assertNotEqual(0, idx)
 }
 
@@ -67,6 +67,6 @@ func (s *VethsSuite) setupClientVpp() {
 
 	clientVeth := s.netInterfaces[clientInterfaceName]
 	idx, err := clientVpp.createAfPacket(clientVeth)
-	s.assertNil(err)
+	s.assertNil(err, err)
 	s.assertNotEqual(0, idx)
 }