test/vpp_pg_interface.py

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