test/vpp_pg_interface.py

   1 import os
   2 import shutil
   3 import socket
   4 from socket import inet_pton, inet_ntop
   5 import struct
   6 import time
   7 from traceback import format_exc, format_stack
   8
   9 from config import config
  10 import scapy.compat
  11 from scapy.utils import wrpcap, rdpcap, PcapReader
  12 from scapy.plist import PacketList
  13 from vpp_interface import VppInterface
  14 from vpp_papi import VppEnum
  15
  16 from scapy.layers.l2 import Ether, ARP
  17 from scapy.layers.inet6 import (
  18     IPv6,
  19     ICMPv6ND_NS,
  20     ICMPv6ND_NA,
  21     ICMPv6NDOptSrcLLAddr,
  22     ICMPv6NDOptDstLLAddr,
  23     ICMPv6ND_RA,
  24     RouterAlert,
  25     IPv6ExtHdrHopByHop,
  26 )
  27 from util import ppp, ppc, UnexpectedPacketError
  28 from scapy.utils6 import in6_getnsma, in6_getnsmac, in6_ismaddr
  29
  30
  31 class CaptureTimeoutError(Exception):
  32     """Exception raised if capture or packet doesn't appear within timeout"""
  33
  34     pass
  35
  36
  37 def is_ipv6_misc(p):
  38     """Is packet one of uninteresting IPv6 broadcasts?"""
  39     if p.haslayer(ICMPv6ND_RA):
  40         if in6_ismaddr(p[IPv6].dst):
  41             return True
  42     if p.haslayer(IPv6ExtHdrHopByHop):
  43         for o in p[IPv6ExtHdrHopByHop].options:
  44             if isinstance(o, RouterAlert):
  45                 return True
  46     return False
  47
  48
  49 class VppPGInterface(VppInterface):
  50     """
  51     VPP packet-generator interface
  52     """
  53
  54     @property
  55     def pg_index(self):
  56         """packet-generator interface index assigned by VPP"""
  57         return self._pg_index
  58
  59     @property
  60     def gso_enabled(self):
  61         """gso enabled on packet-generator interface"""
  62         if self._gso_enabled == 0:
  63             return "gso-disabled"
  64         return "gso-enabled"
  65
  66     @property
  67     def gso_size(self):
  68         """gso size on packet-generator interface"""
  69         return self._gso_size
  70
  71     @property
  72     def coalesce_is_enabled(self):
  73         """coalesce enabled on packet-generator interface"""
  74         if self._coalesce_enabled == 0:
  75             return "coalesce-disabled"
  76         return "coalesce-enabled"
  77
  78     @property
  79     def out_path(self):
  80         """pcap file path - captured packets"""
  81         return self._out_path
  82
  83     def get_in_path(self, worker):
  84         """pcap file path - injected packets"""
  85         if worker is not None:
  86             return "%s/pg%u_wrk%u_in.pcap" % (self.test.tempdir, self.pg_index, worker)
  87         return "%s/pg%u_in.pcap" % (self.test.tempdir, self.pg_index)
  88
  89     @property
  90     def capture_cli(self):
  91         """CLI string to start capture on this interface"""
  92         return self._capture_cli
  93
  94     def get_cap_name(self, worker=None):
  95         """return capture name for this interface and given worker"""
  96         if worker is not None:
  97             return self._cap_name + "-worker%d" % worker
  98         return self._cap_name
  99
 100     def get_input_cli(self, nb_replays=None, worker=None):
 101         """return CLI string to load the injected packets"""
 102         input_cli = "packet-generator new pcap %s source pg%u name %s" % (
 103             self.get_in_path(worker),
 104             self.pg_index,
 105             self.get_cap_name(worker),
 106         )
 107         if nb_replays is not None:
 108             return "%s limit %d" % (input_cli, nb_replays)
 109         if worker is not None:
 110             return "%s worker %d" % (input_cli, worker)
 111         return input_cli
 112
 113     @property
 114     def in_history_counter(self):
 115         """Self-incrementing counter used when renaming old pcap files"""
 116         v = self._in_history_counter
 117         self._in_history_counter += 1
 118         return v
 119
 120     @property
 121     def out_history_counter(self):
 122         """Self-incrementing counter used when renaming old pcap files"""
 123         v = self._out_history_counter
 124         self._out_history_counter += 1
 125         return v
 126
 127     def __init__(self, test, pg_index, gso, gso_size, mode):
 128         """Create VPP packet-generator interface"""
 129         super().__init__(test)
 130
 131         r = test.vapi.pg_create_interface_v2(pg_index, gso, gso_size, mode)
 132         self.set_sw_if_index(r.sw_if_index)
 133
 134         self._in_history_counter = 0
 135         self._out_history_counter = 0
 136         self._out_assert_counter = 0
 137         self._pg_index = pg_index
 138         self._gso_enabled = gso
 139         self._gso_size = gso_size
 140         self._coalesce_enabled = 0
 141         self._out_file = "pg%u_out.pcap" % self.pg_index
 142         self._out_path = self.test.tempdir + "/" + self._out_file
 143         self._capture_cli = "packet-generator capture pg%u pcap %s" % (
 144             self.pg_index,
 145             self.out_path,
 146         )
 147         self._cap_name = "pcap%u-sw_if_index-%s" % (self.pg_index, self.sw_if_index)
 148
 149     def handle_old_pcap_file(self, path, counter):
 150         filename = os.path.basename(path)
 151
 152         if not config.keep_pcaps:
 153             try:
 154                 self.test.logger.debug(f"Removing {path}")
 155                 os.remove(path)
 156             except OSError:
 157                 self.test.logger.debug(f"OSError: Could not remove {path}")
 158             return
 159
 160         # keep
 161         try:
 162             if os.path.isfile(path):
 163                 name = "%s/history.[timestamp:%f].[%s-counter:%04d].%s" % (
 164                     self.test.tempdir,
 165                     time.time(),
 166                     self.name,
 167                     counter,
 168                     filename,
 169                 )
 170                 self.test.logger.debug("Renaming %s->%s" % (path, name))
 171                 shutil.move(path, name)
 172         except OSError:
 173             self.test.logger.debug("OSError: Could not rename %s %s" % (path, filename))
 174
 175     def enable_capture(self):
 176         """Enable capture on this packet-generator interface
 177         of at most n packets.
 178         If n < 0, this is no limit
 179         """
 180         # disable the capture to flush the capture
 181         self.disable_capture()
 182         self.handle_old_pcap_file(self.out_path, self.out_history_counter)
 183         # FIXME this should be an API, but no such exists atm
 184         self.test.vapi.cli(self.capture_cli)
 185         self._pcap_reader = None
 186
 187     def disable_capture(self):
 188         self.test.vapi.cli("%s disable" % self.capture_cli)
 189
 190     def coalesce_enable(self):
 191         """Enable packet coalesce on this packet-generator interface"""
 192         self._coalesce_enabled = 1
 193         self.test.vapi.pg_interface_enable_disable_coalesce(self.sw_if_index, 1)
 194
 195     def coalesce_disable(self):
 196         """Disable packet coalesce on this packet-generator interface"""
 197         self._coalesce_enabled = 0
 198         self.test.vapi.pg_interface_enable_disable_coalesce(self.sw_if_index, 0)
 199
 200     def add_stream(self, pkts, nb_replays=None, worker=None):
 201         """
 202         Add a stream of packets to this packet-generator
 203
 204         :param pkts: iterable packets
 205
 206         """
 207         wrpcap(self.get_in_path(worker), pkts)
 208         self.test.register_pcap(self, worker)
 209         # FIXME this should be an API, but no such exists atm
 210         self.test.vapi.cli(self.get_input_cli(nb_replays, worker))
 211
 212     def generate_debug_aid(self, kind):
 213         """Create a hardlink to the out file with a counter and a file
 214         containing stack trace to ease debugging in case of multiple capture
 215         files present."""
 216         self.test.logger.debug("Generating debug aid for %s on %s" % (kind, self._name))
 217         link_path, stack_path = [
 218             "%s/debug_%s_%s_%s.%s"
 219             % (self.test.tempdir, self._name, self._out_assert_counter, kind, suffix)
 220             for suffix in ["pcap", "stack"]
 221         ]
 222         os.link(self.out_path, link_path)
 223         with open(stack_path, "w") as f:
 224             f.writelines(format_stack())
 225         self._out_assert_counter += 1
 226
 227     def _get_capture(self, timeout, filter_out_fn=is_ipv6_misc):
 228         """Helper method to get capture and filter it"""
 229         try:
 230             if not self.wait_for_capture_file(timeout):
 231                 return None
 232             output = rdpcap(self.out_path)
 233             self.test.logger.debug("Capture has %s packets" % len(output.res))
 234         except:
 235             self.test.logger.debug(
 236                 "Exception in scapy.rdpcap (%s): %s" % (self.out_path, format_exc())
 237             )
 238             return None
 239         before = len(output.res)
 240         if filter_out_fn:
 241             output.res = [p for p in output.res if not filter_out_fn(p)]
 242         removed = before - len(output.res)
 243         if removed:
 244             self.test.logger.debug(
 245                 "Filtered out %s packets from capture (returning %s)"
 246                 % (removed, len(output.res))
 247             )
 248         return output
 249
 250     def get_capture(
 251         self, expected_count=None, remark=None, timeout=1, filter_out_fn=is_ipv6_misc
 252     ):
 253         """Get captured packets
 254
 255         :param expected_count: expected number of packets to capture, if None,
 256                                then self.test.packet_count_for_dst_pg_idx is
 257                                used to lookup the expected count
 258         :param remark: remark printed into debug logs
 259         :param timeout: how long to wait for packets
 260         :param filter_out_fn: filter applied to each packet, packets for which
 261                               the filter returns True are removed from capture
 262         :returns: iterable packets
 263         """
 264         remaining_time = timeout
 265         capture = None
 266         name = self.name if remark is None else "%s (%s)" % (self.name, remark)
 267         based_on = "based on provided argument"
 268         if expected_count is None:
 269             expected_count = self.test.get_packet_count_for_if_idx(self.sw_if_index)
 270             based_on = "based on stored packet_infos"
 271             if expected_count == 0:
 272                 raise Exception(
 273                     "Internal error, expected packet count for %s is 0!" % name
 274                 )
 275         self.test.logger.debug(
 276             "Expecting to capture %s (%s) packets on %s"
 277             % (expected_count, based_on, name)
 278         )
 279         while remaining_time > 0:
 280             before = time.time()
 281             capture = self._get_capture(remaining_time, filter_out_fn)
 282             elapsed_time = time.time() - before
 283             if capture:
 284                 if len(capture.res) == expected_count:
 285                     # bingo, got the packets we expected
 286                     return capture
 287                 elif len(capture.res) > expected_count:
 288                     self.test.logger.error(ppc("Unexpected packets captured:", capture))
 289                     break
 290                 else:
 291                     self.test.logger.debug(
 292                         "Partial capture containing %s "
 293                         "packets doesn't match expected "
 294                         "count %s (yet?)" % (len(capture.res), expected_count)
 295                     )
 296             elif expected_count == 0:
 297                 # bingo, got None as we expected - return empty capture
 298                 return PacketList()
 299             remaining_time -= elapsed_time
 300         if capture:
 301             self.generate_debug_aid("count-mismatch")
 302             if len(capture) > 0 and 0 == expected_count:
 303                 rem = f"\n{remark}" if remark else ""
 304                 raise UnexpectedPacketError(
 305                     capture[0], f"\n({len(capture)} packets captured in total){rem}"
 306                 )
 307             raise Exception(
 308                 "Captured packets mismatch, captured %s packets, "
 309                 "expected %s packets on %s" % (len(capture.res), expected_count, name)
 310             )
 311         else:
 312             if 0 == expected_count:
 313                 return
 314             raise Exception("No packets captured on %s" % name)
 315
 316     def assert_nothing_captured(
 317         self, timeout=1, remark=None, filter_out_fn=is_ipv6_misc
 318     ):
 319         """Assert that nothing unfiltered was captured on interface
 320
 321         :param remark: remark printed into debug logs
 322         :param filter_out_fn: filter applied to each packet, packets for which
 323                               the filter returns True are removed from capture
 324         """
 325         capture = self.get_capture(
 326             0, timeout=timeout, remark=remark, filter_out_fn=filter_out_fn
 327         )
 328         if not capture or len(capture.res) == 0:
 329             # junk filtered out, we're good
 330             return
 331
 332     def wait_for_pg_stop(self):
 333         # wait till packet-generator is stopped
 334         # "show packet-generator" while it is still running gives this:
 335         # Name               Enabled        Count     Parameters
 336         # pcap0-sw_if_inde     Yes           64       limit 64, ...
 337         #
 338         # also have a 5-minute timeout just in case things go terribly wrong...
 339         deadline = time.time() + 300
 340         while self.test.vapi.cli("show packet-generator").find("Yes") != -1:
 341             self._test.sleep(0.01)  # yield
 342             if time.time() > deadline:
 343                 self.test.logger.debug("Timeout waiting for pg to stop")
 344                 break
 345
 346     def wait_for_capture_file(self, timeout=1):
 347         """
 348         Wait until pcap capture file appears
 349
 350         :param timeout: How long to wait for the packet (default 1s)
 351
 352         :returns: True/False if the file is present or appears within timeout
 353         """
 354         self.wait_for_pg_stop()
 355         deadline = time.time() + timeout
 356         if not os.path.isfile(self.out_path):
 357             self.test.logger.debug(
 358                 "Waiting for capture file %s to appear, "
 359                 "timeout is %ss" % (self.out_path, timeout)
 360             )
 361         else:
 362             self.test.logger.debug("Capture file %s already exists" % self.out_path)
 363             return True
 364         while time.time() < deadline:
 365             if os.path.isfile(self.out_path):
 366                 break
 367             self._test.sleep(0)  # yield
 368         if os.path.isfile(self.out_path):
 369             self.test.logger.debug(
 370                 "Capture file appeared after %fs" % (time.time() - (deadline - timeout))
 371             )
 372         else:
 373             self.test.logger.debug("Timeout - capture file still nowhere")
 374             return False
 375         return True
 376
 377     def verify_enough_packet_data_in_pcap(self):
 378         """
 379         Check if enough data is available in file handled by internal pcap
 380         reader so that a whole packet can be read.
 381
 382         :returns: True if enough data present, else False
 383         """
 384         orig_pos = self._pcap_reader.f.tell()  # save file position
 385         enough_data = False
 386         # read packet header from pcap
 387         packet_header_size = 16
 388         caplen = None
 389         end_pos = None
 390         hdr = self._pcap_reader.f.read(packet_header_size)
 391         if len(hdr) == packet_header_size:
 392             # parse the capture length - caplen
 393             sec, usec, caplen, wirelen = struct.unpack(
 394                 self._pcap_reader.endian + "IIII", hdr
 395             )
 396             self._pcap_reader.f.seek(0, 2)  # seek to end of file
 397             end_pos = self._pcap_reader.f.tell()  # get position at end
 398             if end_pos >= orig_pos + len(hdr) + caplen:
 399                 enough_data = True  # yay, we have enough data
 400         self._pcap_reader.f.seek(orig_pos, 0)  # restore original position
 401         return enough_data
 402
 403     def wait_for_packet(self, timeout, filter_out_fn=is_ipv6_misc):
 404         """
 405         Wait for next packet captured with a timeout
 406
 407         :param timeout: How long to wait for the packet
 408
 409         :returns: Captured packet if no packet arrived within timeout
 410         :raises Exception: if no packet arrives within timeout
 411         """
 412         deadline = time.time() + timeout
 413         if self._pcap_reader is None:
 414             if not self.wait_for_capture_file(timeout):
 415                 raise CaptureTimeoutError(
 416                     "Capture file %s did not appear within timeout" % self.out_path
 417                 )
 418             while time.time() < deadline:
 419                 try:
 420                     self._pcap_reader = PcapReader(self.out_path)
 421                     break
 422                 except:
 423                     self.test.logger.debug(
 424                         "Exception in scapy.PcapReader(%s): %s"
 425                         % (self.out_path, format_exc())
 426                     )
 427         if not self._pcap_reader:
 428             raise CaptureTimeoutError(
 429                 "Capture file %s did not appear within timeout" % self.out_path
 430             )
 431
 432         poll = False
 433         if timeout > 0:
 434             self.test.logger.debug("Waiting for packet")
 435         else:
 436             poll = True
 437             self.test.logger.debug("Polling for packet")
 438         while time.time() < deadline or poll:
 439             if not self.verify_enough_packet_data_in_pcap():
 440                 self._test.sleep(0)  # yield
 441                 poll = False
 442                 continue
 443             p = self._pcap_reader.recv()
 444             if p is not None:
 445                 if filter_out_fn is not None and filter_out_fn(p):
 446                     self.test.logger.debug(
 447                         "Packet received after %ss was filtered out"
 448                         % (time.time() - (deadline - timeout))
 449                     )
 450                 else:
 451                     self.test.logger.debug(
 452                         "Packet received after %fs"
 453                         % (time.time() - (deadline - timeout))
 454                     )
 455                     return p
 456             self._test.sleep(0)  # yield
 457             poll = False
 458         self.test.logger.debug("Timeout - no packets received")
 459         raise CaptureTimeoutError("Packet didn't arrive within timeout")
 460
 461     def create_arp_req(self):
 462         """Create ARP request applicable for this interface"""
 463         return Ether(dst="ff:ff:ff:ff:ff:ff", src=self.remote_mac) / ARP(
 464             op=ARP.who_has,
 465             pdst=self.local_ip4,
 466             psrc=self.remote_ip4,
 467             hwsrc=self.remote_mac,
 468         )
 469
 470     def create_ndp_req(self, addr=None):
 471         """Create NDP - NS applicable for this interface"""
 472         if not addr:
 473             addr = self.local_ip6
 474         nsma = in6_getnsma(inet_pton(socket.AF_INET6, addr))
 475         d = inet_ntop(socket.AF_INET6, nsma)
 476
 477         return (
 478             Ether(dst=in6_getnsmac(nsma))
 479             / IPv6(dst=d, src=self.remote_ip6)
 480             / ICMPv6ND_NS(tgt=addr)
 481             / ICMPv6NDOptSrcLLAddr(lladdr=self.remote_mac)
 482         )
 483
 484     def resolve_arp(self, pg_interface=None):
 485         """Resolve ARP using provided packet-generator interface
 486
 487         :param pg_interface: interface used to resolve, if None then this
 488             interface is used
 489
 490         """
 491         if pg_interface is None:
 492             pg_interface = self
 493         self.test.logger.info(
 494             "Sending ARP request for %s on port %s"
 495             % (self.local_ip4, pg_interface.name)
 496         )
 497         arp_req = self.create_arp_req()
 498         pg_interface.add_stream(arp_req)
 499         pg_interface.enable_capture()
 500         self.test.pg_start()
 501         self.test.logger.info(self.test.vapi.cli("show trace"))
 502         try:
 503             captured_packet = pg_interface.wait_for_packet(1)
 504         except:
 505             self.test.logger.info("No ARP received on port %s" % pg_interface.name)
 506             return
 507         arp_reply = captured_packet.copy()  # keep original for exception
 508         try:
 509             if arp_reply[ARP].op == ARP.is_at:
 510                 self.test.logger.info(
 511                     "VPP %s MAC address is %s " % (self.name, arp_reply[ARP].hwsrc)
 512                 )
 513                 self._local_mac = arp_reply[ARP].hwsrc
 514             else:
 515                 self.test.logger.info("No ARP received on port %s" % pg_interface.name)
 516         except:
 517             self.test.logger.error(
 518                 ppp("Unexpected response to ARP request:", captured_packet)
 519             )
 520             raise
 521
 522     def resolve_ndp(self, pg_interface=None, timeout=1, link_layer=False):
 523         """Resolve NDP using provided packet-generator interface
 524
 525         :param pg_interface: interface used to resolve, if None then this
 526             interface is used
 527         :param timeout: how long to wait for response before giving up
 528         :param link_layer: resolve for global address if False (default)
 529             or for link-layer address if True
 530
 531         """
 532         if pg_interface is None:
 533             pg_interface = self
 534         addr = self.local_ip6_ll if link_layer else self.local_ip6
 535         self.test.logger.info(
 536             "Sending NDP request for %s on port %s" % (addr, pg_interface.name)
 537         )
 538         ndp_req = self.create_ndp_req(addr)
 539         pg_interface.add_stream(ndp_req)
 540         pg_interface.enable_capture()
 541         self.test.pg_start()
 542         now = time.time()
 543         deadline = now + timeout
 544         # Enabling IPv6 on an interface can generate more than the
 545         # ND reply we are looking for (namely MLD). So loop through
 546         # the replies to look for want we want.
 547         while now < deadline:
 548             try:
 549                 captured_packet = pg_interface.wait_for_packet(
 550                     deadline - now, filter_out_fn=None
 551                 )
 552             except:
 553                 self.test.logger.error("Timeout while waiting for NDP response")
 554                 raise
 555             ndp_reply = captured_packet.copy()  # keep original for exception
 556             try:
 557                 ndp_na = ndp_reply[ICMPv6ND_NA]
 558                 opt = ndp_na[ICMPv6NDOptDstLLAddr]
 559                 self.test.logger.info(
 560                     "VPP %s MAC address is %s " % (self.name, opt.lladdr)
 561                 )
 562                 self._local_mac = opt.lladdr
 563                 self.test.logger.debug(self.test.vapi.cli("show trace"))
 564                 # we now have the MAC we've been after
 565                 return
 566             except:
 567                 self.test.logger.info(
 568                     ppp("Unexpected response to NDP request:", captured_packet)
 569                 )
 570             now = time.time()
 571
 572         self.test.logger.debug(self.test.vapi.cli("show trace"))
 573         raise Exception("Timeout while waiting for NDP response")