[SDFAB-664] Fix reporting for exceptions and skipped cases

Change-Id: I892fd71a6a253bf376133aa0a041b2b62d751416
diff --git a/TestON/core/teston.py b/TestON/core/teston.py
index c27388c..0aa2294 100644
--- a/TestON/core/teston.py
+++ b/TestON/core/teston.py
@@ -36,9 +36,9 @@
 import importlib
 import threading
 import pdb
-module = new.module( "test" )
 import openspeak
 import subprocess
+module = new.module( "test" )
 global path, drivers_path, core_path, tests_path, logs_path
 location = os.path.abspath( os.path.dirname( __file__ ) )
 path = re.sub( "(core|bin)$", "", location )
@@ -51,13 +51,14 @@
 sys.path.append( drivers_path )
 sys.path.append( core_path )
 sys.path.append( tests_path )
-
 from core.utilities import Utilities
 from core.Thread import Thread
 
+
 class SkipCase( Exception ):
     pass
 
+
 class TestON:
     '''
     TestON will initiate the specified test.
@@ -238,14 +239,14 @@
         self.TOTAL_TC_PLANNED = len( self.testcases_list ) * repeat
         self.log.TAP( "1..%s" % self.TOTAL_TC_PLANNED )
 
-        result = self.TRUE
+        executed = self.TRUE
         while repeat:
             self.leftCase.extend( self.testcases_list )
             for self.CurrentTestCaseNumber in self.testcases_list:
                 self.executedCase.append( self.leftCase.pop( 0 ) )
-                result = self.runCase( self.CurrentTestCaseNumber )
+                executed = self.runCase( self.CurrentTestCaseNumber )
             repeat -= 1
-        return result
+        return executed
 
     def runCase( self, testCaseNumber ):
         self.CurrentTestCaseNumber = testCaseNumber
@@ -257,7 +258,7 @@
         self.caseExplanation = ""
         self.CASERESULT = self.ERROR
         self.STEPRESULT = self.NORESULT
-        result = self.TRUE
+        executed = self.TRUE
 
         # NOTE: number of main.step statements in the
         #       outer most level of the test case. used to
@@ -281,10 +282,11 @@
             return self.FALSE
         self.stepCount = 0
         while self.stepCount < len( self.code[ self.testCaseNumber ].keys() ):
-            result = self.runStep( self.code, self.testCaseNumber )
-            if result == self.FALSE:
+            executed = self.runStep( self.code, self.testCaseNumber )
+            if executed == self.FALSE:
+                # Skip the rest of the case if python error or SkipCase
                 break
-            elif result == self.TRUE:
+            elif executed == self.TRUE:
                 continue
         # stepResults format: ( stepNo[], stepName[], stepResult[], onFail[] )
         stepResults = self.stepResultsList
@@ -312,7 +314,7 @@
             self.caseResultsWiki()
             self.caseResultsTAP()
             self.stepCache = ""
-        return result
+        return executed
 
     def caseResultsWiki( self ):
         """
@@ -367,7 +369,6 @@
         for line in stepLines:
             self.log.TAP( line )
 
-
     def organizeResult( self, caseNum, result ):
         """
             Organize the result and put the current number into either
@@ -400,6 +401,7 @@
                 self.stepCount = self.stepCount + 1
                 return self.FALSE
             except StandardError as e:
+                e_info = sys.exc_info()
                 try:
                     stepNo = self.stepResults[ 0 ][ self.stepNumber - 1 ]
                 except IndexError:
@@ -412,17 +414,21 @@
                     stepName = self.stepResults[ 1 ][ self.stepNumber - 1 ]
                 except IndexError:
                     stepName = "<IndexError>"
-                self.log.error( "\nException in the following section of" +
-                                " code: " + str( testCaseNumber ) + "." +
-                                str( stepNo ) + ": " + stepName )
-                self.log.error( str( e.__class__ ) + str( e.message ) )
-                self.log.exception( "" )
+                errorMsg = "Exception in the following section of" +\
+                            " code: " + str( testCaseNumber ) + "." +\
+                            str( stepNo ) + ": " + stepName + "\n\t" +\
+                            str( e.__class__ ) + str( e.message )
+                self.log.error( errorMsg, exc_info=e_info )
+                self.onFailMsg = errorMsg + ". Skipping the rest of this case. "
+                self.stepCache += "\t\t" + self.onFailMsg + "\n"
                 self.stepCount = self.stepCount + 1
+                self.testCaseResult[ str( self.CurrentTestCaseNumber ) ] = self.FALSE
+                self.organizeResult( self.CurrentTestCaseNumber, self.FALSE )
                 self.logger.updateCaseResults( self )
-                self.stepResultsWiki()
-                self.stepResultsTAP()
-                # summary results
+                self.log.summary( self.caseExplanation )
                 self.log.summary( self.stepCache )
+                self.caseResultsWiki()
+                self.caseResultsTAP()
                 self.stepCache = ""
                 self.cleanup()
                 self.exit()
@@ -515,7 +521,10 @@
             self.CASERESULT = self.FALSE
         self.onFailMsg = "Skipping the rest of this case. "
         if msg:
-            self.onFailMsg += str( msg )
+            if isinstance( msg, Exception ):
+                self.onFailMsg += str( repr( msg ) )
+            else:
+                self.onFailMsg += str( msg )
         raise SkipCase
 
     def addCaseHeader( self ):
@@ -597,7 +606,7 @@
                                            str( component ) )
                         except StandardError:
                             self.log.exception( "Exception while disconnecting from " +
-                                                 str( component ) )
+                                                str( component ) )
                             result = self.FALSE
                     # Closing all the driver's session files
                     for driver in self.componentDictionary.keys():
@@ -612,7 +621,7 @@
                                            " close log file" )
                         except StandardError:
                             self.log.exception( "Exception while closing log files for " +
-                                                 str( driver ) )
+                                                str( driver ) )
                             result = self.FALSE
                 else:
                     pass  # Someone else already ran through this function
@@ -927,6 +936,7 @@
     verifyTestCases( options )
     verifyOnosCell( options )
 
+
 def verifyTest( options ):
     try:
         if options.testname:
@@ -941,12 +951,14 @@
         print "Test or Example not specified please specify the --test <test name > or --example <example name>"
         main.exit()
 
+
 def verifyExample( options ):
     if options.example:
         main.testDir = path + '/examples/'
         main.tests_path = path + "/examples/"
         main.classPath = "examples." + main.TEST + "." + main.TEST
 
+
 def verifyLogdir( options ):
     # Verifying Log directory option
     if options.logdir:
@@ -954,6 +966,7 @@
     else:
         main.logdir = main.FALSE
 
+
 def verifyMail( options ):
     # Mail-To: field
     if options.mail:  # Test run specific
@@ -969,6 +982,7 @@
     # Mail-From account password
     main.senderPwd = main.config[ 'config' ].get( 'mail_pass' )
 
+
 def evalTestCase( tempList ):
     tList = []
     for tcase in tempList:
@@ -978,11 +992,10 @@
             tList.extend( [ tcase ] )
     return tList
 
+
 def verifyTestCases( options ):
     # Getting Test cases list
     if options.testcases:
-        testcases_list = options.testcases
-        # sys.exit()
         testcases_list = re.sub( "(\[|\])", "", options.testcases )
         main.testcases_list = eval( testcases_list + "," )
     else:
@@ -994,6 +1007,7 @@
                   "params file or 'testcases' commandline argument"
             sys.exit()
 
+
 def verifyOnosCell( options ):
     # Verifying onoscell option
     if options.onoscell:
@@ -1018,6 +1032,7 @@
     else:
         main.onoscell = main.FALSE
 
+
 def verifyTestScript( options ):
     '''
     Verifyies test script.
@@ -1070,6 +1085,7 @@
     main.params = main.parser.parseFile( main.testDir + "/" + main.paramsFile )
     main.topology = main.parser.parseFile( main.testDir + "/" + main.topoFile )
 
+
 def verifyParams( options ):
     try:
         main.params = main.params[ 'PARAMS' ]
@@ -1118,6 +1134,7 @@
             else:
                 paramDict[ keyList[ 0 ] ] = value
 
+
 def load_parser():
     '''
     It facilitates the loading customised parser for topology and params file.
@@ -1184,6 +1201,7 @@
     except ImportError:
         print sys.exc_info()[ 1 ]
 
+
 def load_logger():
     '''
     It facilitates the loading customised parser for topology and params file.
@@ -1219,6 +1237,7 @@
     else:
         load_defaultlogger()
 
+
 def load_defaultlogger():
     '''
     It will load the default parser which is xml parser to parse the params and
@@ -1240,5 +1259,6 @@
         print sys.exc_info()[ 1 ]
         main.exit()
 
+
 def _echo( self ):
     print "THIS IS ECHO"
diff --git a/TestON/core/utilities.py b/TestON/core/utilities.py
index 012b651..039ca4a 100644
--- a/TestON/core/utilities.py
+++ b/TestON/core/utilities.py
@@ -38,6 +38,7 @@
 import time
 import random
 
+
 class Utilities:
     '''
        Utilities will take care about the basic functions like :
@@ -95,17 +96,26 @@
         onfail:'Action or string to be triggered or displayed respectively when the assert failed'
         not:'optional argument to specify the negation of the each assertion type'
         operator:'assertion type will be defined by using operator. Like equal , greater, lesser, matches.'
+        onfailFunc: Function to run when the assert fails. Will default to a noop function.
+        onfailFuncArgs: Arguments for onfailFunc
+        onfailFuncKwargs: Keyword Arguments for onfailFunc
 
         It will return the assertion result.
 
         '''
+        def noop( *args, **kwargs ):
+            pass
 
         arguments = self.parse_args( [ "EXPECT", "ACTUAL", "ONPASS", "ONFAIL", "NOT", "OPERATOR" ], **assertParam )
+        onfailFunc = noop
+        onfailFunc = assertParam.get( "onfailFunc", noop )
+        onfailFuncArgs = assertParam.get( "onfailFuncArgs", [] )
+        onfailFuncKwargs = assertParam.get( "onfailFuncKwargs", {} )
 
         result = 0
         valuetype = ''
         operation = "not " + str( arguments[ "OPERATOR" ] ) if arguments[ 'NOT' ] and arguments[ 'NOT' ] == 1 else arguments[ "OPERATOR" ]
-        operators = { 'equals': { 'STR': '==', 'NUM': '==' }, 'matches': '=~', 'greater': '>' , 'lesser': '<' }
+        operators = { 'equals': { 'STR': '==', 'NUM': '==' }, 'matches': '=~', 'greater': '>', 'lesser': '<' }
 
         expectMatch = re.match( '^\s*[+-]?0(e0)?\s*$', str( arguments[ "EXPECT" ] ), re.I + re.M )
         if not( ( not expectMatch ) and ( arguments[ "EXPECT" ] == 0 ) ):
@@ -123,9 +133,8 @@
         try:
             opcode = operators[ str( arguments[ "OPERATOR" ] ) ][ valuetype ] if arguments[ "OPERATOR" ] == 'equals' else operators[ str( arguments[ "OPERATOR" ] ) ]
 
-        except KeyError as e:
-            print "Key Error in assertion"
-            print e
+        except KeyError:
+            main.log.exeception( "Key Error in assertion" )
             return main.FALSE
 
         if opcode == '=~':
@@ -143,19 +152,19 @@
             try:
                 if str( opcode ) == "==":
                     main.log.info( "Verifying the Expected is equal to the actual or not using assert_equal" )
-                    if( arguments[ "EXPECT" ] == arguments[ "ACTUAL" ] ):
+                    if arguments[ "EXPECT" ] == arguments[ "ACTUAL" ]:
                         result = main.TRUE
                     else:
                         result = main.FALSE
                 elif str( opcode ) == ">":
                     main.log.info( "Verifying the Expected is Greater than the actual or not using assert_greater" )
-                    if( ast.literal_eval( arguments[ "EXPECT" ] ) > ast.literal_eval( arguments[ "ACTUAL" ] ) ):
+                    if ast.literal_eval( arguments[ "EXPECT" ] ) > ast.literal_eval( arguments[ "ACTUAL" ] ):
                         result = main.TRUE
                     else:
                         result = main.FALSE
                 elif str( opcode ) == "<":
                     main.log.info( "Verifying the Expected is Lesser than the actual or not using assert_lesser" )
-                    if( ast.literal_eval( arguments[ "EXPECT" ] ) < ast.literal_eval( arguments[ "ACTUAL" ] ) ):
+                    if ast.literal_eval( arguments[ "EXPECT" ] ) < ast.literal_eval( arguments[ "ACTUAL" ] ):
                         result = main.TRUE
                     else:
                         result = main.FALSE
@@ -182,9 +191,8 @@
         if not isinstance( msg, str ):
             try:
                 eval( str( msg ) )
-            except SyntaxError as e:
-                print "function definition is not right"
-                print e
+            except SyntaxError:
+                main.log.exception( "function definition is not right" )
 
         main.last_result = result
         if main.stepResults[ 2 ]:
@@ -195,7 +203,16 @@
                 pass
         else:
             main.log.warn( "Assertion called before a test step" )
-        return result
+        try:
+            if result != main.TRUE:
+                onfailFunc( *onfailFuncArgs, **onfailFuncKwargs )
+        except SkipCase:
+            raise
+        except Exception:
+            main.log.exception( "Error calling onfailFunc: %s" % onfailFunc )
+            return False
+        else:
+            return result
 
     def parse_args( self, args, **kwargs ):
         '''
diff --git a/TestON/tests/USECASE/SegmentRouting/SRStaging/dependencies/SRStagingTest.py b/TestON/tests/USECASE/SegmentRouting/SRStaging/dependencies/SRStagingTest.py
index e65be4e..70fec33 100644
--- a/TestON/tests/USECASE/SegmentRouting/SRStaging/dependencies/SRStagingTest.py
+++ b/TestON/tests/USECASE/SegmentRouting/SRStaging/dependencies/SRStagingTest.py
@@ -155,12 +155,15 @@
                 src.handle.sendline( src.pwd )
                 i = src.handle.expect( [ "password", src.prompt ] )
                 assert i != 0, "Incorrect Password"
-                output = src.handle.before + src.handle.after
+                output += src.handle.before + src.handle.after
         except Exception:
             main.log.exception( "%s: Unexpected response from ping" % src.name )
             src.handle.send( '\x03' )  # ctrl-c
             src.handle.expect( src.prompt )
+            output = src.handle.before + src.handle.after
+            main.log.debug( output )
             return main.FALSE
+        main.log.debug( output )
         main.funcs.clearBuffer( src )
         main.log.warn( "%s: %s" % ( src.name, str( src.handle.before ) ) )
         if " 0% packet loss" in output:
@@ -188,7 +191,8 @@
         main.log.info( "Starting iperf between %s and %s" % ( src.shortName, dstIp ) )
         sudoCheck = main.funcs.singlePingWithSudo( main, src, dstIp )
         if not sudoCheck:
-            main.skipCase( result="FAIL", msg="Incorrect permissions for sudo" )
+            main.skipCase( result="FAIL",
+                           msg="Unable to ping with sudo. Either flows issue or permission error." )
         src.handle.sendline( "/usr/bin/iperf %s " % iperfArgs )
         src.preDisconnect = src.exitFromProcess
 
@@ -262,18 +266,20 @@
             # ping right before to make sure arp is cached and sudo is authenticated
             sudoCheck1 = main.funcs.singlePingWithSudo( main, src, dst.interfaces[0]['ips'][0] )
             checkDesc = "sudo ping from %s to %s" % ( src.shortName, dst.interfaces[0]['ips'][0] )
-            if not sudoCheck1:
-                main.skipCase( result="FAIL", msg="Incorrect permissions for %s" % checkDesc )
             utilities.assert_equals( expect=main.TRUE, actual=sudoCheck1,
-                                     onpass="Successfully %s" % checkDesc ,
-                                     onfail="Failed to %s" % checkDesc )
+                                     onpass="Successfully %s" % checkDesc,
+                                     onfail="Failed to %s" % checkDesc,
+                                     onfailFunc=main.skipCase,
+                                     onfailFuncKwargs={ 'result': 'FAIL',
+                                                        'msg': "Unable to %s" % checkDesc } )
             sudoCheck2 = main.funcs.singlePingWithSudo( main, dst, src.interfaces[0]['ips'][0] )
             checkDesc = "sudo ping from %s to %s" % ( dst.shortName, src.interfaces[0]['ips'][0] )
-            if not sudoCheck2:
-                main.skipCase( result="FAIL", msg="Incorrect permissions for %s" % checkDesc )
-            utilities.assert_equals( expect=main.TRUE, actual=sudoCheck1,
-                                     onpass="Successfully %s" % checkDesc ,
-                                     onfail="Failed to %s" % checkDesc )
+            utilities.assert_equals( expect=main.TRUE, actual=sudoCheck2,
+                                     onpass="Successfully %s" % checkDesc,
+                                     onfail="Failed to %s" % checkDesc,
+                                     onfailFunc=main.skipCase,
+                                     onfailFuncKwargs={ 'result': 'FAIL',
+                                                        'msg': "Unable to %s" % checkDesc } )
             # Start traffic
             # TODO: ASSERTS
             if pingOnly: