CI: Test for Dual NIC BC with HA for phc2sys

Added a new test case for the DualNICBC in HA mode. The test case
implements this sequence:
- Turn down the slave interface in the primary BC.
- Wait for phc2sys logs that reflect the selection of the secondary
  BC's slave interface.
- Turn up the original slave interface in the primary BC.
- Wait for ph2sys logs that reflect the selection of the original slave
  interface of the primary BC.

In order for this test case to work, I've done some modifications in the
test framework:

- Added a function to create a separate third config for DualNIC Boundary
Clocks working in HA mode. This extra config has phc2sys config opts and
haProfiles in the ptpSettings field.
- Updated the discovery mechanism to detect the DualNICBC HA mode when
  two BC configs and the extra HA config for ph2sys are found.
- Refactored GetPodLogsRegex and created GetPodLogsRegexSince and moved
  the regex detection to a separate func findRegexInStream().

Author: greyerof

scripts/run-ci-github.sh

@@ -39,5 +39,7 @@ PTP_TEST_MODE=oc ginkgo --skip=".*The interfaces supporting ptp can be discovere
 PTP_TEST_MODE=bc ginkgo --skip=".*The interfaces supporting ptp can be discovered correctly.*" --skip="Negative - run pmc in a new unprivileged pod on the slave node.*" -v --keep-going --output-dir=$JUNIT_OUTPUT_DIR --junit-report=$JUNIT_OUTPUT_FILE -v "$SUITE"/serial
 # Dual NIC BC
 PTP_TEST_MODE=dualnicbc ginkgo --skip=".*The interfaces supporting ptp can be discovered correctly.*" --skip="Negative - run pmc in a new unprivileged pod on the slave node.*" -v --keep-going --output-dir=$JUNIT_OUTPUT_DIR --junit-report=$JUNIT_OUTPUT_FILE -v "$SUITE"/serial
+# Dual NIC BC HA
+PTP_TEST_MODE=dualnicbcha ginkgo --skip=".*The interfaces supporting ptp can be discovered correctly.*" --skip="Negative - run pmc in a new unprivileged pod on the slave node.*" -v --keep-going --output-dir=$JUNIT_OUTPUT_DIR --junit-report=$JUNIT_OUTPUT_FILE -v "$SUITE"/serial
 # Dual port
 PTP_TEST_MODE=dualfollower ginkgo --skip=".*The interfaces supporting ptp can be discovered correctly.*" --skip="Negative - run pmc in a new unprivileged pod on the slave node.*" -v --keep-going --output-dir=$JUNIT_OUTPUT_DIR --junit-report=$JUNIT_OUTPUT_FILE -v "$SUITE"/serial

test/conformance/serial/ptp.go

@@ -8,6 +8,7 @@ import (
 	"os"
 	"path"
 	"regexp"
+	"slices"
 	"sort"
 	"strconv"
 	"strings"
@@ -364,7 +365,7 @@ var _ = Describe("["+strings.ToLower(DesiredMode.String())+"-serial]", Serial, f
 				}
 				err = ptptesthelper.BasicClockSyncCheck(fullConfig, (*ptpv1.PtpConfig)(fullConfig.DiscoveredClockUnderTestPtpConfig), grandmasterID, metrics.MetricClockStateLocked, metrics.MetricRoleSlave, true)
 				Expect(err).To(BeNil())
-				if fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClock {
+				if fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClock || fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClockHA {
 					err = ptptesthelper.BasicClockSyncCheck(fullConfig, (*ptpv1.PtpConfig)(fullConfig.DiscoveredClockUnderTestSecondaryPtpConfig), grandmasterID, metrics.MetricClockStateLocked, metrics.MetricRoleSlave, true)
 					Expect(err).To(BeNil())
 				}
@@ -474,9 +475,11 @@ var _ = Describe("["+strings.ToLower(DesiredMode.String())+"-serial]", Serial, f
 				}
 
 				if fullConfig.PtpModeDiscovered != testconfig.BoundaryClock &&
-					fullConfig.PtpModeDiscovered != testconfig.DualNICBoundaryClock {
+					fullConfig.PtpModeDiscovered != testconfig.DualNICBoundaryClock &&
+					fullConfig.PtpModeDiscovered != testconfig.DualNICBoundaryClockHA {
 					Skip("test only valid for Boundary clock in multi-node clusters")
 				}
+
 				if !fullConfig.FoundSolutions[testconfig.AlgoBCWithSlavesString] &&
 					!fullConfig.FoundSolutions[testconfig.AlgoDualNicBCWithSlavesString] &&
 					!fullConfig.FoundSolutions[testconfig.AlgoBCWithSlavesExtGMString] &&
@@ -489,8 +492,8 @@ var _ = Describe("["+strings.ToLower(DesiredMode.String())+"-serial]", Serial, f
 				err = ptptesthelper.BasicClockSyncCheck(fullConfig, (*ptpv1.PtpConfig)(fullConfig.DiscoveredSlave1PtpConfig), &masterIDBc1, metrics.MetricClockStateLocked, metrics.MetricRoleSlave, true)
 				Expect(err).To(BeNil())
 
-				if (fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClock) && (fullConfig.FoundSolutions[testconfig.AlgoDualNicBCWithSlavesExtGMString] ||
-					fullConfig.FoundSolutions[testconfig.AlgoDualNicBCWithSlavesString]) {
+				if (fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClock || fullConfig.PtpModeDiscovered == testconfig.DualNICBoundaryClockHA) &&
+					(fullConfig.FoundSolutions[testconfig.AlgoDualNicBCWithSlavesExtGMString] || fullConfig.FoundSolutions[testconfig.AlgoDualNicBCWithSlavesString]) {
 					aLabel := pkg.PtpClockUnderTestNodeLabel
 					masterIDBc2, err := ptphelper.GetClockIDMaster(pkg.PtpBcMaster2PolicyName, &aLabel, nil, false)
 					Expect(err).To(BeNil())
@@ -522,7 +525,7 @@ var _ = Describe("["+strings.ToLower(DesiredMode.String())+"-serial]", Serial, f
 						policyName = pkg.PtpSlave1PolicyName
 					case testconfig.BoundaryClock:
 						policyName = pkg.PtpBcMaster1PolicyName
-					case testconfig.DualNICBoundaryClock:
+					case testconfig.DualNICBoundaryClock, testconfig.DualNICBoundaryClockHA:
 						policyName = pkg.PtpBcMaster1PolicyName
 					}
 					ptpConfigToModify, err := client.Client.PtpV1Interface.PtpConfigs(pkg.PtpLinuxDaemonNamespace).Get(context.Background(), policyName, metav1.GetOptions{})
@@ -575,6 +578,111 @@ var _ = Describe("["+strings.ToLower(DesiredMode.String())+"-serial]", Serial, f
 					}
 				})
 			})
+
+			It("DualNICBCHA phc2sys switches to secondary ptp4l when primary interface fails", func() {
+				if fullConfig.PtpModeDiscovered != testconfig.DualNICBoundaryClockHA {
+					Skip("Test only valid for Dual NIC Boundary Clocks with phc2sys HA configuration (DualNICBCHA)")
+				}
+
+				By("Identifying which interface phc2sys is currently using")
+				primaryPtpConfig := (*ptpv1.PtpConfig)(fullConfig.DiscoveredClockUnderTestPtpConfig)
+				primaryBCSlaveInterfaces := ptpv1.GetInterfaces(*primaryPtpConfig, ptpv1.Slave)
+
+				secondaryPtpConfig := (*ptpv1.PtpConfig)(fullConfig.DiscoveredClockUnderTestSecondaryPtpConfig)
+				secondaryBCSlaveInterfaces := ptpv1.GetInterfaces(*secondaryPtpConfig, ptpv1.Slave)
+
+				logrus.Infof("Primary   BC slave interfaces: %v", primaryBCSlaveInterfaces)
+				logrus.Infof("Secondary BC slave interfaces: %v", secondaryBCSlaveInterfaces)
+
+				// Get phc2sys logs to identify which interface it's using
+				const phc2sysLogPattern = `phc2sys(?m).*?:.* selecting (\w+) as out-of-domain source clock`
+				var selectedInterface string
+
+				logMatches, err := pods.GetPodLogsRegex(fullConfig.DiscoveredClockUnderTestPod.Namespace,
+					fullConfig.DiscoveredClockUnderTestPod.Name, pkg.PtpContainerName,
+					phc2sysLogPattern, false, pkg.TimeoutIn1Minute)
+				Expect(err).NotTo(HaveOccurred())
+				Expect(len(logMatches)).To(BeNumerically("==", 1), "Could not identify which interface phc2sys is using")
+
+				logrus.Infof("phc2sys log matching line: %v", logMatches[0][0])
+				selectedInterface = logMatches[0][1]
+
+				// Save it as primary interface
+				primaryInterface := selectedInterface
+				By("Verifying the selected interface " + selectedInterface + " is a primary BC's slave interface")
+				// Check if the selected interface belongs to the primary boundary clock config
+
+				// Check if the selected interface belongs to the primary boundary clock config
+				if !slices.Contains(primaryBCSlaveInterfaces, selectedInterface) {
+					Fail(fmt.Sprintf("Selected interface %s does not belong to the primary boundary clock config. Primary interfaces: %v", selectedInterface, primaryBCSlaveInterfaces))
+				}
+
+				// Wait for some time to ensure the regex won't match the previous log entry
+				time.Sleep(2 * time.Second)
+				ifDownTime := time.Now()
+				By("Taking down the selected interface " + selectedInterface)
+
+				// Use the PortEngine to turn down the interface so phc2sys will switch to the slave interface in the secondary boundary clock
+				portEngine.TurnPortDown(selectedInterface)
+
+				// Wait for the interface to be down and ptp4l to report freerun
+				Eventually(func() error {
+					return metrics.CheckClockRole([]metrics.MetricRole{metrics.MetricRoleFaulty}, []string{selectedInterface}, &fullConfig.DiscoveredClockUnderTestPod.Spec.NodeName)
+				}, 30*time.Second, 5*time.Second).Should(BeNil(), "Primary BC's slave interface "+selectedInterface+" should be in FAULTY state")
+
+				By("Waiting for 5 seconds for the new interface to be selected")
+				time.Sleep(5 * time.Second)
+
+				By("Verifying phc2sys switches to a different interface")
+				// Wait for phc2sys to switch to a different interface
+				var newSelectedInterface string
+				logMatches, err = pods.GetPodLogsRegexSince(fullConfig.DiscoveredClockUnderTestPod.Namespace,
+					fullConfig.DiscoveredClockUnderTestPod.Name, pkg.PtpContainerName,
+					phc2sysLogPattern, false, pkg.TimeoutIn1Minute, ifDownTime)
+				Expect(err).NotTo(HaveOccurred())
+				Expect(len(logMatches)).To(BeNumerically("==", 1), "Could not identify which interface phc2sys is using")
+				// Get the most recent log entry
+				logrus.Infof("phc2sys log matching line: %v", logMatches[0][0])
+				newSelectedInterface = logMatches[0][1]
+
+				// Verify that phc2sys switched to a different interface
+				Expect(newSelectedInterface).ToNot(Equal(selectedInterface), "phc2sys should have switched to a different interface")
+
+				By("Verifying the new selected interface " + newSelectedInterface + " is a secondary BC's slave interface")
+				// Check if the selected interface belongs to the primary boundary clock config
+				if !slices.Contains(secondaryBCSlaveInterfaces, newSelectedInterface) {
+					Fail(fmt.Sprintf("Selected interface %s does not belong to the secondary boundary clock config. Secondary interfaces: %v", newSelectedInterface, secondaryBCSlaveInterfaces))
+				}
+
+				time.Sleep(2 * time.Second)
+				ifUpTime := time.Now()
+				By("Restoring the primary BC's slave interface " + primaryInterface)
+				// Bring the interface back up
+				portEngine.TurnPortUp(primaryInterface)
+
+				// Wait for the interface to recover to SLAVE state
+				Eventually(func() error {
+					return metrics.CheckClockRole([]metrics.MetricRole{metrics.MetricRoleSlave}, []string{primaryInterface}, &fullConfig.DiscoveredClockUnderTestPod.Spec.NodeName)
+				}, 30*time.Second, 5*time.Second).Should(BeNil(), "Primary BC's slave interface "+primaryInterface+" should recover to SLAVE state")
+
+				By("Waiting 5 seconds for the primary BC's slave interface to be selected again")
+				time.Sleep(5 * time.Second)
+
+				// Check the new interfaces is the primary one
+				logMatches, err = pods.GetPodLogsRegexSince(fullConfig.DiscoveredClockUnderTestPod.Namespace,
+					fullConfig.DiscoveredClockUnderTestPod.Name, pkg.PtpContainerName,
+					phc2sysLogPattern, false, pkg.TimeoutIn1Minute, ifUpTime)
+				Expect(err).NotTo(HaveOccurred())
+				Expect(len(logMatches)).To(BeNumerically("==", 1), "Could not identify which interface phc2sys is using")
+				// Get the most recent log entry
+				logrus.Infof("phc2sys log matching line: %v", logMatches[0][0])
+				selectedInterface = logMatches[0][1]
+
+				By("Verifying the selected interface " + selectedInterface + " is the original primary BC's slave interface " + primaryInterface)
+				if selectedInterface != primaryInterface {
+					Fail(fmt.Sprintf("Selected interface %s is not the original primary interface %s", selectedInterface, primaryInterface))
+				}
+			})
 		})
 
 		Context("PTP metric is present", func() {

test/pkg/clean/clean.go

@@ -63,7 +63,8 @@ func Configs() {
 			ptpConfig.Name == pkg.PtpSlave1PolicyName ||
 			ptpConfig.Name == pkg.PtpBcMaster2PolicyName ||
 			ptpConfig.Name == pkg.PtpSlave2PolicyName ||
-			ptpConfig.Name == pkg.PtpTempPolicyName {
+			ptpConfig.Name == pkg.PtpTempPolicyName ||
+			ptpConfig.Name == pkg.PtpDualNicBCHAPolicyName {
 			err = client.Client.PtpConfigs(pkg.PtpLinuxDaemonNamespace).Delete(context.Background(), ptpConfig.Name, metav1.DeleteOptions{})
 			if err != nil {
 				logrus.Infof("clean.All: Failed to delete ptp config %s %v", ptpConfig.Name, err)

test/pkg/consts.go

@@ -31,6 +31,7 @@ const (
 	PtpSlave1PolicyName         = "test-slave1"
 	PtpBcMaster2PolicyName      = "test-bc-master2"
 	PtpSlave2PolicyName         = "test-slave2"
+	PtpDualNicBCHAPolicyName    = "test-dual-nic-bc-ha"
 	PtpTempPolicyName           = "temp"
 
 	// node labels

test/pkg/pods/pods.go

@@ -3,6 +3,7 @@ package pods
 import (
 	"bytes"
 	"context"
+	"errors"
 	"fmt"
 	"io"
 	"regexp"
@@ -137,6 +138,71 @@ func WaitForPhase(cs *testclient.ClientSet, pod *corev1.Pod, phaseType corev1.Po
 	})
 }
 
+func findRegexInStream(stream io.ReadCloser, r *regexp.Regexp, timeout time.Duration) (matches [][]string, err error) {
+	logContent := ""
+	buf := make([]byte, 2000)
+
+	for start := time.Now(); time.Since(start) <= timeout && len(matches) == 0; {
+		numBytes, err := stream.Read(buf)
+		if err != nil {
+			if err == io.EOF {
+				logContent += string(buf[:numBytes])
+				matches = r.FindAllStringSubmatch(logContent, -1)
+				break
+			} else {
+				return nil, fmt.Errorf("error reading from stream: %s", err)
+			}
+		}
+
+		if numBytes == 0 {
+			time.Sleep(100 * time.Millisecond)
+			continue
+		}
+
+		logContent += string(buf[:numBytes])
+		matches = r.FindAllStringSubmatch(logContent, -1)
+	}
+
+	if len(matches) == 0 {
+		return matches, errors.New("timedout waiting for matches")
+	}
+
+	return matches, nil
+}
+
+// returns last Regex match in the logs for a given pod
+func GetPodLogsRegexSince(namespace string, podName string, containerName, regex string, isLiteralText bool, timeout time.Duration, since time.Time) (matches [][]string, err error) {
+	const matchOnlyFullLines = `\s*^`
+	if isLiteralText {
+		regex = regexp.QuoteMeta(regex)
+	} else {
+		regex += matchOnlyFullLines
+	}
+
+	r := regexp.MustCompile(regex)
+
+	podLogOptions := corev1.PodLogOptions{
+		Container: containerName,
+		Follow:    true,
+		SinceTime: &metav1.Time{Time: since},
+	}
+
+	podLogRequest := testclient.Client.CoreV1().Pods(namespace).GetLogs(podName, &podLogOptions)
+
+	stream, err := podLogRequest.Stream(context.TODO())
+	if err != nil {
+		return matches, fmt.Errorf("failed to open log streamn for %s/%s container=%s, err=%s", namespace, podName, containerName, err)
+	}
+	defer stream.Close()
+
+	matches, err = findRegexInStream(stream, r, timeout)
+	if err != nil {
+		return matches, fmt.Errorf("could not find regex in log stream for %s/%s container=%s, err=%s", namespace, podName, containerName, err)
+	}
+
+	return matches, nil
+}
+
 // returns last Regex match in the logs for a given pod
 func GetPodLogsRegex(namespace string, podName string, containerName, regex string, isLiteralText bool, timeout time.Duration) (matches [][]string, err error) {
 	const matchOnlyFullLines = `\s*^`
@@ -145,46 +211,27 @@ func GetPodLogsRegex(namespace string, podName string, containerName, regex stri
 	} else {
 		regex += matchOnlyFullLines
 	}
-	//count := int64(100)
+
+	r := regexp.MustCompile(regex)
+
 	podLogOptions := corev1.PodLogOptions{
 		Container: containerName,
 		Follow:    true,
-		//TailLines: &count,
 	}
 
 	podLogRequest := testclient.Client.CoreV1().Pods(namespace).GetLogs(podName, &podLogOptions)
+
 	stream, err := podLogRequest.Stream(context.TODO())
 	if err != nil {
-		return matches, fmt.Errorf("could not retrieve log in ns=%s pod=%s, err=%s", namespace, podName, err)
+		return matches, fmt.Errorf("failed to open log streamn for %s/%s container=%s, err=%s", namespace, podName, containerName, err)
 	}
 	defer stream.Close()
-	start := time.Now()
-	message := ""
-	for {
-		t := time.Now()
-		elapsed := t.Sub(start)
-		if elapsed > timeout {
-			return matches, fmt.Errorf("timedout waiting for log in ns=%s pod=%s, looking for = %s", namespace, podName, regex)
-		}
-		buf := make([]byte, 2000)
-		numBytes, err := stream.Read(buf)
-		if numBytes == 0 {
-			continue
-		}
-		if err == io.EOF {
-			break
-		}
-		if err != nil {
-			return matches, fmt.Errorf("error getting log stream in ns=%s pod=%s, err=%s", namespace, podName, err)
-		}
-		message += string(buf[:numBytes])
-		r := regexp.MustCompile(regex)
-		matches = r.FindAllStringSubmatch(message, -1)
-		if len(matches) > 0 {
-			return matches, nil
-		}
 
+	matches, err = findRegexInStream(stream, r, timeout)
+	if err != nil {
+		return matches, fmt.Errorf("could not find regex in log stream for %s/%s container=%s, err=%s", namespace, podName, containerName, err)
 	}
+
 	return matches, nil
 }
 

test/pkg/ptphelper/ptphelper.go

@@ -651,6 +651,24 @@ func IsSecondaryBc(config *ptpv1.PtpConfig) bool {
 	return true
 }
 
+// Checks if the ptpSettings has more than one HA profile
+func hasHaProfiles(ptpSettings map[string]string) bool {
+	logrus.Infof("Checking if ptpSettings %v has more than one HA profile", ptpSettings)
+	return ptpSettings != nil && ptpSettings["haProfiles"] != "" && len(strings.Split(ptpSettings["haProfiles"], ",")) > 1
+}
+
+// Checks for DualNIC BC HA
+func ConfigIsPhc2SysHa(config *ptpv1.PtpConfig) bool {
+	logrus.Infof("Checking if config %s is Phc2Sys HA", config.Name)
+	for _, profile := range config.Spec.Profile {
+		if profile.Phc2sysOpts != nil && profile.Ptp4lOpts != nil && *profile.Ptp4lOpts == "" && hasHaProfiles(profile.PtpSettings) {
+			logrus.Infof("Config %s is Phc2Sys HA", config.Name)
+			return true
+		}
+	}
+	return false
+}
+
 // Checks for OC
 func IsPtpSlave(ptp4lOpts, phc2sysOpts *string) bool {
 	return /*strings.Contains(*ptp4lOpts, "-s") &&*/ ((phc2sysOpts != nil && (strings.Count(*phc2sysOpts, "-a") == 1 && strings.Count(*phc2sysOpts, "-r") == 1)) ||