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>

diff --git a/test/framework.py b/test/framework.py
index c84c8ca..242a079 100644 (file)
--- a/test/framework.py
+++ b/test/framework.py
@@ -32,6 +32,7 @@ from util import ppp, is_core_present
 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
 from scapy.layers.inet6 import ICMPv6EchoReply
 from scapy.layers.inet import IPerror, TCPerror, UDPerror, ICMPerror
 from scapy.layers.inet6 import ICMPv6DestUnreach, ICMPv6EchoRequest
 from scapy.layers.inet6 import ICMPv6EchoReply

+

 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
 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


@@ -39,20 +40,17 @@ if os.name == 'posix' and sys.version_info[0] < 3:
 else:
     import subprocess
 
 else:
     import subprocess
 

-

 PASS = 0
 FAIL = 1
 ERROR = 2
 SKIP = 3
 TEST_RUN = 4
 
 PASS = 0
 FAIL = 1
 ERROR = 2
 SKIP = 3
 TEST_RUN = 4
 

-

 debug_framework = False
 if os.getenv('TEST_DEBUG', "0") == "1":
     debug_framework = True
     import debug_internal
 
 debug_framework = False
 if os.getenv('TEST_DEBUG', "0") == "1":
     debug_framework = True
     import debug_internal
 

-

 """
   Test framework module.
 
 """
   Test framework module.
 


@@ -130,8 +128,8 @@ def pump_output(testclass):
                     for line in split[:limit]:
                         testclass.logger.debug(
                             "VPP STDERR: %s" % line.rstrip("\n"))
                     for line in split[:limit]:
                         testclass.logger.debug(
                             "VPP STDERR: %s" % line.rstrip("\n"))

-        # ignoring the dummy pipe here intentionally - the flag will take care
-        # of properly terminating the loop
+                        # ignoring the dummy pipe here intentionally - the
+                        # 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:
                     if hasattr(layer, cf):
                         if ignore_zero_udp_checksums and \
                 for cf in checksum_fields:
                     if hasattr(layer, cf):
                         if ignore_zero_udp_checksums and \

-                                0 == getattr(layer, cf) and \
-                                layer.name in udp_layers:
+                                        0 == getattr(layer, cf) and \
+                                        layer.name in udp_layers:

                             continue
                         delattr(layer, cf)
                         checksums.append((counter, cf))
                             continue
                         delattr(layer, cf)
                         checksums.append((counter, cf))


@@ -920,7 +918,7 @@ class VppTestCase(unittest.TestCase):
     def assert_packet_counter_equal(self, counter, expected_value):
         counters = self.vapi.cli("sh errors").split('\n')
         counter_value = -1
     def assert_packet_counter_equal(self, counter, expected_value):
         counters = self.vapi.cli("sh errors").split('\n')
         counter_value = -1

-        for i in range(1, len(counters)-1):
+        for i in range(1, len(counters) - 1):

             results = counters[i].split()
             if results[1] == counter:
                 counter_value = int(results[0])
             results = counters[i].split()
             if results[1] == counter:
                 counter_value = int(results[0])


@@ -931,18 +929,18 @@ class VppTestCase(unittest.TestCase):
     @classmethod
     def sleep(cls, timeout, remark=None):
         if hasattr(cls, 'logger'):
     @classmethod
     def sleep(cls, timeout, remark=None):
         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()
         time.sleep(timeout)
         after = time.time()
         before = time.time()
         time.sleep(timeout)
         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!" % (
-                                 after - before, timeout))
+                             "slept for %es instead of ~%es!",
+                             after - before, timeout)

         if hasattr(cls, 'logger'):
             cls.logger.debug(
         if hasattr(cls, 'logger'):
             cls.logger.debug(

-                "Finished sleep (%s) - slept %ss (wanted %ss)" % (
-                    remark, after - before, timeout))
+                "Finished sleep (%s) - slept %es (wanted %es)",
+                remark, after - before, timeout)

 
     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
         self.vapi.cli("clear trace")
 
     def send_and_assert_no_replies(self, intf, pkts, remark="", timeout=None):
         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
     def resultclass(self):
         """Class maintaining the results of the tests"""
     @property
     def resultclass(self):
         """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,
                  result_pipe=None, failfast=False, buffer=False,
                  resultclass=None, print_summary=True):
     def __init__(self, keep_alive_pipe=None, descriptions=True, verbosity=1,
                  result_pipe=None, failfast=False, buffer=False,
                  resultclass=None, print_summary=True):

-

         # ignore stream setting here, use hard-coded stdout to be in sync
         # with prints from VppTestCase methods ...
         super(VppTestRunner, self).__init__(sys.stdout, descriptions,
         # ignore stream setting here, use hard-coded stdout to be in sync
         # with prints from VppTestCase methods ...
         super(VppTestRunner, self).__init__(sys.stdout, descriptions,