aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
authorKlement Sekera <ksekera@cisco.com>2017-02-09 06:04:36 +0100
committerKlement Sekera <ksekera@cisco.com>2017-02-09 06:10:47 +0100
commitb91017a30b3a2034c47008e7bcfe7bda49fe7c57 (patch)
tree46ffcfd254494dd8aef8e1dd8fd8b190b412189e
parentc756c1c7903feca20194bf3ba88863307668106a (diff)
make test: work around scapy truncated packets
Under stress, it's possible to hit a race condition, when the packet header is fully written to pcap, but not all packet data - yet. Scapy is stupid enough to: 1. not detect and report this error, truncating the packet instead 2. continue munching more data from wrong offset The work around is to scan the file ahead, parse the packet header, figure out how much data we need, wait for the file to be big enough, then restore the file position back to where it was and finally let scapy parse the packet. Change-Id: I9fc71d3ebdc62ecab6c90b90f177d0eaeb09b8bb Signed-off-by: Klement Sekera <ksekera@cisco.com>
-rw-r--r--test/framework.py32
-rw-r--r--test/vpp_pg_interface.py33
2 files changed, 65 insertions, 0 deletions
diff --git a/test/framework.py b/test/framework.py
index 4185dbfbb74..6a0ec965861 100644
--- a/test/framework.py
+++ b/test/framework.py
@@ -8,6 +8,7 @@ import resource
from collections import deque
from threading import Thread
from inspect import getdoc
+from traceback import format_exception
from hook import StepHook, PollHook
from vpp_pg_interface import VppPGInterface
from vpp_sub_interface import VppSubInterface
@@ -287,6 +288,9 @@ class VppTestCase(unittest.TestCase):
def tearDown(self):
""" Show various debug prints after each test """
+ self.logger.debug("--- tearDown() for %s.%s(%s) called ---" %
+ (self.__class__.__name__, self._testMethodName,
+ self._testMethodDoc))
if not self.vpp_dead:
self.logger.debug(self.vapi.cli("show trace"))
self.logger.info(self.vapi.ppcli("show int"))
@@ -297,6 +301,9 @@ class VppTestCase(unittest.TestCase):
def setUp(self):
""" Clear trace before running each test"""
+ self.logger.debug("--- setUp() for %s.%s(%s) called ---" %
+ (self.__class__.__name__, self._testMethodName,
+ self._testMethodDoc))
if self.vpp_dead:
raise Exception("VPP is dead when setting up the test")
time.sleep(.1)
@@ -586,6 +593,11 @@ class VppTestResult(unittest.TestResult):
:param test:
"""
+ if hasattr(test, 'logger'):
+ test.logger.debug("--- addSuccess() %s.%s(%s) called"
+ % (test.__class__.__name__,
+ test._testMethodName,
+ test._testMethodDoc))
unittest.TestResult.addSuccess(self, test)
self.result_string = colorize("OK", GREEN)
@@ -597,6 +609,12 @@ class VppTestResult(unittest.TestResult):
:param reason:
"""
+ if hasattr(test, 'logger'):
+ test.logger.debug("--- addSkip() %s.%s(%s) called, reason is %s"
+ % (test.__class__.__name__,
+ test._testMethodName,
+ test._testMethodDoc,
+ reason))
unittest.TestResult.addSkip(self, test, reason)
self.result_string = colorize("SKIP", YELLOW)
@@ -608,6 +626,13 @@ class VppTestResult(unittest.TestResult):
:param err: error message
"""
+ if hasattr(test, 'logger'):
+ test.logger.debug("--- addFailure() %s.%s(%s) called, err is %s"
+ % (test.__class__.__name__,
+ test._testMethodName,
+ test._testMethodDoc, err))
+ test.logger.debug("formatted exception is:\n%s" %
+ "".join(format_exception(*err)))
unittest.TestResult.addFailure(self, test, err)
if hasattr(test, 'tempdir'):
self.result_string = colorize("FAIL", RED) + \
@@ -623,6 +648,13 @@ class VppTestResult(unittest.TestResult):
:param err: error message
"""
+ if hasattr(test, 'logger'):
+ test.logger.debug("--- addError() %s.%s(%s) called, err is %s"
+ % (test.__class__.__name__,
+ test._testMethodName,
+ test._testMethodDoc, err))
+ test.logger.debug("formatted exception is:\n%s" %
+ "".join(format_exception(*err)))
unittest.TestResult.addError(self, test, err)
if hasattr(test, 'tempdir'):
self.result_string = colorize("ERROR", RED) + \
diff --git a/test/vpp_pg_interface.py b/test/vpp_pg_interface.py
index 81737c6d567..d6e6684993c 100644
--- a/test/vpp_pg_interface.py
+++ b/test/vpp_pg_interface.py
@@ -1,6 +1,7 @@
import os
import time
import socket
+import struct
from traceback import format_exc, format_stack
from scapy.utils import wrpcap, rdpcap, PcapReader
from scapy.plist import PacketList
@@ -283,6 +284,37 @@ class VppPGInterface(VppInterface):
return False
return True
+ def wait_for_packet_data(self, deadline):
+ """
+ Wait until enough data is available in the file handled by internal
+ pcap reader so that a whole packet can be read.
+
+ :param deadline: timestamp by which the data must arrive
+ :raises Exception: if not enough data by deadline
+ """
+ orig_pos = self._pcap_reader.f.tell() # save file position
+ enough_data = False
+ while time.time() < deadline:
+ # read packet header from pcap
+ hdr = self._pcap_reader.f.read(16)
+ if len(hdr) < 16:
+ time.sleep(0) # yield
+ continue # cannot read full header, continue looping
+ # find 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
+ break
+ self.test.logger.debug("Partial packet data in pcap")
+ time.sleep(0) # yield
+ self._pcap_reader.f.seek(orig_pos, 0) # restore original position
+ if not enough_data:
+ raise Exception(
+ "Not enough data to read a full packet within deadline")
+
def wait_for_packet(self, timeout, filter_out_fn=is_ipv6_misc):
"""
Wait for next packet captured with a timeout
@@ -311,6 +343,7 @@ class VppPGInterface(VppInterface):
self.test.logger.debug("Waiting for packet")
while time.time() < deadline:
+ self.wait_for_packet_data(deadline)
p = self._pcap_reader.recv()
if p is not None:
if filter_out_fn is not None and filter_out_fn(p):