Fix e2e tests (ligato#1895)

Fixes the followig tests that were failing randomly:
* TestInitFromFileAndEtcd
* TestSourceNAT and TestNATStaticMappings
* TestL3ACLs

Signed-off-by: Matus Halaj <[email protected]>

Signed-off-by: Matus Halaj <[email protected]>
Co-authored-by: Ondrej Fabry <[email protected]>

Author: mhalaj1

tests/e2e/001_init_config_test.go

@@ -197,17 +197,19 @@ endpoints:
 	)
 
 	// check whether initial configuration is correctly loaded from Etcd and file in running VPP-Agent
-	initInterfaceConfigState := func(interfaceName string, ipAddress string) kvscheduler.ValueState {
-		return ctx.GetValueStateByKey(
-			fmt.Sprintf("vpp/interface/%v/address/static/%v/32", interfaceName, ipAddress))
+	initInterfaceConfigStateClb := func(interfaceName string, ipAddress string) func() kvscheduler.ValueState {
+		return func() kvscheduler.ValueState {
+			return ctx.GetValueStateByKey(
+				fmt.Sprintf("vpp/interface/%v/address/static/%v/32", interfaceName, ipAddress))
+		}
 	}
-	ctx.Eventually(initInterfaceConfigState("memif-from-etcd", "10.10.1.1")).
+	ctx.Eventually(initInterfaceConfigStateClb("memif-from-etcd", "10.10.1.1")).
 		Should(Equal(kvscheduler.ValueState_CONFIGURED),
 			"unique memif from etcd was not properly created")
-	ctx.Eventually(initInterfaceConfigState("memif-from-init-file", "10.10.1.2")).
+	ctx.Eventually(initInterfaceConfigStateClb("memif-from-init-file", "10.10.1.2")).
 		Should(Equal(kvscheduler.ValueState_CONFIGURED),
 			"unique memif from init file was not properly created")
-	ctx.Eventually(initInterfaceConfigState("memif-from-both-sources", "10.10.1.3")).
+	ctx.Eventually(initInterfaceConfigStateClb("memif-from-both-sources", "10.10.1.3")).
 		Should(Equal(kvscheduler.ValueState_CONFIGURED),
 			"conflicting memif (defined in init file and etcd) was either not correctly "+
 				"merged (etcd data should have priority) or other things prevented its proper creation")

tests/e2e/connection.go

@@ -18,6 +18,7 @@ import (
 	"bufio"
 	"context"
 	"fmt"
+	"log"
 	"net"
 	"strings"
 	"time"
@@ -29,7 +30,10 @@ type connectionRequest struct {
 	err  error
 }
 
-func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqMsg, respMsg string, done chan<- error) {
+func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqMsg, respMsg string, done chan<- error, logger *log.Logger) {
+	defer func() {
+		done <- nil
+	}()
 	// move to the network namespace where server should listen
 	exitNetNs := ms.enterNetNs()
 	defer exitNetNs()
@@ -45,6 +49,10 @@ func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 	newConn := make(chan connectionRequest, 1)
 	go func() {
 		conn, err := listener.Accept()
+		if err != nil {
+			err = fmt.Errorf("accept failed with: %v", err)
+			logger.Println(err)
+		}
 		newConn <- connectionRequest{conn: conn, err: err}
 		close(newConn)
 	}()
@@ -57,7 +65,7 @@ func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 		return
 	case cr = <-newConn:
 		if cr.err != nil {
-			done <- fmt.Errorf("accept failed with: %v", cr.err)
+			done <- cr.err
 			return
 		}
 		defer cr.conn.Close()
@@ -70,20 +78,26 @@ func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 		// receive message from the client
 		message, err := bufio.NewReader(cr.conn).ReadString('\n')
 		if err != nil {
-			commRv <- fmt.Errorf("failed to read data from client: %v", err)
+			err = fmt.Errorf("failed to read data from client: %v", err)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		// send response to the client
 		_, err = cr.conn.Write([]byte(respMsg + "\n"))
 		if err != nil {
-			commRv <- fmt.Errorf("failed to send data to client: %v", err)
+			err = fmt.Errorf("failed to send data to client: %v", err)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		// check if the exchanged data are as expected
 		message = strings.TrimRight(message, "\n")
 		if message != expReqMsg {
-			commRv <- fmt.Errorf("unexpected message received from client ('%s' vs. '%s')",
+			err = fmt.Errorf("unexpected message received from client ('%s' vs. '%s')",
 				message, expReqMsg)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		commRv <- nil
@@ -102,13 +116,18 @@ func simpleTCPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 	<-ctx.Done()
 }
 
-func simpleUDPServer(ctx context.Context, ms *Microservice, addr string, expReqMsg, respMsg string, done chan<- error) {
+func simpleUDPServer(ctx context.Context, ms *Microservice, addr string, expReqMsg, respMsg string, done chan<- error, ready chan<- error, logger *log.Logger) {
+	defer func() {
+		done <- nil
+	}()
+
 	const maxBufferSize = 1024
 	// move to the network namespace where server should listen
 	exitNetNs := ms.enterNetNs()
 	defer exitNetNs()
 
 	conn, err := net.ListenPacket("udp", addr)
+	ready <- err
 	if err != nil {
 		done <- err
 		return
@@ -123,21 +142,27 @@ func simpleUDPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 		buffer := make([]byte, maxBufferSize)
 		n, addr, err := conn.ReadFrom(buffer)
 		if err != nil {
-			commRv <- fmt.Errorf("failed to read data from client: %v", err)
+			err = fmt.Errorf("failed to read data from client: %v", err)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		message := string(buffer[:n])
 		// send response to the client
 		_, err = conn.WriteTo([]byte(respMsg+"\n"), addr)
 		if err != nil {
-			commRv <- fmt.Errorf("failed to send data to client: %v", err)
+			err = fmt.Errorf("failed to send data to client: %v", err)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		// check if the exchanged data are as expected
 		message = strings.TrimRight(message, "\n")
 		if message != expReqMsg {
-			commRv <- fmt.Errorf("unexpected message received from client ('%s' vs. '%s')",
+			err = fmt.Errorf("unexpected message received from client ('%s' vs. '%s')",
 				message, expReqMsg)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		commRv <- nil
@@ -156,7 +181,7 @@ func simpleUDPServer(ctx context.Context, ms *Microservice, addr string, expReqM
 	<-ctx.Done()
 }
 
-func simpleTCPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, timeout time.Duration, done chan<- error) {
+func simpleTCPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, timeout time.Duration, done chan<- error, logger *log.Logger) {
 	// try to connect with the server
 	newConn := make(chan connectionRequest, 1)
 
@@ -171,16 +196,20 @@ func simpleTCPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, t
 				time.Sleep(checkPollingInterval)
 				continue
 			}
+			if err != nil {
+				err = fmt.Errorf("dial failed with: %v", err)
+				logger.Println(err)
+			}
 			newConn <- connectionRequest{conn: conn, err: err}
 			break
 		}
 		close(newConn)
 	}()
 
-	simpleTCPOrUDPClient(newConn, addr, reqMsg, expRespMsg, timeout, done)
+	simpleTCPOrUDPClient(newConn, addr, reqMsg, expRespMsg, timeout, done, logger)
 }
 
-func simpleUDPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, timeout time.Duration, done chan<- error) {
+func simpleUDPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, timeout time.Duration, done chan<- error, srvReady chan error, logger *log.Logger) {
 	// try to connect with the server
 	newConn := make(chan connectionRequest, 1)
 
@@ -190,27 +219,40 @@ func simpleUDPClient(ms *Microservice, addr string, reqMsg, expRespMsg string, t
 		defer exitNetNs()
 		udpAddr, err := net.ResolveUDPAddr("udp", addr)
 		if err != nil {
+			err = fmt.Errorf("dial failed with: %v", err)
+			logger.Println(err)
 			newConn <- connectionRequest{conn: nil, err: err}
 		} else {
 			start := time.Now()
-			for {
-				conn, err := net.DialUDP("udp", nil, udpAddr)
-				if err != nil && time.Since(start) < timeout {
-					time.Sleep(checkPollingInterval)
-					continue
+			err = <-srvReady
+			if err != nil {
+				err = fmt.Errorf("dial failed with: %v", "server not ready")
+				logger.Println(err)
+				newConn <- connectionRequest{conn: nil, err: err}
+			} else {
+				for {
+					conn, err := net.DialUDP("udp", nil, udpAddr)
+					if err != nil && time.Since(start) < timeout {
+						time.Sleep(checkPollingInterval)
+						continue
+					}
+					if err != nil {
+						err = fmt.Errorf("dial failed with: %v", err)
+						logger.Println(err)
+					}
+					newConn <- connectionRequest{conn: conn, err: err}
+					break
 				}
-				newConn <- connectionRequest{conn: conn, err: err}
-				break
 			}
 		}
 		close(newConn)
 	}()
 
-	simpleTCPOrUDPClient(newConn, addr, reqMsg, expRespMsg, timeout, done)
+	simpleTCPOrUDPClient(newConn, addr, reqMsg, expRespMsg, timeout, done, logger)
 }
 
 func simpleTCPOrUDPClient(newConn chan connectionRequest, addr, reqMsg, expRespMsg string,
-	timeout time.Duration, done chan<- error) {
+	timeout time.Duration, done chan<- error, logger *log.Logger) {
 
 	// wait for connection
 	var cr connectionRequest
@@ -220,7 +262,7 @@ func simpleTCPOrUDPClient(newConn chan connectionRequest, addr, reqMsg, expRespM
 		return
 	case cr = <-newConn:
 		if cr.err != nil {
-			done <- fmt.Errorf("dial failed with: %v", cr.err)
+			done <- cr.err
 			return
 		}
 		defer cr.conn.Close()
@@ -234,7 +276,9 @@ func simpleTCPOrUDPClient(newConn chan connectionRequest, addr, reqMsg, expRespM
 		// send message to the server
 		_, err := cr.conn.Write([]byte(reqMsg + "\n"))
 		if err != nil {
-			commRv <- fmt.Errorf("failed to send data to the server: %v", err)
+			err = fmt.Errorf("failed to send data to the server: %v", err)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 		// listen for reply
@@ -247,16 +291,20 @@ func simpleTCPOrUDPClient(newConn chan connectionRequest, addr, reqMsg, expRespM
 				continue
 			}
 			if err != nil {
-				commRv <- fmt.Errorf("failed to read data from server: %v", err)
+				err = fmt.Errorf("failed to read data from server: %v", err)
+				logger.Println(err)
+				commRv <- err
 				return
 			}
 			break
 		}
 		// check if the exchanged data are as expected
 		message = strings.TrimRight(message, "\n")
 		if message != expRespMsg {
-			commRv <- fmt.Errorf("unexpected message received from server ('%s' vs. '%s')",
+			err = fmt.Errorf("unexpected message received from server ('%s' vs. '%s')",
 				message, expRespMsg)
+			logger.Println(err)
+			commRv <- err
 			return
 		}
 

tests/e2e/e2e.go

@@ -493,6 +493,11 @@ func (test *TestCtx) PingFromVPPClb(destAddress string) func() error {
 	return test.Agent.PingFromVPPAsCallback(destAddress)
 }
 
+// TestConnection starts a simple TCP or UPD server and client, sends some data
+// and stops the client and server.
+//
+// If upd is true and there was no prior traffic (TPC/UDP/ICMP) between the
+// endpoints, ARP glean may happen and TestConnection may fail.
 func (test *TestCtx) TestConnection(
 	fromMs, toMs, toAddr, listenAddr string,
 	toPort, listenPort uint16, udp bool,
@@ -529,12 +534,14 @@ func (test *TestCtx) TestConnection(
 
 	srvRet := make(chan error, 1)
 	srvCtx, cancelSrv := context.WithCancel(context.Background())
+	udpSrvReady := make(chan error, 1)
+	defer close(udpSrvReady)
 	runServer := func() {
 		defer close(srvRet)
 		if udp {
-			simpleUDPServer(srvCtx, serverMs, serverAddr, reqData, respData, srvRet)
+			simpleUDPServer(srvCtx, serverMs, serverAddr, reqData, respData, srvRet, udpSrvReady, test.Logger)
 		} else {
-			simpleTCPServer(srvCtx, serverMs, serverAddr, reqData, respData, srvRet)
+			simpleTCPServer(srvCtx, serverMs, serverAddr, reqData, respData, srvRet, test.Logger)
 		}
 	}
 
@@ -543,10 +550,10 @@ func (test *TestCtx) TestConnection(
 		defer close(clientRet)
 		if udp {
 			simpleUDPClient(clientMs, clientAddr,
-				reqData, respData, connTimeout, clientRet)
+				reqData, respData, connTimeout, clientRet, udpSrvReady, test.Logger)
 		} else {
 			simpleTCPClient(clientMs, clientAddr,
-				reqData, respData, connTimeout, clientRet)
+				reqData, respData, connTimeout, clientRet, test.Logger)
 		}
 	}
 
@@ -572,12 +579,13 @@ func (test *TestCtx) TestConnection(
 		cancelSrv()
 		srvErr = <-srvRet
 	}
-	if err == nil {
-		err = srvErr
-	}
+	// wait until server actually stops
+	<-srvRet
 
 	outcome := "OK"
-	if err != nil {
+	if err != nil || srvErr != nil {
+		time.Sleep(50 * time.Millisecond) // give other goroutines time to print logs
+		err = fmt.Errorf("server: <%v>, client: <%v>", srvErr, err)
 		outcome = err.Error()
 	}