nicer displays of various durations
Thierry Parmentelat [Sun, 1 Mar 2015 07:22:55 +0000 (08:22 +0100)]
system/Completer.py
system/TestMain.py
system/TestPlc.py
system/TestSlice.py
system/TestSliceSfa.py

index 2e1586d..5cf3c9b 100755 (executable)
@@ -9,9 +9,10 @@ import utils
 ### takes in argument a list of tasks that are instances 
 ### of a CompleterTask subclass
 class Completer:
-    def __init__ (self, tasks, verbose=True):
+    def __init__ (self, tasks, verbose=True, message=None):
         self.tasks=tasks
         self.verbose=verbose
+        self.message="({})".format(message) if message else ""
     def run (self, timeout_timedelta, silent_timedelta, period=None):
         begin = datetime.now()
         timeout = begin+timeout_timedelta
@@ -30,7 +31,10 @@ class Completer:
                 if success: fine.append(task)
             for task in fine: tasks.remove(task)
             if not tasks:
-                print "Completer duration = {}".format(int(datetime.now()-begin))
+                if self.verbose:
+                    duration = datetime.now()-begin
+                    print "total completer {} {}s".format(self.message,
+                                                          int(duration.total_seconds()))
                 return True
             if datetime.now() > timeout:
                 for task in tasks: 
index 3fa6816..dd4fbd3 100755 (executable)
@@ -6,9 +6,9 @@
 import sys, os, os.path
 from optparse import OptionParser
 import traceback
-from time import strftime
 import readline
 import glob
+from datetime import datetime
 
 import utils
 from TestPlc import TestPlc, Ignored
@@ -190,9 +190,6 @@ steps refer to a method in TestPlc or to a step_* module
                           help="prompts before each step")
         parser.add_option("-n","--dry-run", action="store_true", dest="dry_run", default=False,
                           help="Show environment and exits")
-# dropped when added Completer.py
-#        parser.add_option("-r","--restart-nm", action="store_true", dest="forcenm", default=False, 
-#                          help="Force the NM to restart in ssh_slices step")
         parser.add_option("-t","--trace", action="store", dest="trace_file", default=None,
                           help="Trace file location")
         (self.options, self.args) = parser.parse_args()
@@ -410,7 +407,7 @@ steps refer to a method in TestPlc or to a step_* module
 
         # do all steps on all plcs
         TIME_FORMAT="%H-%M-%S"
-        TRACE_FORMAT="TRACE: %(plc_counter)d %(beg)s->%(end)s status=%(status)s step=%(stepname)s plc=%(plcname)s force=%(force)s\n"
+        TRACE_FORMAT="TRACE: %(plc_counter)d %(begin)s->%(seconds)ss=%(duration)s status=%(status)s step=%(stepname)s plc=%(plcname)s force=%(force)s\n"
         for (stepname,method,force,cross,qualifier) in all_step_infos:
             plc_counter=0
             for (spec,plc_obj) in all_plcs:
@@ -422,7 +419,8 @@ steps refer to a method in TestPlc or to a step_* module
                 across_plcs = [ o for (s,o) in all_plcs if o!=plc_obj ]
 
                 # run the step
-                beg=strftime(TIME_FORMAT)
+                beg_time = datetime.now()
+                begin = beg_time.strftime(TIME_FORMAT)
                 if not spec['failed_step'] or force or self.options.interactive or self.options.keep_going:
                     skip_step=False
                     if self.options.interactive:
@@ -497,7 +495,9 @@ steps refer to a method in TestPlc or to a step_* module
                     utils.header("********** %d SKIPPED Step %s on %s (%s)"%(plc_counter,stepname,plcname,why))
                     status="UNDEF"
                 if not self.options.dry_run:
-                    end=strftime(TIME_FORMAT)
+                    delay = datetime.now()-beg_time
+                    seconds = int(delay.total_seconds())
+                    duration = str(delay)
                     # always do this on stdout
                     print TRACE_FORMAT%locals()
                     # duplicate on trace_file if provided
index 1d1d7c3..0b07291 100644 (file)
@@ -107,7 +107,7 @@ class slice_mapper__tasks (object):
                 test_site = TestSite(self,site_spec)
                 test_slice=TestSlice(self,test_site,slice_spec)
                 tasks += slice_method (test_slice, self.options)
-            return Completer (tasks).run (decorator_self.timeout, decorator_self.silent, decorator_self.period)
+            return Completer (tasks, message=method.__name__).run (decorator_self.timeout, decorator_self.silent, decorator_self.period)
         # restore the doc text from the TestSlice method even if a bit odd
         wrappee.__name__ = method.__name__
         wrappee.__doc__ = slice_method.__doc__
@@ -1040,7 +1040,8 @@ class TestPlc:
         utils.header("checking nodes boot state (expected %s)"%target_boot_state)
         tasks = [ CompleterTaskBootState (self,hostname) \
                       for (hostname,_) in self.all_node_infos() ]
-        return Completer (tasks).run (timeout, graceout, period)
+        message = 'check_boot_state={}'.format(target_boot_state)
+        return Completer (tasks, message=message).run (timeout, graceout, period)
 
     def nodes_booted(self):
         return self.nodes_check_boot_state('boot',timeout_minutes=30,silent_minutes=28)
@@ -1065,7 +1066,7 @@ class TestPlc:
         period=timedelta (seconds=period_seconds)
         node_infos = self.all_node_infos()
         tasks = [ CompleterTaskPingNode (h) for (h,_) in node_infos ]
-        return Completer (tasks).run (timeout, graceout, period)
+        return Completer (tasks, message='ping_node').run (timeout, graceout, period)
 
     # ping node before we try to reach ssh, helpful for troubleshooting failing bootCDs
     def ping_node (self):
@@ -1080,15 +1081,17 @@ class TestPlc:
         vservername=self.vservername
         if debug: 
             message="debug"
+            completer_message = 'ssh_node_debug'
             local_key = "keys/%(vservername)s-debug.rsa"%locals()
         else: 
             message="boot"
+            completer_message = 'ssh_node_boot'
            local_key = "keys/key_admin.rsa"
         utils.header("checking ssh access to nodes (expected in %s mode)"%message)
         node_infos = self.all_node_infos()
         tasks = [ CompleterTaskNodeSsh (nodename, qemuname, local_key, boot_state=message) \
                       for (nodename,qemuname) in node_infos ]
-        return Completer (tasks).run (timeout, graceout, period)
+        return Completer (tasks, message=completer_message).run (timeout, graceout, period)
         
     def ssh_node_debug(self):
         "Tries to ssh into nodes in debug mode with the debug ssh key"
@@ -1161,7 +1164,7 @@ class TestPlc:
                 test_node = TestNode (self,test_site,node)
                 test_sliver = TestSliver (self, test_node, test_slice)
                 tasks.append ( CompleterTaskInitscript (test_sliver, stamp))
-        return Completer (tasks).run (timedelta(minutes=5), timedelta(minutes=4), timedelta(seconds=10))
+        return Completer (tasks, message='check_initscripts').run (timedelta(minutes=5), timedelta(minutes=4), timedelta(seconds=10))
            
     def check_initscripts(self):
         "check that the initscripts have triggered"
@@ -1351,7 +1354,7 @@ class TestPlc:
         period  = timedelta (seconds=period_seconds)
         tasks = [ CompleterTaskSystemSlice (test_node, self.options.dry_run) \
                       for test_node in self.all_nodes() ]
-        return Completer (tasks) . run (timeout, silent, period)
+        return Completer (tasks, message='_check_system_slice') . run (timeout, silent, period)
 
     def plcsh_stress_test (self):
         "runs PLCAPI stress test, that checks Add/Update/Delete on all types - preserves contents"
index 0043d4c..f7e406b 100644 (file)
@@ -10,7 +10,7 @@ from TestKey import TestKey
 from TestUser import TestUser
 from TestNode import TestNode, CompleterTaskNodeSsh
 from TestSsh import TestSsh
-from Completer import Completer, CompleterTask
+from Completer import CompleterTask
 
 class CompleterTaskSliceSsh (CompleterTask):
 
@@ -182,7 +182,6 @@ class TestSlice:
             tasks.append( CompleterTaskSliceSsh(self.test_plc,node_spec['node_fields']['hostname'],
                                                 slicename,private_key,command,expected,dry_run))
         return tasks
-#        return Completer (tasks).run (timeout, graceout, period)
 
     def ssh_slice_basics (self, options, *args, **kwds):
         "the slice is expected to be UP and we just check a few simple sanity commands, including 'ps' to check for /proc"
index eba256d..341f518 100644 (file)
@@ -200,4 +200,4 @@ class TestSliceSfa:
             (site_spec,node_spec) = self.test_plc.locate_node(nodename)
             tasks.append( CompleterTaskSliceSsh(self.test_plc,node_spec['node_fields']['hostname'],
                                                 slicename,private_key,command,expected=True,dry_run=dry_run))
-        return Completer (tasks).run (timeout, graceout, period)
+        return Completer (tasks, message='ssh_slice_sfa').run (timeout, graceout, period)