MAP: Use explicit address/prefix types in API
[vpp.git] / test / vpp_pg_interface.py
index b5929a4..1300f1f 100644 (file)
@@ -1,8 +1,10 @@
 import os
 import time
 import socket
-from traceback import format_exc
+import struct
+from traceback import format_exc, format_stack
 from scapy.utils import wrpcap, rdpcap, PcapReader
+from scapy.plist import PacketList
 from vpp_interface import VppInterface
 
 from scapy.layers.l2 import Ether, ARP
@@ -13,6 +15,12 @@ from util import ppp, ppc
 from scapy.utils6 import in6_getnsma, in6_getnsmac, in6_ismaddr
 from scapy.utils import inet_pton, inet_ntop
 
+
+class CaptureTimeoutError(Exception):
+    """ Exception raised if capture or packet doesn't appear within timeout """
+    pass
+
+
 def is_ipv6_misc(p):
     """ Is packet one of uninteresting IPv6 broadcasts? """
     if p.haslayer(ICMPv6ND_RA):
@@ -76,13 +84,14 @@ class VppPGInterface(VppInterface):
 
     def __init__(self, test, pg_index):
         """ Create VPP packet-generator interface """
-        r = test.vapi.pg_create_interface(pg_index)
-        self._sw_if_index = r.sw_if_index
-
         super(VppPGInterface, self).__init__(test)
 
+        r = test.vapi.pg_create_interface(pg_index)
+        self.set_sw_if_index(r.sw_if_index)
+
         self._in_history_counter = 0
         self._out_history_counter = 0
+        self._out_assert_counter = 0
         self._pg_index = pg_index
         self._out_file = "pg%u_out.pcap" % self.pg_index
         self._out_path = self.test.tempdir + "/" + self._out_file
@@ -91,25 +100,25 @@ class VppPGInterface(VppInterface):
         self._capture_cli = "packet-generator capture pg%u pcap %s" % (
             self.pg_index, self.out_path)
         self._cap_name = "pcap%u" % self.sw_if_index
-        self._input_cli = "packet-generator new pcap %s source pg%u name %s" % (
-            self.in_path, self.pg_index, self.cap_name)
+        self._input_cli = \
+            "packet-generator new pcap %s source pg%u name %s" % (
+                self.in_path, self.pg_index, self.cap_name)
 
-    def rotate_out_file(self):
+    def enable_capture(self):
+        """ Enable capture on this packet-generator interface"""
         try:
             if os.path.isfile(self.out_path):
-                os.rename(self.out_path,
-                          "%s/history.[timestamp:%f].[%s-counter:%04d].%s" %
-                          (self.test.tempdir,
-                           time.time(),
-                           self.name,
-                           self.out_history_counter,
-                           self._out_file))
+                name = "%s/history.[timestamp:%f].[%s-counter:%04d].%s" % \
+                    (self.test.tempdir,
+                     time.time(),
+                     self.name,
+                     self.out_history_counter,
+                     self._out_file)
+                self.test.logger.debug("Renaming %s->%s" %
+                                       (self.out_path, name))
+                os.rename(self.out_path, name)
         except:
             pass
-
-    def enable_capture(self):
-        """ Enable capture on this packet-generator interface"""
-        self.rotate_out_file()
         # FIXME this should be an API, but no such exists atm
         self.test.vapi.cli(self.capture_cli)
         self._pcap_reader = None
@@ -123,13 +132,15 @@ class VppPGInterface(VppInterface):
         """
         try:
             if os.path.isfile(self.in_path):
-                os.rename(self.in_path,
-                          "%s/history.[timestamp:%f].[%s-counter:%04d].%s" %
-                          (self.test.tempdir,
-                           time.time(),
-                           self.name,
-                           self.in_history_counter,
-                           self._in_file))
+                name = "%s/history.[timestamp:%f].[%s-counter:%04d].%s" %\
+                    (self.test.tempdir,
+                     time.time(),
+                     self.name,
+                     self.in_history_counter,
+                     self._in_file)
+                self.test.logger.debug("Renaming %s->%s" %
+                                       (self.in_path, name))
+                os.rename(self.in_path, name)
         except:
             pass
         wrpcap(self.in_path, pkts)
@@ -137,6 +148,22 @@ class VppPGInterface(VppInterface):
         # FIXME this should be an API, but no such exists atm
         self.test.vapi.cli(self.input_cli)
 
+    def generate_debug_aid(self, kind):
+        """ Create a hardlink to the out file with a counter and a file
+        containing stack trace to ease debugging in case of multiple capture
+        files present. """
+        self.test.logger.debug("Generating debug aid for %s on %s" %
+                               (kind, self._name))
+        link_path, stack_path = ["%s/debug_%s_%s_%s.%s" %
+                                 (self.test.tempdir, self._name,
+                                  self._out_assert_counter, kind, suffix)
+                                 for suffix in ["pcap", "stack"]
+                                 ]
+        os.link(self.out_path, link_path)
+        with open(stack_path, "w") as f:
+            f.writelines(format_stack())
+        self._out_assert_counter += 1
+
     def _get_capture(self, timeout, filter_out_fn=is_ipv6_misc):
         """ Helper method to get capture and filter it """
         try:
@@ -145,7 +172,7 @@ class VppPGInterface(VppInterface):
             output = rdpcap(self.out_path)
             self.test.logger.debug("Capture has %s packets" % len(output.res))
         except:
-            self.test.logger.debug("Exception in scapy.rdpcap(%s): %s" %
+            self.test.logger.debug("Exception in scapy.rdpcap (%s): %s" %
                                    (self.out_path, format_exc()))
             return None
         before = len(output.res)
@@ -181,8 +208,9 @@ class VppPGInterface(VppInterface):
             based_on = "based on stored packet_infos"
             if expected_count == 0:
                 raise Exception(
-                    "Internal error, expected packet count for %s is 0!" % name)
-        self.test.logger.debug("Expecting to capture %s(%s) packets on %s" % (
+                    "Internal error, expected packet count for %s is 0!" %
+                    name)
+        self.test.logger.debug("Expecting to capture %s (%s) packets on %s" % (
             expected_count, based_on, name))
         while remaining_time > 0:
             before = time.time()
@@ -192,10 +220,21 @@ class VppPGInterface(VppInterface):
                 if len(capture.res) == expected_count:
                     # bingo, got the packets we expected
                     return capture
+                elif len(capture.res) > expected_count:
+                    self.test.logger.error(
+                        ppc("Unexpected packets captured:", capture))
+                    break
+                else:
+                    self.test.logger.debug("Partial capture containing %s "
+                                           "packets doesn't match expected "
+                                           "count %s (yet?)" %
+                                           (len(capture.res), expected_count))
             elif expected_count == 0:
-                return None
+                # bingo, got None as we expected - return empty capture
+                return PacketList()
             remaining_time -= elapsed_time
         if capture:
+            self.generate_debug_aid("count-mismatch")
             raise Exception("Captured packets mismatch, captured %s packets, "
                             "expected %s packets on %s" %
                             (len(capture.res), expected_count, name))
@@ -213,22 +252,19 @@ class VppPGInterface(VppInterface):
             try:
                 capture = self.get_capture(
                     0, remark=remark, filter_out_fn=filter_out_fn)
-                if capture:
-                    if len(capture.res) == 0:
-                        # junk filtered out, we're good
-                        return
-                    self.test.logger.error(
-                        ppc("Unexpected packets captured:", capture))
+                if not capture or len(capture.res) == 0:
+                    # junk filtered out, we're good
+                    return
             except:
                 pass
+            self.generate_debug_aid("empty-assert")
             if remark:
                 raise AssertionError(
-                    "Non-empty capture file present for interface %s(%s)" %
+                    "Non-empty capture file present for interface %s (%s)" %
                     (self.name, remark))
             else:
-                raise AssertionError(
-                    "Non-empty capture file present for interface %s" %
-                    self.name)
+                raise AssertionError("Capture file present for interface %s" %
+                                     self.name)
 
     def wait_for_capture_file(self, timeout=1):
         """
@@ -238,7 +274,7 @@ class VppPGInterface(VppInterface):
 
         :returns: True/False if the file is present or appears within timeout
         """
-        limit = time.time() + timeout
+        deadline = time.time() + timeout
         if not os.path.isfile(self.out_path):
             self.test.logger.debug("Waiting for capture file %s to appear, "
                                    "timeout is %ss" % (self.out_path, timeout))
@@ -246,18 +282,43 @@ class VppPGInterface(VppInterface):
             self.test.logger.debug("Capture file %s already exists" %
                                    self.out_path)
             return True
-        while time.time() < limit:
+        while time.time() < deadline:
             if os.path.isfile(self.out_path):
                 break
             time.sleep(0)  # yield
         if os.path.isfile(self.out_path):
             self.test.logger.debug("Capture file appeared after %fs" %
-                                   (time.time() - (limit - timeout)))
+                                   (time.time() - (deadline - timeout)))
         else:
             self.test.logger.debug("Timeout - capture file still nowhere")
             return False
         return True
 
+    def verify_enough_packet_data_in_pcap(self):
+        """
+        Check if enough data is available in file handled by internal pcap
+        reader so that a whole packet can be read.
+
+        :returns: True if enough data present, else False
+        """
+        orig_pos = self._pcap_reader.f.tell()  # save file position
+        enough_data = False
+        # read packet header from pcap
+        packet_header_size = 16
+        caplen = None
+        end_pos = None
+        hdr = self._pcap_reader.f.read(packet_header_size)
+        if len(hdr) == packet_header_size:
+            # parse the capture length - caplen
+            sec, usec, caplen, wirelen = struct.unpack(
+                self._pcap_reader.endian + "IIII", hdr)
+            self._pcap_reader.f.seek(0, 2)  # seek to end of file
+            end_pos = self._pcap_reader.f.tell()  # get position at end
+            if end_pos >= orig_pos + len(hdr) + caplen:
+                enough_data = True  # yay, we have enough data
+        self._pcap_reader.f.seek(orig_pos, 0)  # restore original position
+        return enough_data
+
     def wait_for_packet(self, timeout, filter_out_fn=is_ipv6_misc):
         """
         Wait for next packet captured with a timeout
@@ -270,21 +331,31 @@ class VppPGInterface(VppInterface):
         deadline = time.time() + timeout
         if self._pcap_reader is None:
             if not self.wait_for_capture_file(timeout):
-                raise Exception("Capture file %s did not appear within "
-                                "timeout" % self.out_path)
+                raise CaptureTimeoutError("Capture file %s did not appear "
+                                          "within timeout" % self.out_path)
             while time.time() < deadline:
                 try:
                     self._pcap_reader = PcapReader(self.out_path)
                     break
                 except:
-                    self.test.logger.debug("Exception in scapy.PcapReader(%s): "
-                                           "%s" % (self.out_path, format_exc()))
+                    self.test.logger.debug(
+                        "Exception in scapy.PcapReader(%s): %s" %
+                        (self.out_path, format_exc()))
         if not self._pcap_reader:
-            raise Exception("Capture file %s did not appear within "
-                            "timeout" % self.out_path)
+            raise CaptureTimeoutError("Capture file %s did not appear within "
+                                      "timeout" % self.out_path)
 
-        self.test.logger.debug("Waiting for packet")
-        while time.time() < deadline:
+        poll = False
+        if timeout > 0:
+            self.test.logger.debug("Waiting for packet")
+        else:
+            poll = True
+            self.test.logger.debug("Polling for packet")
+        while time.time() < deadline or poll:
+            if not self.verify_enough_packet_data_in_pcap():
+                time.sleep(0)  # yield
+                poll = False
+                continue
             p = self._pcap_reader.recv()
             if p is not None:
                 if filter_out_fn is not None and filter_out_fn(p):
@@ -292,12 +363,14 @@ class VppPGInterface(VppInterface):
                         "Packet received after %ss was filtered out" %
                         (time.time() - (deadline - timeout)))
                 else:
-                    self.test.logger.debug("Packet received after %fs" %
-                                           (time.time() - (deadline - timeout)))
+                    self.test.logger.debug(
+                        "Packet received after %fs" %
+                        (time.time() - (deadline - timeout)))
                     return p
             time.sleep(0)  # yield
+            poll = False
         self.test.logger.debug("Timeout - no packets received")
-        raise Exception("Packet didn't arrive within timeout")
+        raise CaptureTimeoutError("Packet didn't arrive within timeout")
 
     def create_arp_req(self):
         """Create ARP request applicable for this interface"""
@@ -337,7 +410,6 @@ class VppPGInterface(VppInterface):
             self.test.logger.info("No ARP received on port %s" %
                                   pg_interface.name)
             return
-        self.rotate_out_file()
         arp_reply = captured_packet.copy()  # keep original for exception
         # Make Dot1AD packet content recognizable to scapy
         if arp_reply.type == 0x88a8:
@@ -382,7 +454,8 @@ class VppPGInterface(VppInterface):
                 captured_packet = pg_interface.wait_for_packet(
                     deadline - now, filter_out_fn=None)
             except:
-                self.test.logger.error("Timeout while waiting for NDP response")
+                self.test.logger.error(
+                    "Timeout while waiting for NDP response")
                 raise
             ndp_reply = captured_packet.copy()  # keep original for exception
             # Make Dot1AD packet content recognizable to scapy
@@ -397,13 +470,12 @@ class VppPGInterface(VppInterface):
                 self._local_mac = opt.lladdr
                 self.test.logger.debug(self.test.vapi.cli("show trace"))
                 # we now have the MAC we've been after
-                self.rotate_out_file()
                 return
             except:
                 self.test.logger.info(
-                    ppp("Unexpected response to NDP request:", captured_packet))
+                    ppp("Unexpected response to NDP request:",
+                        captured_packet))
             now = time.time()
 
         self.test.logger.debug(self.test.vapi.cli("show trace"))
-        self.rotate_out_file()
         raise Exception("Timeout while waiting for NDP response")