test/framework.py: change logger to return 'e' format.

* When the framework logs an unexpected sleep time,
  display the units in the same format. Typically,
  it has been returning a float and an 'e'.
  ex. unexpected time.sleep() result - slept for 0.000107049942017s instead of ~4.88758087158e-05s!

* Defer logger interpolation.

Change-Id: I543ad6d41c7f263d61615341437f80973c0017de
Signed-off-by: Paul Vinciguerra <pvinci@vinciconsulting.com>
This commit is contained in:
Paul Vinciguerra
2018-12-09 15:37:04 -08:00
committed by Ole Trøan
parent dfb984d4e8
commit 6919b0de47

View File

@ -32,6 +32,7 @@ from util import ppp, is_core_present
from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
from scapy.layers.inet6 import ICMPv6EchoReply from scapy.layers.inet6 import ICMPv6EchoReply
if os.name == 'posix' and sys.version_info[0] < 3: if os.name == 'posix' and sys.version_info[0] < 3:
# using subprocess32 is recommended by python official documentation # using subprocess32 is recommended by python official documentation
# @ https://docs.python.org/2/library/subprocess.html # @ https://docs.python.org/2/library/subprocess.html
@ -39,20 +40,17 @@ if os.name == 'posix' and sys.version_info[0] < 3:
else: else:
import subprocess import subprocess
PASS = 0 PASS = 0
FAIL = 1 FAIL = 1
ERROR = 2 ERROR = 2
SKIP = 3 SKIP = 3
TEST_RUN = 4 TEST_RUN = 4
debug_framework = False debug_framework = False
if os.getenv('TEST_DEBUG', "0") == "1": if os.getenv('TEST_DEBUG', "0") == "1":
debug_framework = True debug_framework = True
import debug_internal import debug_internal
""" """
Test framework module. Test framework module.
@ -130,8 +128,8 @@ def pump_output(testclass):
for line in split[:limit]: for line in split[:limit]:
testclass.logger.debug( testclass.logger.debug(
"VPP STDERR: %s" % line.rstrip("\n")) "VPP STDERR: %s" % line.rstrip("\n"))
# ignoring the dummy pipe here intentionally - the flag will take care # ignoring the dummy pipe here intentionally - the
# of properly terminating the loop # flag will take care of properly terminating the loop
def is_skip_aarch64_set(): def is_skip_aarch64_set():
@ -844,8 +842,8 @@ class VppTestCase(unittest.TestCase):
for cf in checksum_fields: for cf in checksum_fields:
if hasattr(layer, cf): if hasattr(layer, cf):
if ignore_zero_udp_checksums and \ if ignore_zero_udp_checksums and \
0 == getattr(layer, cf) and \ 0 == getattr(layer, cf) and \
layer.name in udp_layers: layer.name in udp_layers:
continue continue
delattr(layer, cf) delattr(layer, cf)
checksums.append((counter, cf)) checksums.append((counter, cf))
@ -920,7 +918,7 @@ class VppTestCase(unittest.TestCase):
def assert_packet_counter_equal(self, counter, expected_value): def assert_packet_counter_equal(self, counter, expected_value):
counters = self.vapi.cli("sh errors").split('\n') counters = self.vapi.cli("sh errors").split('\n')
counter_value = -1 counter_value = -1
for i in range(1, len(counters)-1): for i in range(1, len(counters) - 1):
results = counters[i].split() results = counters[i].split()
if results[1] == counter: if results[1] == counter:
counter_value = int(results[0]) counter_value = int(results[0])
@ -931,18 +929,18 @@ class VppTestCase(unittest.TestCase):
@classmethod @classmethod
def sleep(cls, timeout, remark=None): def sleep(cls, timeout, remark=None):
if hasattr(cls, 'logger'): if hasattr(cls, 'logger'):
cls.logger.debug("Starting sleep for %ss (%s)" % (timeout, remark)) cls.logger.debug("Starting sleep for %es (%s)", timeout, remark)
before = time.time() before = time.time()
time.sleep(timeout) time.sleep(timeout)
after = time.time() after = time.time()
if after - before > 2 * timeout: if hasattr(cls, 'logger') and after - before > 2 * timeout:
cls.logger.error("unexpected time.sleep() result - " cls.logger.error("unexpected time.sleep() result - "
"slept for %ss instead of ~%ss!" % ( "slept for %es instead of ~%es!",
after - before, timeout)) after - before, timeout)
if hasattr(cls, 'logger'): if hasattr(cls, 'logger'):
cls.logger.debug( cls.logger.debug(
"Finished sleep (%s) - slept %ss (wanted %ss)" % ( "Finished sleep (%s) - slept %es (wanted %es)",
remark, after - before, timeout)) remark, after - before, timeout)
def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None): def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
self.vapi.cli("clear trace") self.vapi.cli("clear trace")
@ -1262,6 +1260,7 @@ class VppTestRunner(unittest.TextTestRunner):
""" """
A basic test runner implementation which prints results to standard error. A basic test runner implementation which prints results to standard error.
""" """
@property @property
def resultclass(self): def resultclass(self):
"""Class maintaining the results of the tests""" """Class maintaining the results of the tests"""
@ -1270,7 +1269,6 @@ class VppTestRunner(unittest.TextTestRunner):
def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1, def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
result_pipe=None, failfast=False, buffer=False, result_pipe=None, failfast=False, buffer=False,
resultclass=None, print_summary=True): resultclass=None, print_summary=True):
# ignore stream setting here, use hard-coded stdout to be in sync # ignore stream setting here, use hard-coded stdout to be in sync
# with prints from VppTestCase methods ... # with prints from VppTestCase methods ...
super(VppTestRunner, self).__init__(sys.stdout, descriptions, super(VppTestRunner, self).__init__(sys.stdout, descriptions,