TestON/tests/SCPF/SCPFswitchLat/SCPFswitchLat.py

# CASE1 starts number of nodes specified in param file
#
# cameron@onlab.us

class SCPFswitchLat:

    def __init__( self ):
        self.default = ''

    def CASE1( self, main ):
        import sys
        import re
        import os
        import time

        global init
        try:
            if type(init) is not bool:
                init = Fals
        except NameError:
            init = False

        #Load values from params file
        checkoutBranch = main.params[ 'GIT' ][ 'checkout' ]
        gitPull = main.params[ 'GIT' ][ 'autopull' ]
        cellName = main.params[ 'ENV' ][ 'cellName' ]
        Apps = main.params[ 'ENV' ][ 'cellApps' ]
        BENCHIp = main.params[ 'BENCH' ][ 'ip' ]
        MN1Ip = main.params[ 'MN' ][ 'ip1' ]
        main.maxNodes = int(main.params[ 'max' ])
        cellName = main.params[ 'ENV' ][ 'cellName' ]
        homeDir = os.path.expanduser('~')
        topoCfgFile = main.params['TEST']['topoConfigFile']
        topoCfgName = main.params['TEST']['topoConfigName']
        switchEventResultPath = main.params['DB']['switchEventResultPath']
        skipMvn = main.params ['TEST']['mci']
        testONpath = re.sub( "(tests)$", "bin", main.testDir )  # TestON/bin
        user = main.params[ 'CTRL' ][ 'user' ]

        # -- INIT SECTION, ONLY RUNS ONCE -- #
        if init == False:
            init = True
            global clusterCount             #number of nodes running
            global scale
            global commit
            global timeToPost
            global runNum
            global jenkinsBuildNumber
            global CLIs
            CLIs = []
            main.ONOSIp = []

            for i in range( 1, 8 ):
                CLIs.append( getattr( main, 'ONOS' + str( i ) + 'cli' ) )

            timeToPost = time.strftime('%Y-%m-%d %H:%M:%S')
            runNum = time.strftime('%d%H%M%S')

            try:
                jenkinsBuildNumber = str(os.environ['BUILD_NUMBER'])
                main.log.report( 'Jenkins build number: ' + jenkinsBuildNumber )
            except KeyError:
                jenkinsBuildNumber = str(0)
                main.log.info( 'Job is not run by jenkins. ' + 'Build number set to: ' + jenkinsBuildNumber)

            clusterCount = 0
            main.ONOSIp = main.ONOSbench.getOnosIps()

            scale = (main.params[ 'SCALE' ]).split(",")
            clusterCount = int(scale[0])

            #mvn clean install, for debugging set param 'skipCleanInstall' to yes to speed up test
            if skipMvn != "off":
                mvnResult = main.ONOSbench.cleanInstall()

            #git
            main.step( "Git checkout and pull " + checkoutBranch )
            if gitPull == 'on':
                checkoutResult = main.ONOSbench.gitCheckout( checkoutBranch )
                pullResult = main.ONOSbench.gitPull()

            else:
                checkoutResult = main.TRUE
                pullResult = main.TRUE
                main.log.info( "Skipped git checkout and pull" )

            main.step("Grabbing commit number")
            commit = main.ONOSbench.getVersion()       ####
            commit = (commit.split(" "))[1]

            temp = testONpath.replace("bin","") + "tests/SCPFswitchLat/dependencies/"
            main.ONOSbench.scp( main.Mininet1,
                                temp + "topo-perf-1sw.py",
                                main.Mininet1.home,
                                direction="to" )
            #main.ONOSbench.handle.expect(":~")

            main.step('Clearing previous DB log file')
            print switchEventResultPath
            fSwitchLog = open(switchEventResultPath, "w+")
            fSwitchLog.write("")
            fSwitchLog.close()

        # -- END OF INIT SECTION --#

        main.step("Adjusting scale")
        clusterCount = int(scale[0])
        scale.remove(scale[0])

        #kill off all onos processes
        main.step("Safety check, killing all ONOS processes before initiating environment setup")
        for node in range(main.maxNodes):
            main.ONOSbench.onosDie(main.ONOSIp[node])

        #Uninstall everywhere
        main.step( "Cleaning Enviornment..." )
        for i in range(main.maxNodes):
            main.log.info(" Uninstalling ONOS " + str(i) )
            main.ONOSbench.onosUninstall( main.ONOSIp[i] )
        main.log.info("Sleep 10 second for uninstall to settle...")
        time.sleep(10)
        main.ONOSbench.handle.sendline(" ")
        main.ONOSbench.handle.expect(":~")

        #construct the cell file
        main.log.info("Creating cell file")
        cellIp = []
        for node in range (clusterCount):
            cellIp.append(main.ONOSIp[node])

        main.ONOSbench.createCellFile(main.ONOSbench.ip_address, cellName, MN1Ip, str(Apps), cellIp)

        main.step( "Set Cell" )
        main.ONOSbench.setCell(cellName)

        main.step( "Creating ONOS package" )
        packageResult = main.ONOSbench.onosPackage()

        main.step( "verify cells" )
        verifyCellResult = main.ONOSbench.verifyCell()

        main.step('Starting mininet topology ')
        main.Mininet1.startNet()

        main.log.report( "Initializeing " + str( clusterCount ) + " node cluster." )
        for node in range(clusterCount):
            main.log.info("Starting ONOS " + str(node) + " at IP: " + main.ONOSIp[node])
            main.ONOSbench.onosInstall( node=main.ONOSIp[node])

        for i in range(50):
            time.sleep(15)
            print "attempt " + str(i)
            main.ONOSbench.handle.sendline("onos $OC1 summary")
            main.ONOSbench.handle.expect(":~")
            print main.ONOSbench.handle.before
            if "nodes=" in main.ONOSbench.handle.before:
                break

        for node in range(clusterCount):
            for i in range( 2 ):
                isup = main.ONOSbench.isup( main.ONOSIp[node] )
                if isup:
                    main.log.info("ONOS " + str(node) + " is up\n")
                    break
            if not isup:
                main.log.report( "ONOS " + str(node) + " didn't start!" )
        main.log.info("Startup sequence complete")

        #time.sleep(20)

        main.step('Start onos cli')
        for i in range(0,clusterCount):
            cli1 = CLIs[i].startOnosCli(main.ONOSIp[i])

        main.step( 'Configuring application parameters' )

        configName = 'org.onosproject.net.topology.impl.DefaultTopologyProvider'
        configParam = 'maxEvents 1'
        main.ONOSbench.onosCfgSet( main.ONOSIp[0], configName, configParam )
        configParam = 'maxBatchMs 0'
        main.ONOSbench.onosCfgSet( main.ONOSIp[0], configName, configParam )
        configParam = 'maxIdleMs 0'
        main.ONOSbench.onosCfgSet( main.ONOSIp[0], configName, configParam )

    def CASE2(self, main):
        print "Cluster size: " + str(clusterCount)
        """
        Assign s3 to ONOSbench and measure latency

        There are 4 levels of latency measurements to this test:
        1 ) End-to-end measurement: Complete end-to-end measurement
           from TCP ( SYN/ACK ) handshake to Graph change
        2 ) OFP-to-graph measurement: 'ONOS processing' snippet of
           measurement from OFP Vendor message to Graph change
        3 ) OFP-to-device measurement: 'ONOS processing without
           graph change' snippet of measurement from OFP vendor
           message to Device change timestamp
        4 ) T0-to-device measurement: Measurement that includes
           the switch handshake to devices timestamp without
           the graph view change. ( TCP handshake -> Device
           change )
        """
        import time
        import subprocess
        import json
        import requests
        import os
        import numpy

        ONOSUser = main.params['CTRL']['user']
        numIter = main.params['TEST']['numIter']
        iterIgnore = int(main.params['TEST']['iterIgnore'])

        deviceTimestampKey = main.params['JSON']['deviceTimestamp']
        graphTimestampKey = main.params['JSON']['graphTimestamp']

        debugMode = main.params['TEST']['debugMode']
        onosLog = main.params['TEST']['onosLogFile']
        resultPath = main.params['DB']['switchEventResultPath']
        thresholdStr = main.params['TEST']['singleSwThreshold']
        thresholdObj = thresholdStr.split(',')
        thresholdMin = int(thresholdObj[0])
        thresholdMax = int(thresholdObj[1])

        # Look for 'role-request' messages,
        # which replaces the 'vendor' messages previously seen
        # on OVS 2.0.1
        tsharkTcpString = main.params[ 'TSHARK' ][ 'tcpSynAck' ]
        tsharkFeatureReply = main.params[ 'TSHARK' ][ 'featureReply' ]
        tsharkRoleRequest = main.params[ 'TSHARK' ][ 'roleRequest' ]
        tsharkOfString = main.params[ 'TSHARK' ][ 'ofpRoleReply' ]
        tsharkFinAckSequence = main.params[ 'TSHARK' ][ 'finAckSequence' ]

        tsharkOfOutput = '/tmp/tshark_of_topo.txt'
        tsharkTcpOutput = '/tmp/tshark_tcp_topo.txt'
        tsharkRoleOutput = '/tmp/tshark_role_request.txt'
        tsharkFeatureOutput = '/tmp/tshark_feature_reply.txt'
        tsharkFinAckOutput = '/tmp/tshark_fin_ack.txt'

        # Switch connect measurement list
        # TCP Syn/Ack -> Feature Reply latency collection for each node
        tcpToFeatureLatNodeIter = numpy.zeros((clusterCount, int(numIter)))
        # Feature Reply -> Role Request latency collection for each node
        featureToRoleRequestLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        # Role Request -> Role Reply latency collection for each node
        roleRequestToRoleReplyLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        # Role Reply -> Device Update latency collection for each node
        roleReplyToDeviceLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        # Device Update -> Graph Update latency collection for each node
        deviceToGraphLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        endToEndLatNodeIter = numpy.zeros((clusterCount, int(numIter)))

        # Switch disconnect measurement lists
        # Mininet Fin / Ack -> Mininet Ack
        finAckTransactionLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        # Mininet Ack -> Device Event
        ackToDeviceLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        # Device event -> Graph event
        deviceToGraphDiscLatNodeIter = numpy.zeros((clusterCount,
            int(numIter)))
        endToEndDiscLatNodeIter = numpy.zeros((clusterCount, int(numIter)))

        assertion = main.TRUE
        localTime = time.strftime('%x %X')
        localTime = localTime.replace('/', '')
        localTime = localTime.replace(' ', '_')
        localTime = localTime.replace(':', '')

        if debugMode == 'on':
            main.ONOSbench.tsharkPcap('eth0', '/tmp/single_sw_lat_pcap_' + localTime)
            main.log.info('Debug mode is on')

        main.log.report('Latency of adding one switch to controller')
        main.log.report('First ' + str(iterIgnore) + ' iterations ignored' + ' for jvm warmup time')
        main.log.report('Total iterations of test: ' + str(numIter))

        for i in range(0, int(numIter)):
            main.log.info('Starting tshark capture')
            main.ONOSbench.tsharkGrep(tsharkTcpString, tsharkTcpOutput)
            main.ONOSbench.tsharkGrep(tsharkOfString, tsharkOfOutput)
            main.ONOSbench.tsharkGrep(tsharkRoleRequest, tsharkRoleOutput)
            main.ONOSbench.tsharkGrep(tsharkFeatureReply, tsharkFeatureOutput)

            time.sleep(10)

            main.log.info('Assigning s3 to controller')
            main.Mininet1.assignSwController(sw='s3',
                    ip=main.ONOSIp[0])

            jsonStr = []
            for node in range (0, clusterCount):
                metricsSwUp = CLIs[node].topologyEventsMetrics()
                jsonStr.append(metricsSwUp)

            time.sleep(10)

            main.log.info('Stopping all Tshark processes')
            main.ONOSbench.tsharkStop()

            time.sleep(5)

            '''
            main.log.info('Copying over tshark files')
            os.system('scp ' + ONOSUser + '@' + main.ONOSIp[0] +
                    ':' + tsharkTcpOutput + ' /tmp/')
            os.system('scp ' + ONOSUser + '@' + main.ONOSIp[0] +
                    ':' + tsharkRoleOutput + ' /tmp/')
            os.system('scp ' + ONOSUser + '@' + main.ONOSIp[0] +
                    ':' + tsharkFeatureOutput + ' /tmp/')
            os.system('scp ' + ONOSUser + '@' +
                      main.ONOSIp[0] + ':' + tsharkOfOutput + ' /tmp/')
            '''

            # Get tcp syn / ack output
            time.sleep(1)

            tcpFile = open(tsharkTcpOutput, 'r')
            tempText = tcpFile.readline()
            tempText = tempText.split(' ')
            main.log.info('Object read in from TCP capture: ' + str(tempText))

            if len(tempText) > 1:
                t0Tcp = float(tempText[1]) * 1000.0
            else:
                main.log.error('Tshark output file for TCP' + ' returned unexpected results')
                t0Tcp = 0
                assertion = main.FALSE
            tcpFile.close()

            # Get Role reply output
            ofFile = open(tsharkOfOutput, 'r')
            lineOfp = ''
            while True:
                tempText = ofFile.readline()
                if tempText != '':
                    lineOfp = tempText
                else:
                    break
            obj = lineOfp.split(' ')
            main.log.info('Object read in from OFP capture: ' +
                    str(lineOfp))
            if len(obj) > 1:
                t0Ofp = float(obj[1]) * 1000.0
            else:
                main.log.error('Tshark output file for OFP' +
                        ' returned unexpected results')
                t0Ofp = 0
                assertion = main.FALSE
            ofFile.close()

            # Get role request output
            roleFile = open(tsharkRoleOutput, 'r')
            tempText = roleFile.readline()
            tempText = tempText.split(' ')
            if len(tempText) > 1:
                main.log.info('Object read in from role request capture:' +
                        str(tempText))
                roleTimestamp = float(tempText[1]) * 1000.0
            else:
                main.log.error('Tshark output file for role request' +
                        ' returned unexpected results')
                timeRoleRequest = 0
                assertion = main.FALSE
            roleFile.close()

            # Get feature reply output
            featureFile = open(tsharkFeatureOutput, 'r')
            tempText = featureFile.readline()
            tempText = tempText.split(' ')
            if len(tempText) > 1:
                main.log.info('Object read in from feature reply capture: '+
                        str(tempText))
                if tempText[1] != ' ' and float(tempText[1]) > 1400000000.0:
                    temp = tempText[1]
                elif tempText[2] != ' ' and float(tempText[2]) > 1400000000.0:
                    temp = tempText[2]
                else:
                    temp = 0
                featureTimestamp = float(temp) * 1000.0
            else:
                main.log.error('Tshark output file for feature reply' +
                        ' returned unexpected results')
                timeFeatureReply = 0
                assertion = main.FALSE
            featureFile.close()

            for node in range(0, clusterCount):
                nodeNum = node+1
                #metricsSwUp = CLIs[node].topologyEventsMetrics
                #jsonStr = metricsSwUp()
                jsonObj = json.loads(jsonStr[node])
                if jsonObj:
                    graphTimestamp = jsonObj[graphTimestampKey]['value']
                    deviceTimestamp = jsonObj[deviceTimestampKey]['value']
                else:
                    main.log.error( "Unexpected JSON object" )
                    # If we could not obtain the JSON object,
                    # set the timestamps to 0, which will be
                    # excluded from the measurement later on
                    # (realized as invalid)
                    graphTimestamp = 0
                    deviceTimestamp = 0

                endToEnd = int(graphTimestamp) - int(t0Tcp)

                # Below are measurement breakdowns of the end-to-end
                # measurement.
                tcpToFeature = int(featureTimestamp) - int(t0Tcp)
                featureToRole = int(roleTimestamp) - int(featureTimestamp)
                roleToOfp = float(t0Ofp) - float(roleTimestamp)
                ofpToDevice = float(deviceTimestamp) - float(t0Ofp)
                # Timestamps gathered from ONOS are millisecond
                # precision. They are returned as integers, thus no
                # need to be more precise than 'int'. However,
                # the processing seems to be mostly under 1 ms,
                # thus this may be a problem point to handle any
                # submillisecond output that we are unsure of.
                # For now, this will be treated as 0 ms if less than 1 ms
                deviceToGraph = int(graphTimestamp) - int(deviceTimestamp)

                if endToEnd >= thresholdMin and\
                   endToEnd < thresholdMax and i >= iterIgnore:
                    endToEndLatNodeIter[node][i] = endToEnd
                    main.log.info("ONOS "+str(nodeNum)+ " end-to-end: "+
                            str(endToEnd) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+ " end-to-end "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(endToEnd))

                if tcpToFeature >= thresholdMin and\
                   tcpToFeature < thresholdMax and i >= iterIgnore:
                    tcpToFeatureLatNodeIter[node][i] = tcpToFeature
                    main.log.info("ONOS "+str(nodeNum)+ " tcp-to-feature: "+
                            str(tcpToFeature) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+ " tcp-to-feature "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(tcpToFeature))

                if featureToRole >= thresholdMin and\
                   featureToRole < thresholdMax and i >= iterIgnore:
                    featureToRoleRequestLatNodeIter[node][i] = featureToRole
                    main.log.info("ONOS "+str(nodeNum)+ " feature-to-role: "+
                            str(featureToRole) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+ " feature-to-role "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(featureToRole))

                if roleToOfp >= thresholdMin and\
                   roleToOfp < thresholdMax and i >= iterIgnore:
                    roleRequestToRoleReplyLatNodeIter[node][i] = roleToOfp
                    main.log.info("ONOS "+str(nodeNum)+ " role-to-reply: "+
                            str(roleToOfp) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+ " role-to-reply "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(roleToOfp))

                if ofpToDevice >= thresholdMin and\
                   ofpToDevice < thresholdMax and i >= iterIgnore:
                    roleReplyToDeviceLatNodeIter[node][i] = ofpToDevice
                    main.log.info("ONOS "+str(nodeNum)+ " reply-to-device: "+
                            str(ofpToDevice) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+ " reply-to-device "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(ofpToDevice))

                if deviceToGraph >= thresholdMin and\
                   deviceToGraph < thresholdMax and i >= iterIgnore:
                    deviceToGraphLatNodeIter[node][i] = deviceToGraph
                    main.log.info("ONOS "+str(nodeNum)+ " device-to-graph: "+
                            str(deviceToGraph) + " ms")
                else:
                    if deviceToGraph == 0:
                        deviceToGraphLatNodeIter[node][i] = 0
                        main.log.info("ONOS "+str(nodeNum) +
                            " device-to-graph measurement "+
                            "was set to 0 ms because of precision "+
                            "uncertainty. ")
                    else:
                        main.log.info("ONOS "+str(nodeNum)+
                            " device-to-graph "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                        main.log.info(str(deviceToGraph))

            # ********************
            time.sleep(5)

            # Get device id to remove
            deviceIdJsonStr = main.ONOS1cli.devices()

            main.log.info( "Device obj obtained: " + str(deviceIdJsonStr) )
            deviceId = json.loads(deviceIdJsonStr)

            deviceList = []
            for device in deviceId:
                deviceList.append(device['id'])

            # Measure switch down metrics
            # TCP FIN/ACK -> TCP FIN
            # TCP FIN -> Device Event
            # Device Event -> Graph Event
            # Capture switch down FIN / ACK packets

            # The -A 1 grep option allows us to grab 1 extra line after the
            # last tshark output grepped originally
            main.ONOSbench.tsharkGrep( tsharkFinAckSequence, tsharkFinAckOutput,
                    grepOptions = '-A 1' )

            time.sleep( 5 )

            removeJsonList = []
            main.step('Remove switch from controller')
            main.Mininet1.deleteSwController('s3')
            firstDevice = deviceList[0]

            time.sleep( 5 )

            # We need to get metrics before removing
            # device from the store below.
            for node in range(0, clusterCount):
                metricsSwDown = CLIs[node].topologyEventsMetrics
                jsonStr = metricsSwDown()
                removeJsonList.append( json.loads(jsonStr) )

            main.ONOSbench.tsharkStop()

            main.log.info( "Removing device " +str(firstDevice)+
                    " from ONOS" )

            #if deviceId:
            main.ONOS1cli.deviceRemove(firstDevice)

            #main.log.info('Copying over tshark files')
            #os.system('scp ' + ONOSUser + '@' + main.ONOSIp[0] + ':' + tsharkFinAckOutput + ' /tmp/')

            time.sleep( 10 )
            finAckOutputList = []
            with open(tsharkFinAckOutput, 'r') as f:
                tempLine = f.readlines()
                main.log.info('Object read in from FinAck capture: ' +
                    "\n".join(tempLine))

                index = 1
                for line in tempLine:
                    obj = line.split(' ')

                    # There are at least 3 objects in field (valid
                    # tshark output is lengthy)
                    if len(obj) > 2:
                        # If first index of object is like an epoch time
                        if obj[1] != ' ' and float(obj[1]) > 1400000000.0:
                            temp = obj[1]
                        elif obj[2] != ' 'and float(obj[2]) > 1400000000.0:
                            temp = obj[2]
                        elif obj[3] != ' 'and float(obj[3]) > 1400000000.0:
                            temp = obj[3]
                        else:
                            temp = 0
                        if index == 1:
                            tFinAck = float(temp) * 1000.0
                            main.log.info("DEBUG-- tFinAck: " + str(tFinAck))
                        elif index == 3:
                            tAck = float(temp) * 1000.0
                            main.log.info("DEBUG-- tAck: " + str(tAck))
                        else:
                            tAck = 0
                    else:
                        main.log.error('Tshark output file for OFP' +
                            ' returned unexpected results')
                        tFinAck = 0
                        tAck = 0
                        assertion = main.FALSE

                    index += 1
                main.log.info("DEBUG-- tFinAck: " + str(tFinAck))
                main.log.info("DEBUG-- tAck: " + str(tAck))

            # with open() as f takes care of closing file

            time.sleep(5)

            for node in range(0, clusterCount):
                nodeNum = node+1
                jsonObj = removeJsonList[node]
                if jsonObj:
                    graphTimestamp = jsonObj[graphTimestampKey]['value']
                    deviceTimestamp = jsonObj[deviceTimestampKey]['value']
                    main.log.info("Graph timestamp: "+str(graphTimestamp))
                    main.log.info("Device timestamp: "+str(deviceTimestamp))
                else:
                    main.log.error( "Unexpected JSON object" )
                    # If we could not obtain the JSON object,
                    # set the timestamps to 0, which will be
                    # excluded from the measurement later on
                    # (realized as invalid)
                    graphTimestamp = 0
                    deviceTimestamp = 0

                finAckTransaction = float(tAck) - float(tFinAck)
                ackToDevice = float(deviceTimestamp) - float(tAck)
                deviceToGraph = float(graphTimestamp) - float(deviceTimestamp)
                endToEndDisc = int(graphTimestamp) - int(tFinAck)
                main.log.info("DEBUG-- endToEndDisc = graphTimestamp - tFinAck  == (" + str(graphTimestamp) + "-" + str(tFinAck) + ")") 

                if endToEndDisc >= thresholdMin and\
                   endToEndDisc < thresholdMax and i >= iterIgnore:
                    endToEndDiscLatNodeIter[node][i] = endToEndDisc
                    main.log.info("ONOS "+str(nodeNum) +
                            "end-to-end disconnection: "+
                            str(endToEndDisc) + " ms" )
                else:
                    main.log.info("ONOS " + str(nodeNum) +
                            " end-to-end disconnection "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(endToEndDisc))

                if finAckTransaction >= thresholdMin and\
                   finAckTransaction < thresholdMax and i >= iterIgnore:
                    finAckTransactionLatNodeIter[node][i] = finAckTransaction
                    main.log.info("ONOS "+str(nodeNum)+
                            " fin/ack transaction: "+
                            str(finAckTransaction) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+
                            " fin/ack transaction "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(finAckTransaction))

                if ackToDevice >= thresholdMin and\
                   ackToDevice < thresholdMax and i >= iterIgnore:
                    ackToDeviceLatNodeIter[node][i] = ackToDevice
                    main.log.info("ONOS "+str(nodeNum)+
                            " ack-to-device: "+
                            str(ackToDevice) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+
                            " ack-to-device "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(ackToDevice))

                if deviceToGraph >= thresholdMin and\
                   deviceToGraph < thresholdMax and i >= iterIgnore:
                    deviceToGraphDiscLatNodeIter[node][i] = deviceToGraph
                    main.log.info("ONOS "+str(nodeNum)+
                            " device-to-graph disconnect: "+
                            str(deviceToGraph) + " ms")
                else:
                    main.log.info("ONOS "+str(nodeNum)+
                            " device-to-graph disconnect "+
                            "measurement ignored due to excess in "+
                            "threshold or premature iteration: ")
                    main.log.info(str(deviceToGraph))

        endToEndAvg = 0
        ofpToGraphAvg = 0
        dbCmdList = []
        for node in range(0, clusterCount):
            # List of latency for each node
            endToEndList = []
            tcpToFeatureList = []
            featureToRoleList = []
            roleToOfpList = []
            ofpToDeviceList = []
            deviceToGraphList = []

            finAckTransactionList = []
            ackToDeviceList = []
            deviceToGraphDiscList = []
            endToEndDiscList = []

            # LatNodeIter 2d arrays contain all iteration latency
            # for each node of the current scale cluster size
            # Switch connection measurements
            # Set further acceptance criteria for measurements
            # here if you would like to filter reporting results
            for item in endToEndLatNodeIter[node]:
                if item > 0.0:
                    endToEndList.append(item)

            for item in tcpToFeatureLatNodeIter[node]:
                if item > 0.0:
                    tcpToFeatureList.append(item)

            for item in featureToRoleRequestLatNodeIter[node]:
                if item > 0.0:
                    featureToRoleList.append(item)

            for item in roleRequestToRoleReplyLatNodeIter[node]:
                if item > 0.0:
                    roleToOfpList.append(item)

            for item in roleReplyToDeviceLatNodeIter[node]:
                if item >= 0.0:
                    ofpToDeviceList.append(item)

            for item in featureToRoleRequestLatNodeIter[node]:
                if item > 0.0:
                    featureToRoleList.append(item)

            for item in deviceToGraphLatNodeIter[node]:
                if item >= 0.0:
                    deviceToGraphList.append(item)

            # Switch disconnect measurements
            for item in endToEndDiscLatNodeIter[node]:
                if item > 0.0:
                    endToEndDiscList.append(item)

            for item in finAckTransactionLatNodeIter[node]:
                if item > 0.0:
                    finAckTransactionList.append(item)

            for item in ackToDeviceLatNodeIter[node]:
                if item > 0.0:
                    ackToDeviceList.append(item)

            for item in deviceToGraphDiscLatNodeIter[node]:
                if item >= 0.0:
                    deviceToGraphDiscList.append(item)

            endToEndAvg = round(numpy.mean(endToEndList), 2)
            endToEndStdDev = round(numpy.std(endToEndList), 2)
            main.log.info("endToEndList: " + str(endToEndList))

            tcpToFeatureAvg = round(numpy.mean(tcpToFeatureList), 2)
            tcpToFeatureStdDev = round(numpy.std(tcpToFeatureList), 2)
            main.log.info("tcpToFeatureList: " + str(tcpToFeatureList))

            featureToRoleAvg = round(numpy.mean(featureToRoleList), 2)
            featureToRoleStdDev = round(numpy.std(featureToRoleList), 2)
            main.log.info("featureToRoleList: " + str(featureToRoleList)) 

            roleToOfpAvg = round(numpy.mean(roleToOfpList), 2)
            roleToOfpStdDev = round(numpy.std(roleToOfpList), 2)
            main.log.info("roleToOfList: " + str(roleToOfpList))

            ofpToDeviceAvg = round(numpy.mean(ofpToDeviceList), 2)
            ofpToDeviceStdDev = round(numpy.std(ofpToDeviceList), 2)
            main.log.info("ofpToDeviceList: " + str(ofpToDeviceList))

            deviceToGraphAvg = round(numpy.mean(deviceToGraphList), 2)
            deviceToGraphStdDev = round(numpy.std(deviceToGraphList), 2)
            main.log.info("deviceToGraphList: " + str(deviceToGraphList))

            endToEndDiscAvg = round(numpy.mean(endToEndDiscList), 2)
            endToEndDiscStdDev = round(numpy.std(endToEndDiscList), 2)
            main.log.info("endToEndDiscList: " + str(endToEndDiscList))

            finAckAvg = round(numpy.mean(finAckTransactionList), 2)
            finAckStdDev = round(numpy.std(finAckTransactionList), 2)
            main.log.info("finAckTransactionList: " + str(finAckTransactionList))

            ackToDeviceAvg = round(numpy.mean(ackToDeviceList), 2)
            ackToDeviceStdDev = round(numpy.std(ackToDeviceList), 2)
            main.log.info("ackToDeviceList: " + str(ackToDeviceList))

            deviceToGraphDiscAvg = round(numpy.mean(deviceToGraphDiscList), 2)
            deviceToGraphDiscStdDev = round(numpy.std(deviceToGraphDiscList), 2)
            main.log.info("deviceToGraphDiscList: " + str(deviceToGraphDiscList))

            main.log.report(' - Node ' + str(node + 1) + ' Summary - ')
            main.log.report(' - Switch Connection Statistics - ')

            main.log.report(' End-to-end Avg: ' + str(endToEndAvg) +
                    ' ms' + ' End-to-end Std dev: ' +
                    str(endToEndStdDev) + ' ms')

            main.log.report(' Tcp-to-feature-reply Avg: ' +
                    str(tcpToFeatureAvg) + ' ms')
            main.log.report(' Tcp-to-feature-reply Std dev: '+
                    str(tcpToFeatureStdDev) + ' ms')

            main.log.report(' Feature-reply-to-role-request Avg: ' +
                    str(featureToRoleAvg) + ' ms')
            main.log.report(' Feature-reply-to-role-request Std Dev: ' +
                    str(featureToRoleStdDev) + ' ms')

            main.log.report(' Role-request-to-role-reply Avg: ' +
                    str(roleToOfpAvg) +' ms')
            main.log.report(' Role-request-to-role-reply Std dev: ' +
                    str(roleToOfpStdDev) + ' ms')

            main.log.report(' Role-reply-to-device Avg: ' +
                    str(ofpToDeviceAvg) +' ms')
            main.log.report(' Role-reply-to-device Std dev: ' +
                    str(ofpToDeviceStdDev) + ' ms')

            main.log.report(' Device-to-graph Avg: ' +
                    str(deviceToGraphAvg) + ' ms')
            main.log.report( 'Device-to-graph Std dev: ' +
                    str(deviceToGraphStdDev) + ' ms')

            main.log.report(' - Switch Disconnection Statistics - ')
            main.log.report(' End-to-end switch disconnect Avg: ' +
                    str(endToEndDiscAvg) + ' ms')
            main.log.report(' End-to-end switch disconnect Std dev: ' +
                    str(endToEndDiscStdDev) + ' ms')
            main.log.report(' Fin/Ack-to-Ack Avg: ' + str(finAckAvg) + ' ms')
            main.log.report(' Fin/Ack-to-Ack Std dev: ' +
                    str(finAckStdDev) + ' ms')

            main.log.report(' Ack-to-device Avg: ' + str(ackToDeviceAvg) +
                    ' ms')
            main.log.report(' Ack-to-device Std dev: ' + str(ackToDeviceStdDev) +
                    ' ms')

            main.log.report(' Device-to-graph (disconnect) Avg: ' +
                    str(deviceToGraphDiscAvg) + ' ms')
            main.log.report(' Device-to-graph (disconnect) Std dev: ' +
                    str(deviceToGraphDiscStdDev) + ' ms')

            # For database schema, refer to Amazon web services
            dbCmdList.append(
                    "'" + timeToPost + "','switch_latency_results'," +
                    jenkinsBuildNumber + ',' + str(clusterCount) + ",'baremetal" +
                    str(node + 1) + "'," +
                    str(endToEndAvg) + ',' +
                    str(tcpToFeatureAvg) + ',' +
                    str(featureToRoleAvg) + ',' +
                    str(roleToOfpAvg) + ',' +
                    str(ofpToDeviceAvg) + ',' +
                    str(deviceToGraphAvg) + ',' +
                    str(endToEndDiscAvg) + ',' +
                    str(finAckAvg) + ',' +
                    str(ackToDeviceAvg) + ',' +
                    str(deviceToGraphDiscAvg))

        if debugMode == 'on':
            main.ONOSbench.cpLogsToDir('/opt/onos/log/karaf.log',
                    '/tmp/', copyFileName='sw_lat_karaf')
        fResult = open(resultPath, 'a')
        for line in dbCmdList:
            if line:
                fResult.write(line + '\n')
                main.log.report(line)
        fResult.close()

        assertion = main.TRUE

        utilities.assert_equals(expect=main.TRUE, actual=assertion,
                onpass='Switch latency test successful',
                onfail='Switch latency test failed')

        main.Mininet1.stopNet()