ligang/vpp
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

make test: improve stability

Browse Source 
Disable automatic garbage collection and run it manually before
running each test case to minimize stalls. Improve vpp subprocess
cleanup. Reduce helper thread count to one and properly clean that
thread once it's not needed.

Change-Id: I3ea78ed9628552b5ef3ff29cc7bcf2d3fc42f2c3
Signed-off-by: Klement Sekera <ksekera@cisco.com>
This commit is contained in:
Klement Sekera
2017-02-14 02:55:31 +01:00
parent 2bce0332d3
commit acb9b8e8c3
6 changed files with 149 additions and 88 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

11
test/Makefile
View File

@ -5,8 +5,14 @@ ifndef VPP_PYTHON_PREFIX
$(error VPP_PYTHON_PREFIX is not set) $(error VPP_PYTHON_PREFIX is not set)
endif endif
UNITTEST_EXTRA_OPTS=""
ifeq ($(FAILFAST),1)
UNITTEST_EXTRA_OPTS="-f"
endif
PYTHON_VENV_PATH=$(VPP_PYTHON_PREFIX)/virtualenv PYTHON_VENV_PATH=$(VPP_PYTHON_PREFIX)/virtualenv
PYTHON_DEPENDS=scapy==2.3.3 pexpect PYTHON_DEPENDS=scapy==2.3.3 pexpect subprocess32
SCAPY_SOURCE=$(PYTHON_VENV_PATH)/lib/python2.7/site-packages/ SCAPY_SOURCE=$(PYTHON_VENV_PATH)/lib/python2.7/site-packages/
BUILD_COV_DIR = $(BR)/test-cov BUILD_COV_DIR = $(BR)/test-cov
@ -35,7 +41,7 @@ $(PAPI_INSTALL_DONE): $(PIP_PATCH_DONE)
@touch $@ @touch $@
define retest-func define retest-func
@bash -c "source $(PYTHON_VENV_PATH)/bin/activate && python run_tests.py discover -p test_\"*.py\"" @bash -c "source $(PYTHON_VENV_PATH)/bin/activate && python run_tests.py discover $(UNITTEST_EXTRA_OPTS) -p test_\"*.py\""
endef endef
test: reset verify-python-path $(PAPI_INSTALL_DONE) test: reset verify-python-path $(PAPI_INSTALL_DONE)
@ -103,6 +109,7 @@ help:
@echo "" @echo ""
@echo "Arguments controlling test runs:" @echo "Arguments controlling test runs:"
@echo " V=[0|1|2] - set test verbosity level" @echo " V=[0|1|2] - set test verbosity level"
@echo " FAILFAST=[0|1] - fail fast if 1, complete all tests if 0"
@echo " DEBUG=<type> - set VPP debugging kind" @echo " DEBUG=<type> - set VPP debugging kind"
@echo " DEBUG=core - detect coredump and load it in gdb on crash" @echo " DEBUG=core - detect coredump and load it in gdb on crash"
@echo " DEBUG=gdb - allow easy debugging by printing VPP PID " @echo " DEBUG=gdb - allow easy debugging by printing VPP PID "

78
test/framework.py
View File

@ -1,23 +1,33 @@
#!/usr/bin/env python #!/usr/bin/env python
import subprocess from __future__ import print_function
import gc
import sys
import os
import select
import unittest import unittest
import tempfile import tempfile
import time import time
import resource import resource
from collections import deque from collections import deque
from threading import Thread from threading import Thread, Event
from inspect import getdoc from inspect import getdoc
from traceback import format_exception from traceback import format_exception
from logging import FileHandler, DEBUG, Formatter
from scapy.packet import Raw
from hook import StepHook, PollHook from hook import StepHook, PollHook
from vpp_pg_interface import VppPGInterface from vpp_pg_interface import VppPGInterface
from vpp_sub_interface import VppSubInterface from vpp_sub_interface import VppSubInterface
from vpp_lo_interface import VppLoInterface from vpp_lo_interface import VppLoInterface
from vpp_papi_provider import VppPapiProvider from vpp_papi_provider import VppPapiProvider
from scapy.packet import Raw
from logging import FileHandler, DEBUG
from log import * from log import *
from vpp_object import VppObjectRegistry from vpp_object import VppObjectRegistry
if os.name == 'posix' and sys.version_info[0] < 3:
# using subprocess32 is recommended by python official documentation
# @ https://docs.python.org/2/library/subprocess.html
import subprocess32 as subprocess
else:
import subprocess
""" """
Test framework module. Test framework module.
@ -51,9 +61,21 @@ class _PacketInfo(object):
return index and src and dst and data return index and src and dst and data
def pump_output(out, deque): def pump_output(testclass):
for line in iter(out.readline, b''): """ pump output from vpp stdout/stderr to proper queues """
deque.append(line) while not testclass.pump_thread_stop_flag.wait(0):
readable = select.select([testclass.vpp.stdout.fileno(),
testclass.vpp.stderr.fileno(),
testclass.pump_thread_wakeup_pipe[0]],
[], [])[0]
if testclass.vpp.stdout.fileno() in readable:
read = os.read(testclass.vpp.stdout.fileno(), 1024)
testclass.vpp_stdout_deque.append(read)
if testclass.vpp.stderr.fileno() in readable:
read = os.read(testclass.vpp.stderr.fileno(), 1024)
testclass.vpp_stderr_deque.append(read)
# ignoring the dummy pipe here intentionally - the flag will take care
# of properly terminating the loop
class VppTestCase(unittest.TestCase): class VppTestCase(unittest.TestCase):
@ -181,10 +203,14 @@ class VppTestCase(unittest.TestCase):
Perform class setup before running the testcase Perform class setup before running the testcase
Remove shared memory files, start vpp and connect the vpp-api Remove shared memory files, start vpp and connect the vpp-api
""" """
gc.collect() # run garbage collection first
cls.logger = getLogger(cls.__name__) cls.logger = getLogger(cls.__name__)
cls.tempdir = tempfile.mkdtemp( cls.tempdir = tempfile.mkdtemp(
prefix='vpp-unittest-' + cls.__name__ + '-') prefix='vpp-unittest-' + cls.__name__ + '-')
file_handler = FileHandler("%s/log.txt" % cls.tempdir) file_handler = FileHandler("%s/log.txt" % cls.tempdir)
file_handler.setFormatter(
Formatter(fmt='%(asctime)s,%(msecs)03d %(message)s',
datefmt="%H:%M:%S"))
file_handler.setLevel(DEBUG) file_handler.setLevel(DEBUG)
cls.logger.addHandler(file_handler) cls.logger.addHandler(file_handler)
cls.shm_prefix = cls.tempdir.split("/")[-1] cls.shm_prefix = cls.tempdir.split("/")[-1]
@ -206,20 +232,18 @@ class VppTestCase(unittest.TestCase):
try: try:
cls.run_vpp() cls.run_vpp()
cls.vpp_stdout_deque = deque() cls.vpp_stdout_deque = deque()
cls.vpp_stdout_reader_thread = Thread(target=pump_output, args=(
cls.vpp.stdout, cls.vpp_stdout_deque))
cls.vpp_stdout_reader_thread.start()
cls.vpp_stderr_deque = deque() cls.vpp_stderr_deque = deque()
cls.vpp_stderr_reader_thread = Thread(target=pump_output, args=( cls.pump_thread_stop_flag = Event()
cls.vpp.stderr, cls.vpp_stderr_deque)) cls.pump_thread_wakeup_pipe = os.pipe()
cls.vpp_stderr_reader_thread.start() cls.pump_thread = Thread(target=pump_output, args=(cls,))
cls.pump_thread.start()
cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls) cls.vapi = VppPapiProvider(cls.shm_prefix, cls.shm_prefix, cls)
if cls.step: if cls.step:
hook = StepHook(cls) hook = StepHook(cls)
else: else:
hook = PollHook(cls) hook = PollHook(cls)
cls.vapi.register_hook(hook) cls.vapi.register_hook(hook)
time.sleep(0.1) cls.sleep(0.1, "after vpp startup, before initial poll")
hook.poll_vpp() hook.poll_vpp()
try: try:
cls.vapi.connect() cls.vapi.connect()
@ -251,12 +275,25 @@ class VppTestCase(unittest.TestCase):
raw_input("When done debugging, press ENTER to kill the " raw_input("When done debugging, press ENTER to kill the "
"process and finish running the testcase...") "process and finish running the testcase...")
os.write(cls.pump_thread_wakeup_pipe[1], 'ding dong wake up')
cls.pump_thread_stop_flag.set()
if hasattr(cls, 'pump_thread'):
cls.logger.debug("Waiting for pump thread to stop")
cls.pump_thread.join()
if hasattr(cls, 'vpp_stderr_reader_thread'):
cls.logger.debug("Waiting for stdderr pump to stop")
cls.vpp_stderr_reader_thread.join()
if hasattr(cls, 'vpp'): if hasattr(cls, 'vpp'):
if hasattr(cls, 'vapi'): if hasattr(cls, 'vapi'):
cls.vapi.disconnect() cls.vapi.disconnect()
del cls.vapi
cls.vpp.poll() cls.vpp.poll()
if cls.vpp.returncode is None: if cls.vpp.returncode is None:
cls.logger.debug("Sending TERM to vpp")
cls.vpp.terminate() cls.vpp.terminate()
cls.logger.debug("Waiting for vpp to die")
cls.vpp.communicate()
del cls.vpp del cls.vpp
if hasattr(cls, 'vpp_stdout_deque'): if hasattr(cls, 'vpp_stdout_deque'):
@ -306,7 +343,7 @@ class VppTestCase(unittest.TestCase):
self._testMethodDoc)) self._testMethodDoc))
if self.vpp_dead: if self.vpp_dead:
raise Exception("VPP is dead when setting up the test") raise Exception("VPP is dead when setting up the test")
time.sleep(.1) self.sleep(.1, "during setUp")
self.vpp_stdout_deque.append( self.vpp_stdout_deque.append(
"--- test setUp() for %s.%s(%s) starts here ---\n" % "--- test setUp() for %s.%s(%s) starts here ---\n" %
(self.__class__.__name__, self._testMethodName, (self.__class__.__name__, self._testMethodName,
@ -351,9 +388,7 @@ class VppTestCase(unittest.TestCase):
for stamp, cap_name in cls._zombie_captures: for stamp, cap_name in cls._zombie_captures:
wait = stamp + capture_ttl - now wait = stamp + capture_ttl - now
if wait > 0: if wait > 0:
cls.logger.debug("Waiting for %ss before deleting capture %s", cls.sleep(wait, "before deleting capture %s" % cap_name)
wait, cap_name)
time.sleep(wait)
now = time.time() now = time.time()
cls.logger.debug("Removing zombie capture %s" % cap_name) cls.logger.debug("Removing zombie capture %s" % cap_name)
cls.vapi.cli('packet-generator delete %s' % cap_name) cls.vapi.cli('packet-generator delete %s' % cap_name)
@ -552,8 +587,10 @@ class VppTestCase(unittest.TestCase):
name, real_value, expected_min, expected_max) name, real_value, expected_min, expected_max)
self.assertTrue(expected_min <= real_value <= expected_max, msg) self.assertTrue(expected_min <= real_value <= expected_max, msg)
def sleep(self, timeout): @classmethod
self.logger.debug("Sleeping for %ss" % timeout) def sleep(cls, timeout, remark=None):
if hasattr(cls, 'logger'):
cls.logger.debug("Sleeping for %ss (%s)" % (timeout, remark))
time.sleep(timeout) time.sleep(timeout)
@ -817,6 +854,7 @@ class VppTestRunner(unittest.TextTestRunner):
:param test: :param test:
""" """
gc.disable() # disable garbage collection, we'll do that manually
print("Running tests using custom test runner") # debug message print("Running tests using custom test runner") # debug message
filter_file, filter_class, filter_func = self.parse_test_option() filter_file, filter_class, filter_func = self.parse_test_option()
print("Active filters: file=%s, class=%s, function=%s" % ( print("Active filters: file=%s, class=%s, function=%s" % (

2
test/util.py
View File

@ -1,3 +1,5 @@
""" test framework utilities """
import socket import socket
import sys import sys
from abc import abstractmethod, ABCMeta from abc import abstractmethod, ABCMeta

35
test/vpp_object.py
View File

@ -1,3 +1,5 @@
""" abstract vpp object and object registry """
from abc import ABCMeta, abstractmethod from abc import ABCMeta, abstractmethod
@ -5,9 +7,6 @@ class VppObject(object):
""" Abstract vpp object """ """ Abstract vpp object """
__metaclass__ = ABCMeta __metaclass__ = ABCMeta
def __init__(self):
VppObjectRegistry().register(self)
@abstractmethod @abstractmethod
def add_vpp_config(self): def add_vpp_config(self):
""" Add the configuration for this object to vpp. """ """ Add the configuration for this object to vpp. """
@ -42,13 +41,13 @@ class VppObjectRegistry(object):
if not hasattr(self, "_object_dict"): if not hasattr(self, "_object_dict"):
self._object_dict = dict() self._object_dict = dict()
def register(self, o, logger): def register(self, obj, logger):
""" Register an object in the registry. """ """ Register an object in the registry. """
if not o.object_id() in self._object_dict: if obj.object_id() not in self._object_dict:
self._object_registry.append(o) self._object_registry.append(obj)
self._object_dict[o.object_id()] = o self._object_dict[obj.object_id()] = obj
else: else:
logger.debug("REG: duplicate add, ignoring (%s)" % o) logger.debug("REG: duplicate add, ignoring (%s)" % obj)
def remove_vpp_config(self, logger): def remove_vpp_config(self, logger):
""" """
@ -60,23 +59,23 @@ class VppObjectRegistry(object):
return return
logger.info("REG: Removing VPP configuration for registered objects") logger.info("REG: Removing VPP configuration for registered objects")
# remove the config in reverse order as there might be dependencies # remove the config in reverse order as there might be dependencies
for o in reversed(self._object_registry): for obj in reversed(self._object_registry):
if o.query_vpp_config(): if obj.query_vpp_config():
logger.info("REG: Removing configuration for %s" % o) logger.info("REG: Removing configuration for %s" % obj)
o.remove_vpp_config() obj.remove_vpp_config()
else: else:
logger.info( logger.info(
"REG: Skipping removal for %s, configuration not present" % "REG: Skipping removal for %s, configuration not present" %
o) obj)
failed = [] failed = []
for o in self._object_registry: for obj in self._object_registry:
if o.query_vpp_config(): if obj.query_vpp_config():
failed.append(o) failed.append(obj)
self._object_registry = [] self._object_registry = []
self._object_dict = dict() self._object_dict = dict()
if failed: if failed:
logger.error("REG: Couldn't remove configuration for object(s):") logger.error("REG: Couldn't remove configuration for object(s):")
for x in failed: for obj in failed:
logger.error(repr(x)) logger.error(repr(obj))
raise Exception("Couldn't remove configuration for object(s): %s" % raise Exception("Couldn't remove configuration for object(s): %s" %
(", ".join(str(x) for x in failed))) (", ".join(str(x) for x in failed)))

8
test/vpp_papi_provider.py
View File

@ -87,6 +87,12 @@ class VppPapiProvider(object):
def wait_for_event(self, timeout, name=None): def wait_for_event(self, timeout, name=None):
""" Wait for and return next event. """ """ Wait for and return next event. """
if name:
self.test_class.logger.debug("Expecting event within %ss",
timeout)
else:
self.test_class.logger.debug("Expecting event '%s' within %ss",
name, timeout)
if self._events: if self._events:
self.test_class.logger.debug("Not waiting, event already queued") self.test_class.logger.debug("Not waiting, event already queued")
limit = time.time() + timeout limit = time.time() + timeout
@ -101,8 +107,6 @@ class VppPapiProvider(object):
(name, e)) (name, e))
return e return e
time.sleep(0) # yield time.sleep(0) # yield
if name is not None:
raise Exception("Event %s did not occur within timeout" % name)
raise Exception("Event did not occur within timeout") raise Exception("Event did not occur within timeout")
def __call__(self, name, event): def __call__(self, name, event):

103
test/vpp_pg_interface.py
View File

@ -16,6 +16,11 @@ from scapy.utils6 import in6_getnsma, in6_getnsmac, in6_ismaddr
from scapy.utils import inet_pton, inet_ntop 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): def is_ipv6_misc(p):
""" Is packet one of uninteresting IPv6 broadcasts? """ """ Is packet one of uninteresting IPv6 broadcasts? """
if p.haslayer(ICMPv6ND_RA): if p.haslayer(ICMPv6ND_RA):
@ -103,13 +108,15 @@ class VppPGInterface(VppInterface):
""" Enable capture on this packet-generator interface""" """ Enable capture on this packet-generator interface"""
try: try:
if os.path.isfile(self.out_path): if os.path.isfile(self.out_path):
os.rename(self.out_path, name = "%s/history.[timestamp:%f].[%s-counter:%04d].%s" % \
"%s/history.[timestamp:%f].[%s-counter:%04d].%s" % (self.test.tempdir,
(self.test.tempdir, time.time(),
time.time(), self.name,
self.name, self.out_history_counter,
self.out_history_counter, self._out_file)
self._out_file)) self.test.logger.debug("Renaming %s->%s" %
(self.out_path, name))
os.rename(self.out_path, name)
except: except:
pass pass
# FIXME this should be an API, but no such exists atm # FIXME this should be an API, but no such exists atm
@ -125,13 +132,15 @@ class VppPGInterface(VppInterface):
""" """
try: try:
if os.path.isfile(self.in_path): if os.path.isfile(self.in_path):
os.rename(self.in_path, name = "%s/history.[timestamp:%f].[%s-counter:%04d].%s" %\
"%s/history.[timestamp:%f].[%s-counter:%04d].%s" % (self.test.tempdir,
(self.test.tempdir, time.time(),
time.time(), self.name,
self.name, self.in_history_counter,
self.in_history_counter, self._in_file)
self._in_file)) self.test.logger.debug("Renaming %s->%s" %
(self.in_path, name))
os.rename(self.in_path, name)
except: except:
pass pass
wrpcap(self.in_path, pkts) wrpcap(self.in_path, pkts)
@ -263,57 +272,50 @@ class VppPGInterface(VppInterface):
:returns: True/False if the file is present or appears within timeout :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): if not os.path.isfile(self.out_path):
self.test.logger.debug("Waiting for capture file %s to appear, " self.test.logger.debug("Waiting for capture file %s to appear, "
"timeout is %ss" % (self.out_path, timeout)) "timeout is %ss" % (self.out_path, timeout))
else: else:
self.test.logger.debug( self.test.logger.debug("Capture file %s already exists" %
"Capture file %s already exists" % self.out_path)
self.out_path)
return True return True
while time.time() < limit: while time.time() < deadline:
if os.path.isfile(self.out_path): if os.path.isfile(self.out_path):
break break
time.sleep(0) # yield time.sleep(0) # yield
if os.path.isfile(self.out_path): if os.path.isfile(self.out_path):
self.test.logger.debug("Capture file appeared after %fs" % self.test.logger.debug("Capture file appeared after %fs" %
(time.time() - (limit - timeout))) (time.time() - (deadline - timeout)))
else: else:
self.test.logger.debug("Timeout - capture file still nowhere") self.test.logger.debug("Timeout - capture file still nowhere")
return False return False
return True return True
def wait_for_packet_data(self, deadline): def verify_enough_packet_data_in_pcap(self):
""" """
Wait until enough data is available in the file handled by internal Check if enough data is available in file handled by internal pcap
pcap reader so that a whole packet can be read. reader so that a whole packet can be read.
:param deadline: timestamp by which the data must arrive :returns: True if enough data present, else False
:raises Exception: if not enough data by deadline
""" """
orig_pos = self._pcap_reader.f.tell() # save file position orig_pos = self._pcap_reader.f.tell() # save file position
enough_data = False enough_data = False
while time.time() < deadline: # read packet header from pcap
# read packet header from pcap packet_header_size = 16
hdr = self._pcap_reader.f.read(16) caplen = None
if len(hdr) < 16: end_pos = None
time.sleep(0) # yield hdr = self._pcap_reader.f.read(packet_header_size)
continue # cannot read full header, continue looping if len(hdr) == packet_header_size:
# find the capture length - caplen # parse the capture length - caplen
sec, usec, caplen, wirelen = struct.unpack( sec, usec, caplen, wirelen = struct.unpack(
self._pcap_reader.endian + "IIII", hdr) self._pcap_reader.endian + "IIII", hdr)
self._pcap_reader.f.seek(0, 2) # seek to end of file self._pcap_reader.f.seek(0, 2) # seek to end of file
end_pos = self._pcap_reader.f.tell() # get position at end end_pos = self._pcap_reader.f.tell() # get position at end
if end_pos >= orig_pos + len(hdr) + caplen: if end_pos >= orig_pos + len(hdr) + caplen:
enough_data = True # yay, we have enough data 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 self._pcap_reader.f.seek(orig_pos, 0) # restore original position
if not enough_data: return 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): def wait_for_packet(self, timeout, filter_out_fn=is_ipv6_misc):
""" """
@ -327,8 +329,8 @@ class VppPGInterface(VppInterface):
deadline = time.time() + timeout deadline = time.time() + timeout
if self._pcap_reader is None: if self._pcap_reader is None:
if not self.wait_for_capture_file(timeout): if not self.wait_for_capture_file(timeout):
raise Exception("Capture file %s did not appear within " raise CaptureTimeoutError("Capture file %s did not appear "
"timeout" % self.out_path) "within timeout" % self.out_path)
while time.time() < deadline: while time.time() < deadline:
try: try:
self._pcap_reader = PcapReader(self.out_path) self._pcap_reader = PcapReader(self.out_path)
@ -338,12 +340,20 @@ class VppPGInterface(VppInterface):
"Exception in scapy.PcapReader(%s): %s" % "Exception in scapy.PcapReader(%s): %s" %
(self.out_path, format_exc())) (self.out_path, format_exc()))
if not self._pcap_reader: if not self._pcap_reader:
raise Exception("Capture file %s did not appear within " raise CaptureTimeoutError("Capture file %s did not appear within "
"timeout" % self.out_path) "timeout" % self.out_path)
self.test.logger.debug("Waiting for packet") poll = False
while time.time() < deadline: if timeout > 0:
self.wait_for_packet_data(deadline) 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() p = self._pcap_reader.recv()
if p is not None: if p is not None:
if filter_out_fn is not None and filter_out_fn(p): if filter_out_fn is not None and filter_out_fn(p):
@ -356,8 +366,9 @@ class VppPGInterface(VppInterface):
(time.time() - (deadline - timeout))) (time.time() - (deadline - timeout)))
return p return p
time.sleep(0) # yield time.sleep(0) # yield
poll = False
self.test.logger.debug("Timeout - no packets received") 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): def create_arp_req(self):
"""Create ARP request applicable for this interface""" """Create ARP request applicable for this interface"""