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 86f511c..10b5933 100644 (file)
--- 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 fc221aa..1606137 100644 (file)
--- 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 7f93b15..908c046 100644 (file)
--- 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 9872f8d..e710f38 100644 (file)
--- 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 b6249cd..1ccf859 100644 (file)
--- 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 c03403c..47ebd03 100644 (file)
--- 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 897be6c..c76a0fd 100644 (file)
--- 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 7b7321e..cdb516a 100644 (file)
--- 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 2c1ac34..4e8f497 100644 (file)
--- 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 de4812d..8593c88 100644 (file)
--- 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)
 }