lib: show run_and_expect spent time

Standardize run_and_expect to show start and end time along with maximum
estimated wait time.

Signed-off-by: Rafael Zalamena <rzalamena@opensourcerouting.org>

diff --git a/tests/topotests/lib/topotest.py b/tests/topotests/lib/topotest.py
index 1cbde825ac9059512e730e36f4cf1f360654c08b..b5c9bbe165925f2769a9d145efcc4316a330bff1 100644 (file)
--- a/tests/topotests/lib/topotest.py
+++ b/tests/topotests/lib/topotest.py
@@ -27,6 +27,7 @@ import os
 import errno
 import re
 import sys
+import functools
 import glob
 import StringIO
 import subprocess
@@ -207,13 +208,32 @@ def run_and_expect(func, what, count=20, wait=3):
     Returns (True, func-return) on success or
     (False, func-return) on failure.
     """
+    start_time = time.time()
+    func_name = "<unknown>"
+    if func.__class__ == functools.partial:
+        func_name = func.func.__name__
+    else:
+        func_name = func.__name__
+
+    logger.info(
+        "'{}' polling started (interval {} secs, maximum wait {} secs)".format(
+            func_name, wait, int(wait * count)))
+
     while count > 0:
         result = func()
         if result != what:
             time.sleep(wait)
             count -= 1
             continue
+
+        end_time = time.time()
+        logger.info("'{}' succeeded after {:.2f} seconds".format(
+            func_name, end_time - start_time))
         return (True, result)
+
+    end_time = time.time()
+    logger.error("'{}' failed after {:.2f} seconds".format(
+        func_name, end_time - start_time))
     return (False, result)