Fix: Wait for ptp4l/phc2sys death before PF rebind in validation conftest

.github/instructions/mtl-validation-tests.instructions.md

@@ -123,6 +123,8 @@ sudo grep -E "EAL|hugepage|VF|RxTxApp|RemoteProcess|Traceback|err:" \
 | RxTxApp `Segmentation fault` inside `iavf_tm_node_add` (after `dev_if_init_pacing(0), try rl as drv support TM`) | **(setup)** Stock kernel ice loaded instead of the MTL out-of-tree patched ice (`versions.env::ICE_VER`). Re-run `setup_validation.sh` — the ice stage version-checks and reloads automatically. |
 | RxTxApp `Segmentation fault` anywhere else | **NOT setup.** Capture `gdb -batch -ex 'bt full' .local_install/mtl/bin/RxTxApp /tmp/core.*` (or `coredumpctl gdb RxTxApp`) and report upstream as a real MTL/DPDK bug. Do **not** add a workaround. |
 | `Permission denied (publickey)` to `root@127.0.0.1` | **(setup)** Pubkey not in `/root/.ssh/authorized_keys`. |
+| `preflight: MtlManager or RxTxApp missing` despite binaries present under `.local_install/mtl/bin/` | **(setup)** Fixed: preflight now checks both the legacy in-tree `build/` path and the `.local_install` prefix that `mtl_engine/const.py::PREFIX` actually invokes. Re-run setup. |
+| `preflight: hugepages free is 64 MiB (<1024 MiB)` on a host with 1GB hugepages configured (`default_hugepagesz=1G` on kernel cmdline) | **(setup)** Fixed: hugepage check now reads `Hugepagesize` from `/proc/meminfo` instead of assuming 2MB pages. Re-run setup. |
 
 **(setup)** = re-run `setup_environment.sh` (build stage) and/or `setup_validation.sh`
 (pytest-custom stage) — both are idempotent, safe to re-run on an already-prepared host.

.github/scripts/setup_validation.sh

@@ -182,7 +182,7 @@ print_summary() {
 	log " .local_install/ffmpeg/bin/ffmpeg  : $([[ -x .local_install/ffmpeg/bin/ffmpeg ]] && echo OK || echo 'MISSING (only needed for application=ffmpeg tests)')"
 	log " libdpdk (system, for gtest)       : $(pkg-config --modversion libdpdk 2>/dev/null || echo MISSING)"
 	log " ice driver     : $(modinfo ice 2>/dev/null | awk '/^version:/ {print $2; exit}' || echo MISSING) @ $(modinfo -n ice 2>/dev/null || echo '<none>')"
-	log " hugepages free : $(awk '/HugePages_Free/ {print $2*2 " MiB"}' /proc/meminfo)"
+	log " hugepages free : $(hugepages_free_mb) MiB"
 	if mountpoint -q /mnt/media; then
 		log " /mnt/media     : $(findmnt -no SOURCE /mnt/media) ($(df -h /mnt/media | awk 'NR==2{print $5" used of "$2}'))"
 		log " media files    : $(find /mnt/media -mindepth 1 -maxdepth 1 2>/dev/null | wc -l) entries"
@@ -196,6 +196,23 @@ print_summary() {
 	trap_arm
 }
 
+# RxTxApp/MtlManager may live at the legacy in-tree build path or at the
+# .local_install prefix that tests/validation/mtl_engine/const.py::PREFIX
+# actually invokes — accept either so preflight matches what pytest runs.
+mtl_rxtxapp_present() {
+	[[ -x tests/tools/RxTxApp/build/RxTxApp || -x .local_install/mtl/bin/RxTxApp ]]
+}
+
+mtl_manager_present() {
+	[[ -x build/manager/MtlManager || -x .local_install/mtl/bin/MtlManager ]]
+}
+
+# Hugepage size varies by host (2MB vs 1GB default_hugepagesz=1G on the
+# kernel cmdline); HugePages_Free*2 silently under-reports on 1GB-page hosts.
+hugepages_free_mb() {
+	awk '/Hugepagesize:/ {sz=$2} /HugePages_Free:/ {free=$2} END {printf "%d", free*sz/1024}' /proc/meminfo
+}
+
 # ============================================================================
 # STAGE FUNCTIONS
 # ============================================================================
@@ -261,19 +278,24 @@ stage_preflight() {
 		warn "preflight: libmtl.so missing in ld cache"
 		missing=1
 	fi
+<<<<<<< HEAD
 	# NOTE: pytest needs .local_install/mtl/bin/{MtlManager,RxTxApp}, built by
 	# MCP tool setup_validation_base/setup_validation_full — a SEPARATE tree
 	# from build/manager + tests/tools/RxTxApp/build used by gtest/KahawaiTest.
 	if [[ ! -x .local_install/mtl/bin/MtlManager || ! -x .local_install/mtl/bin/RxTxApp ]]; then
 		warn "preflight: .local_install/mtl/bin/{MtlManager,RxTxApp} missing (pytest needs this, not build/manager or tests/tools/RxTxApp/build)"
+=======
+	if ! mtl_manager_present || ! mtl_rxtxapp_present; then
+		warn "preflight: MtlManager or RxTxApp missing"
+>>>>>>> 96ed3d2e (Fix: Detect .local_install RxTxApp/MtlManager and 1G hugepages in setup_validation.sh)
 		missing=1
 	fi
 	ice_path=$(modinfo -n ice 2>/dev/null || true)
 	if [[ "$ice_path" != *"/updates/"* ]]; then
 		warn "preflight: out-of-tree ice driver not loaded (path=$ice_path)"
 		missing=1
 	fi
-	free_mb=$(awk '/HugePages_Free/ {print $2*2}' /proc/meminfo)
+	free_mb=$(hugepages_free_mb)
 	if ((free_mb < 1024)); then
 		warn "preflight: hugepages free is ${free_mb} MiB (<1024 MiB)"
 		missing=1

tests/validation/common/nicctl.py

@@ -394,6 +394,45 @@ def get_mixed_interfaces_list_single(
                 f"Found {len(host.network_interfaces)} interface(s)."
             )
 
+        tx_pci = host.network_interfaces[tx_index].pci_address.lspci
+        rx_pci = host.network_interfaces[rx_index].pci_address.lspci
+
+        # Check IOMMU group of TX and RX PFs.
+        # One PF is bound to PMD (vfio-pci), while the other PF remains bound to the kernel (host for run/VFs).
+        # This is impossible if they share the same IOMMU group because VFIO group viability is violated.
+        try:
+            tx_group = (
+                self.nicctl_objs[host.name]
+                .connection.execute_command(
+                    f"basename $(readlink /sys/bus/pci/devices/{tx_pci}/iommu_group 2>/dev/null) 2>/dev/null"
+                )
+                .stdout
+                or ""
+            ).strip()
+            rx_group = (
+                self.nicctl_objs[host.name]
+                .connection.execute_command(
+                    f"basename $(readlink /sys/bus/pci/devices/{rx_pci}/iommu_group 2>/dev/null) 2>/dev/null"
+                )
+                .stdout
+                or ""
+            ).strip()
+            if tx_group and rx_group and tx_group == rx_group:
+                if (
+                    tx_interface_type.lower() == "pf"
+                    and rx_interface_type.lower() == "vf"
+                ) or (
+                    tx_interface_type.lower() == "vf"
+                    and rx_interface_type.lower() == "pf"
+                ):
+                    pytest.skip(
+                        f"Skipping mixed PF/VF test: PF {tx_pci} and PF {rx_pci} share the same IOMMU group "
+                        f"({tx_group}) "
+                        f"and cannot be bound to different drivers (vfio-pci vs ice) simultaneously."
+                    )
+        except Exception as e:
+            logger.warning(f"Failed to check IOMMU group conflict: {e}")
+
         tx_interface = self._get_single_interface_by_type(
             host, tx_interface_type, tx_index
         )

tests/validation/conftest.py

@@ -55,6 +55,7 @@
 )
 from pytest_mfd_config.models.topology import TopologyModel
 from pytest_mfd_logging.amber_log_formatter import AmberLogFormatter
+from tests.single.ptp.ptp_helpers import wait_for_ptp4l_foreign_master
 
 logger = logging.getLogger(__name__)
 
@@ -376,13 +377,41 @@ def _select_capture_host(hosts: dict):
     return hosts["client"] if "client" in hosts else list(hosts.values())[0]
 
 
-_REAP_GRACE_SEC = 0.3  # Grace period between SIGTERM and SIGKILL for ptp daemons
+_REAP_POLL_TIMEOUT_SEC = 3  # Max time to wait for a killed daemon to actually exit
 _PHC_SYNC_THRESHOLD_NS = 2000  # Capture PHC must track TAI this tightly
 _PHC_SYNC_TIMEOUT_SEC = 30  # Max wait for phc2sys to converge before capturing
 
 
+def _wait_daemon_dead(host, name: str, timeout_s: float) -> bool:
+    """Poll (best-effort) until no process named *name* remains, up to *timeout_s*.
+
+    A bare ``sleep()`` after ``pkill`` does not guarantee the kernel has
+    finished tearing down the process -- and releasing any PF netdev/PHC fd
+    it held (e.g. ptp4l on the PF interface) -- by the time the caller
+    proceeds. That gap has been observed to race nicctl's VF/PF rebind
+    checks (``_wait_vfio_idle`` / ``bind_kernel`` / ``disable_vf``): if the
+    fd is still open, those calls time out and fall back to a PCI
+    remove+rescan, which force-reprobes the PF (``ice_probe``) and can hit
+    an ``ice`` driver GPF (RSS flow-profile UAF in ``ice_add_prof``).
+    Polling for actual daemon death closes that race. Returns True once
+    confirmed dead (or if liveness can't be probed); False on timeout.
+    """
+    deadline = time.monotonic() + timeout_s
+    while time.monotonic() < deadline:
+        try:
+            res = host.connection.execute_command(
+                f"pgrep -x {name}", expected_return_codes=None
+            )
+        except Exception:
+            return True  # cannot probe; don't block the caller forever
+        if res.return_code != 0:
+            return True
+        time.sleep(0.1)
+    return False
+
+
 def _reap_ptp_daemons(host, *, patterns=("phc2sys", "ptp4l")) -> None:
-    """Forcefully kill any ptp4l/phc2sys daemons.
+    """Forcefully kill any ptp4l/phc2sys daemons and wait for them to exit.
 
     Required because ``host.connection.start_process('sudo <tool> ...')`` wraps
     the daemon in ``bash -c 'sudo ...'``; ``process.kill(SIGTERM)`` only signals
@@ -391,6 +420,9 @@ def _reap_ptp_daemons(host, *, patterns=("phc2sys", "ptp4l")) -> None:
     stale ``struct ptp_clock *`` across SR-IOV VF cycling and have been seen to
     trigger ``ice``-driver use-after-free in ``ptp_clock_index()``, hanging the
     host. Always cleanup via ``pkill`` on the argv, not via the process handle.
+    We also wait for the kill to actually take effect (see
+    :func:`_wait_daemon_dead`) instead of a blind sleep, since callers rebind
+    the PF right after this returns.
     """
     for name in patterns:
         try:
@@ -399,14 +431,23 @@ def _reap_ptp_daemons(host, *, patterns=("phc2sys", "ptp4l")) -> None:
             )
         except Exception as e:
             logger.debug("pkill -TERM %s: %s", name, e)
-    time.sleep(_REAP_GRACE_SEC)
+    for name in patterns:
+        _wait_daemon_dead(host, name, _REAP_POLL_TIMEOUT_SEC)
     for name in patterns:
         try:
             host.connection.execute_command(
                 f"sudo pkill -KILL -x {name} || true", expected_return_codes=None
             )
         except Exception as e:
             logger.debug("pkill -KILL %s: %s", name, e)
+    for name in patterns:
+        if not _wait_daemon_dead(host, name, _REAP_POLL_TIMEOUT_SEC):
+            logger.warning(
+                "%s on %s still alive %ss after SIGKILL; PF rebind may race it",
+                name,
+                host.name,
+                _REAP_POLL_TIMEOUT_SEC,
+            )
 
 
 def _host_tai_utc_offset(host) -> int:
@@ -571,30 +612,61 @@ def ptp_sync(request, test_config: dict, hosts):
 
     host = _select_capture_host(hosts)
     is_single_host = len(hosts) == 1
-    capture_iface = _select_sniff_interface_name(
-        host, capture_cfg, single_host=is_single_host
-    )
 
     # Belt-and-braces: ensure no leftover daemon from a previous test/session
     # is holding a stale PHC handle before we start a new one.
     _reap_ptp_daemons(host)
 
-    logger.info(f"Starting ptp4l for PTP synchronization (iface={capture_iface})")
-    log_path = f"/tmp/ptp4l-{capture_iface}.log"
-    ptp4l_cmd = f"sudo ptp4l -i '{capture_iface}' -s -m -2"
-    ptp4l_process = host.connection.start_process(
-        ptp4l_cmd,
-        stderr_to_stdout=True,
-        output_file=log_path,
+    # Sync ONLY the capture interface. Both ports of an E810/E830 adapter share
+    # one PHC (/dev/ptpN), so a second ptp4l instance does not get its own clock
+    # -- it fights the first one over the same hardware clock. Worse, when that
+    # second port is link-down (just rebound by a previous test) its ptp4l
+    # declares itself grandmaster and free-runs the shared PHC, smearing the
+    # capture timestamps until EBU LIST can no longer parse a stream at all.
+    # Only the capture PHC has to follow the grandmaster.
+    interfaces_to_sync = []
+    capture_iface = _select_sniff_interface_name(
+        host, capture_cfg, single_host=is_single_host
     )
+    check_cmd = f"[ -d /sys/class/net/{capture_iface} ]"
+    res = host.connection.execute_command(check_cmd, expected_return_codes=None)
+    if res.return_code == 0:
+        interfaces_to_sync.append(capture_iface)
+    else:
+        logger.warning(
+            f"PTP skip: Capture interface {capture_iface} is not present in /sys/class/net/"
+        )
 
-    # Give ptp4l a moment to fail fast (e.g., missing interface).
-    time.sleep(0.2)
-    if not ptp4l_process.running:
-        _reap_ptp_daemons(host)
-        raise RuntimeError(
-            f"Failed to start ptp4l (iface={capture_iface}). log={log_path}"
+    ptp4l_processes = []
+    for iface in interfaces_to_sync:
+        logger.info(f"Starting ptp4l for PTP synchronization (iface={iface})")
+        log_path = f"/tmp/ptp4l-{iface}.log"
+        ptp4l_cmd = f"sudo ptp4l -i '{iface}' -s -m -2"
+        ptp4l_process = host.connection.start_process(
+            ptp4l_cmd,
+            stderr_to_stdout=True,
+            output_file=log_path,
         )
+        time.sleep(0.2)
+        if not ptp4l_process.running:
+            _reap_ptp_daemons(host)
+            raise RuntimeError(f"Failed to start ptp4l (iface={iface}). log={log_path}")
+        ptp4l_processes.append(ptp4l_process)
+
+    # A hardware PTP clock that never actually locks to a grandmaster (or
+    # never even hears one) free-runs -- exactly the condition that produced
+    # a ~-55.8s packet_ts_vs_rtp_ts offset and VRX compliance failure in the
+    # past (see /memories/repo/ptp_sync_fixture_root_cause.md). Block here,
+    # before the test body/pcap_capture ever touch this clock, so a dead/
+    # unreachable grandmaster surfaces as a fast, clear ERROR. Must reap on
+    # timeout too, else the just-started ptp4l processes are orphaned (same
+    # leak class _reap_ptp_daemons/reap_leaked_phc_daemons exist to prevent).
+    try:
+        for iface in interfaces_to_sync:
+            wait_for_ptp4l_foreign_master(host, f"/tmp/ptp4l-{iface}.log")
+    except Exception:
+        _reap_ptp_daemons(host)
+        raise
 
     try:
         yield
@@ -1246,12 +1318,12 @@ def pcap_capture(
                         streams = (report or {}).get("streams") or []
                         if not streams:
                             # Empty capture — interface may not see VF-to-VF
-                            # loopback traffic.  Not a real failure.
-                            update_compliance_result(request.node.nodeid, "N/A")
-                            logger.warning(
-                                "PCAP compliance check skipped: capture "
-                                "contains no streams (capture interface may "
-                                "not see VF-to-VF loopback traffic)"
+                            # loopback traffic. Reject with a test failure so we catch false passes.
+                            update_compliance_result(request.node.nodeid, "Fail")
+                            log_fail(
+                                "PCAP compliance check failed: capture contains no streams. "
+                                "Normally interface may not see VF-to-VF loopback traffic, "
+                                "but empty capture is disallowed for strict validation/compliance."
                             )
                         else:
                             update_compliance_result(request.node.nodeid, "Fail")

tests/validation/mtl_engine/application_base.py

@@ -22,6 +22,16 @@
 MTL_PTP_INTERNAL_TIMEOUT = 180
 
 
+# MTL dumps ``PTP(<port>): delta avg <ns> ...`` (or ``PTP(<port>): not
+# connected``) with every stat interval. Until it locks, MTL stamps RTP
+# timestamps from the system clock while the capture NIC PHC already follows
+# the grandmaster -- the two timescales differ by seconds, which EBU LIST
+# reports as ``invalid_delta_packet_ts_vs_rtp_ts``.
+_MTL_PTP_DELTA_RE = re.compile(r"PTP\(\d+\): delta avg (-?\d+)")
+_MTL_PTP_LOCK_TOLERANCE_NS = 1_000_000
+_MTL_PTP_LOCK_TIMEOUT = 150
+
+
 # Encoder name -> MTL st22 plugin shared object, for require_encoder()
 # pre-flight checks shared across framework adapters.
 MTL_ENCODER_PLUGIN_MAP = {
@@ -440,21 +450,48 @@ def _make_netsniff_hook(self, netsniff) -> Callable:
         capture window aligns with the steady-state stream.
         """
 
-        def _hook(_first_proc) -> None:
+        def _hook(first_proc) -> None:
             try:
                 if self.params.get("enable_ptp", False):
-                    ptp_sync_time = self.params.get("ptp_sync_time", 50)
-                    logger.info(
-                        "Waiting %ds for PTP sync before netsniff capture",
-                        ptp_sync_time,
-                    )
-                    time.sleep(ptp_sync_time)
+                    self._wait_mtl_ptp_locked(first_proc)
                 self._start_netsniff_capture(netsniff)
             except Exception as e:
                 logger.warning("netsniff capture setup failed: %s", e)
 
         return _hook
 
+    def _wait_mtl_ptp_locked(self, proc) -> bool:
+        """Block until MTL reports a locked PTP delta, or the budget expires.
+
+        The capture and the transmitted RTP timestamps must share one
+        timescale. MTL only stamps from the grandmaster once its PTP client
+        locks -- which can take well over a minute after a PF is (re)bound to
+        DPDK -- so capturing on a fixed sleep can sample a window where MTL is
+        still on the system clock and every packet fails compliance.
+        """
+        timeout = self.params.get("ptp_lock_timeout", _MTL_PTP_LOCK_TIMEOUT)
+        logger.info(
+            "Waiting up to %ds for MTL PTP lock before netsniff capture", timeout
+        )
+        deadline = time.monotonic() + timeout
+        try:
+            for line in proc.get_stdout_iter():
+                match = _MTL_PTP_DELTA_RE.search(line)
+                if match and abs(int(match.group(1))) < _MTL_PTP_LOCK_TOLERANCE_NS:
+                    logger.info("MTL PTP locked (delta avg %sns)", match.group(1))
+                    return True
+                if time.monotonic() > deadline:
+                    break
+        except Exception as e:
+            logger.warning("Could not read MTL PTP state: %s", e)
+            return False
+        logger.warning(
+            "MTL PTP did not lock within %ds; capture timestamps may not match "
+            "the RTP media clock",
+            timeout,
+        )
+        return False
+
     def _dispatch_validate(self, fail_on_error: bool) -> bool:
         """Run :meth:`validate_results` with consistent soft-fail semantics."""
         try: