Master.py

Go to the documentation of this file.

#
# Copyright 2007, MeVis Medical Solutions AG
#
# The user may use this file in accordance with the license agreement provided with
# the Software or, alternatively, in accordance with the terms contained in a
# written agreement between the user and MeVis Medical Solutions AG.
#
# For further information use the contact form at https://www.mevislab.de/contact
#
 
 
 
# -- system imports ----------------------------------------------------------------------------{{{-
import copy
import datetime
import os
import re
import sys
import time
import logging
import traceback
import subprocess
import tempfile
import threading
 
from copy import deepcopy
 
import xml.etree.cElementTree as etree
 
try:
    import TestSupport
except:
    pass
 
# ----------------------------------------------------------------------------------------------}}}-
 
# -- local imports -----------------------------------------------------------------------------{{{-
from . import Config
from . import IPC
from . import Utils
 
from .LogHandler import LogHandler
 
if sys.version_info.major >= 3:
    unicode = str
 
# ----------------------------------------------------------------------------------------------}}}-
 
 
class TestCaseTimer:
    def __init__(self, seconds):
        self.start = time.monotonic()
        self.availableSeconds = seconds
 
    def extendTimeout(self, seconds):
        self.availableSeconds += seconds
 
    def getSecondsRemaining(self):
        passedSeconds = time.monotonic() - self.start
        return self.availableSeconds - passedSeconds
 
    def isExpired(self):
        return self.getSecondsRemaining() <= 0.0
 
 
# ----------------------------------------------------------------------------------------------}}}-
 
 
class SlaveProcess:
    nextSlaveId = 0
 
    def __init__(self, config, logfileDir, env, isInsideTestCaseManager):
        self.__id = SlaveProcess.nextSlaveId
        SlaveProcess.nextSlaveId += 1
        self.__wasKilled = False
        self.__hasStarted = False
        self.__logFileFD = None
        self.__logFile = None
        self.__slaveLogFile = None
        self.__logger = logging.getLogger("TestCenter")
        self.__workDir = os.path.join(config.getResultDir(), "work")
 
        cmd = self.__getCommandLine(config, logfileDir, isInsideTestCaseManager)
        if cmd:
            self.__startProcess(cmd, config, env)
 
    def hasStarted(self):
        return self.__hasStarted
 
    def __getCommandLine(self, config, logfileDir, isInsideTestCaseManager):
        try:
            cmd = config.getMLABTestCenterCommand(macroName="TestCenter")
            if cmd:
                self.__slaveLogFile = os.path.join(logfileDir, f"slaveLogfile_{self.getID()}.log")
                cmd.insert(1, "-logfile")
                cmd.insert(2, self.__slaveLogFile)
                if isInsideTestCaseManager:
                    cmd.append("--started-from-test-case-manager")
        except Config.MLABExecutableNotFoundException:
            cmd = None
 
        if not cmd:
            self.__logger.error(
                "Failed to start slave as no MeVisLab executable was found. "
                + "Please verify your configuration (see TestCase Manager's "
                + "Configuration tab or check the file %s)!" % config.getConfigFilePath()
            )
        return cmd
 
    def __startProcess(self, cmd, _, env):
        self.__logFileFD, self.__logFile = tempfile.mkstemp()
        self.__logger.debug("Starting slave with command line %s" % " ".join(cmd))
        try:
            preexec_fn = os.setpgrp if Utils.isUnix else None
            self.__process = subprocess.Popen(
                cmd,
                cwd=self.__workDir,
                preexec_fn=preexec_fn,
                env=env,
                stdin=subprocess.PIPE,
                stdout=self.__logFileFD,
                stderr=self.__logFileFD,
            )
            self.__hasStarted = True
        except OSError:
            self.__logger.error("Failed to start slave (%s)\n%s" % (cmd, traceback.format_exc()))
 
    def getID(self):
        return self.__id
 
    def getPID(self):
        return self.__process.pid
 
    def isRunning(self):
        return self.getExitCode() is None
 
    def getExitCode(self):
        return self.__process.poll()
 
    def kill(self):
        self.__wasKilled = Utils.kill(self.__process)
        return self.__wasKilled
 
    def wasKilled(self):
        return self.__wasKilled
 
    def __printLogsAfterError(self):
        try:
            output = ""
            if self.__slaveLogFile is not None and os.path.exists(self.__slaveLogFile):
                with open(self.__slaveLogFile, "r", errors="replace") as fh:
                    output = fh.read()
            if os.path.exists(self.__logFile):
                with open(self.__logFile, "r", errors="replace") as fh:
                    output += fh.read()
            if not output:
                output = "none"
            self.logErrorWithPID("Slave output: %s" % output)
        except IOError as e:
            self.logErrorWithPID(f"Could not read log file: {e}")
 
    def finish(self, printLog):
        try:
            os.fsync(self.__logFileFD)
            os.close(self.__logFileFD)
        except IOError as e:
            self.logErrorWithPID("Could not close log file: %s" % str(e))
        if printLog:
            self.__printLogsAfterError()
        if os.path.exists(self.__logFile):
            try:
                Utils.removeFile(self.__logFile)
            except IOError as e:
                self.logErrorWithPID("Could not remove log file: %s" % str(e))
        else:
            self.logMessageWithPID("Log file does not exist: %s" % self.__logFile)
 
    def logMessageWithPID(self, message):
        return "%s (PID: %s)" % (message, str(self.getPID()))
 
    def logDebugWithPID(self, message):
        self.__logger.debug(self.logMessageWithPID(message))
 
    def logErrorWithPID(self, message):
        self.__logger.error(self.logMessageWithPID(message))
 
 
class ProgressTestCase:
    def __init__(self, name, status, errorCount, warningCount, duration):
        self.duration = duration
        self.name = name
        self.status = status
        self.errorCount = errorCount
        self.warningCount = warningCount
 
 
class TestProgress:
    def __init__(self):
        self.activeTestCase = None
        self.finishedTestCases = []
        self.testCaseCount = 0
 
    def reset(self, testCaseCount):
        self.activeTestCase = None
        self.finishedTestCases = []
        self.testCaseCount = testCaseCount
 
 
# -- Class Master ------------------------------------------------------------------------------{{{-
 
class Master:
    # -- member variables ------------------------------------------------------------------------{{{-
    
    __config = None
    
    __com = None
 
    # Slave instance to use if offline testing is used.
    __slave = None
    
    __slaveProc = None
 
    
    __hangingSlaves = []
 
    # The configuration of the current test run.
    __testCfg = None
    
    __xmlRoot = None
 
    
    __logger = None
 
    
    __testCasesToIgnoreList = []
 
    
    __stackTraceFile = None
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __init__ ----------------------------------------------------------------------------{{{-
    
    def __init__(self, cfgFile=None, verbose=False, slave=None, slaveEnvironment=None, isInsideTestCaseManager=False):
        self.__logger = logging.getLogger("TestCenter")
 
        self.__config = Config.Configuration(cfgFile)
 
        self.__com = (
            None if slave is not None else IPC.ComMaster(connectTimeout=self.__config.getIPCConnectionTimeout())
        )
        self.__slave = slave
        self.__slaveEnvironment = slaveEnvironment
 
        self.__testProgress = TestProgress()
        self.__shouldStop = False
        self.__lock = threading.Lock()
 
        self.__testCaseListener = None
 
        self.__testedPkgList = []
 
        # Clean up existing result directory or create it.
        resultDir = self.__config.getResultDir()
        imgDir = os.path.join(resultDir, "images")
        fileDir = os.path.join(resultDir, "files")
        workDir = os.path.join(resultDir, "work")
        self.logfileDir = os.path.join(resultDir, "logfiles")
 
        if not os.path.exists(resultDir):
            os.makedirs(resultDir)
        # Clean up old file directory.
        Utils.rmtree(fileDir)
        os.makedirs(fileDir)
        # Clean up old image directory.
        Utils.rmtree(imgDir)
        os.makedirs(imgDir)
        # Clean up old work directory.
        Utils.rmtree(workDir)
        os.makedirs(workDir)
        # Clean up old logfile directory.
        Utils.rmtree(self.logfileDir)
        os.makedirs(self.logfileDir)
 
        if Utils.isLinux and "NO_MEVISLAB_DEBUGGER" not in os.environ:
            self.__stackTraceFile = os.path.join(self.logfileDir, "lastCrashStackTrace.txt")
            self.__slaveEnvironment = Utils.setStackTraceFile(self.__slaveEnvironment, self.__stackTraceFile)
 
        self.__isInsideTestCaseManager = isInsideTestCaseManager
 
        self.__testCfg = self.__testConfigSkeleton()
 
        self.__updateProgressFunc = None
 
        # If not running offline start a second MeVisLab instance.
        if self.__slave is None:
            if not self.__startSlave():
                raise Exception("Failed to start slave")
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def onExit(self):
        for slaveProc in self.__hangingSlaves:
            slaveProc.finish(printLog=True)
            if not slaveProc.kill():
                self.__logger.error("Finally killing process %s failed." % slaveProc.getPID())
        self.__hangingSlaves.clear()
 
    def __enter__(self):
        return self
 
    def __exit__(self, *_):
        self.onExit()
 
    def __del__(self):
        self.onExit()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def stop(self):
        self.__lock.acquire()
        self.__shouldStop = True
        self.__lock.release()
 
    def shouldStop(self):
        self.__lock.acquire()
        result = self.__shouldStop
        self.__lock.release()
        return result
 
    def getTestProgress(self):
        self.__lock.acquire()
        result = copy.deepcopy(self.__testProgress)
        self.__lock.release()
        return result
 
    def resetTestProgress(self, testCaseCount):
        self.__lock.acquire()
        self.__testProgress.reset(testCaseCount)
        self.__lock.release()
 
    def updateTestProgress(self, finishedTestCase=None, additionalTestCaseCount=None):
        progressTestCase = None
        if finishedTestCase is not None:
            errorCount = 0
            warningCount = 0
            for function in finishedTestCase.findall("Function"):
                status = int(function.get("status", str(Utils.TEST_STATUS_DISABLED)))
                if status in (
                    Utils.TEST_STATUS_ERROR,
                    Utils.TEST_STATUS_CRASHED,
                    Utils.TEST_STATUS_FUNCTION_NOT_FOUND,
                    Utils.TEST_STATUS_TIMEOUT,
                ):
                    errorCount += 1
                elif status == Utils.TEST_STATUS_WARNING:
                    warningCount += 1
            progressTestCase = ProgressTestCase(
                finishedTestCase.get("name"),
                int(finishedTestCase.get("status", str(Utils.TEST_STATUS_CANCELLED))),
                errorCount,
                warningCount,
                float(finishedTestCase.get("duration", "0")),
            )
 
        self.__lock.acquire()
        if progressTestCase is not None:
            self.__testProgress.finishedTestCases.append(progressTestCase)
        if additionalTestCaseCount is not None:
            self.__testProgress.testCaseCount += additionalTestCaseCount
        self.__lock.release()
 
    def setUpdateProgressFunc(self, updateProgressFunc):
        self.__updateProgressFunc = updateProgressFunc
 
    def setActiveTestCase(self, testCase):
        self.__lock.acquire()
        self.__testProgress.activeTestCase = testCase
        self.__lock.release()
 
    # -- def __testConfigSkeleton() --------------------------------------------------------------{{{-
    
    def __testConfigSkeleton(self):
        return etree.fromstring(
            """
      <Configuration>
        <TestGroups />
        <TestCases />
        <TestSuites />
        <Modules />
        <Packages>
          <Tested />
          <Available />
          <Ignored />
        </Packages>
        <TestOptions />
      </Configuration>"""
        )
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def setTestCaseListener(self, listener):
        self.__testCaseListener = listener
 
    # -- def setTestCases ------------------------------------------------------------------------{{{-
    
    def setTestCases(self, testCaseList):
        assert self.__xmlRoot == None
 
        xmlNode = self.__testCfg.find("TestCases")
        for testCaseName in testCaseList:
            etree.SubElement(xmlNode, "TestCase", name=testCaseName)
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def setIgnoreTestCases ------------------------------------------------------------------------{{{-
    
    def setTestCasesToIgnore(self, testCaseToIgnoreList):
        self.__testCasesToIgnoreList__testCasesToIgnoreList = testCaseToIgnoreList
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def setTestGroups -----------------------------------------------------------------------{{{-
    
    def setTestGroups(self, testGroupList):
        assert self.__xmlRoot == None
 
        xmlNode = self.__testCfg.find("TestGroups")
        for testGroupName in testGroupList:
            etree.SubElement(xmlNode, "TestGroup", name=testGroupName)
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def setTestSuites(self, testSuiteList):
        assert self.__xmlRoot == None
 
        xmlNode = self.__testCfg.find("TestSuites")
        for testSuiteName in testSuiteList:
            etree.SubElement(xmlNode, "TestSuite", name=testSuiteName)
 
    # -- def setModules --------------------------------------------------------------------------{{{-
    
    def setModules(self, moduleList=[], filterList=[]):
        assert self.__xmlRoot == None
 
        xmlNode = self.__testCfg.find("Modules")
        for moduleName in moduleList:
            etree.SubElement(xmlNode, "Module", name=moduleName)
        for filter in filterList:
            etree.SubElement(xmlNode, "Filter").text = filter
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def setPackages -------------------------------------------------------------------------{{{-
    
    def setPackages(self, testedPkgList=[], availablePkgList=[], ignoredPkgList=[]):
        assert self.__xmlRoot == None
 
        self.__testedPkgList = testedPkgList
 
        xmlNode = self.__testCfg.find("Packages/Tested")
        for packageID in testedPkgList:
            etree.SubElement(xmlNode, "Package", name=packageID)
 
        xmlNode = self.__testCfg.find("Packages/Available")
        for packageID in availablePkgList:
            etree.SubElement(xmlNode, "Package", name=packageID)
 
        xmlNode = self.__testCfg.find("Packages/Ignored")
        for packageID in ignoredPkgList:
            etree.SubElement(xmlNode, "Package", name=packageID)
 
    # --------------------------------------------------------------------------------------------}}}-
 
 
    def __sortNodes(self, nodes):
        nodeList = []
        testAgendas = {}
        for testCaseNode in nodes:
            testCaseAgenda = self.__buildTestCaseAgenda(testCaseNode)
            testAgendas[testCaseNode] = testCaseAgenda
        for prefRendererSetting in ["", "hardware", "software"]:
            for testCaseNode in nodes:
                testCaseAgenda = testAgendas[testCaseNode]
                testCaseInfoNodes = testCaseAgenda.findall("TestCase")
                testCaseInfoNode = testCaseInfoNodes[0]
                preferredRendererNode = testCaseInfoNode.find("preferredRenderer")
                if preferredRendererNode is None and prefRendererSetting == "" or preferredRendererNode is not None and preferredRendererNode.text.lower() == prefRendererSetting:
                    nodeList.append(testCaseNode)
        assert len(nodes) == len(nodeList)
        return nodeList, testAgendas
 
 
    def __testTypeAndName(self, xmlNode):
        # Just print anything if we are in verbose mode.
        testType = xmlNode.get("type")
        testName = (
            xmlNode.get("name")
            if testType == "FunctionalTestCase"
            else "%s::%s" % (xmlNode.get("name"), xmlNode.get("module"))
        )
 
        return testType, testName
 
    # -- def __statusMessage ---------------------------------------------------------------------{{{-
    
    def __statusMessage(self, xmlNode, status):
        assert type(status) == int
        assert xmlNode.tag == "TestCase"
 
        statusStr = Utils.getStatusString(status)
        testType, testName = self.__testTypeAndName(xmlNode)
        fillIn = "." * (80 - len(testType + testName + statusStr) - 2)
        msg = "%s::%s%s%s" % (testType, testName, fillIn, statusStr)
        if status == Utils.TEST_STATUS_OK or status == Utils.TEST_STATUS_DO_NOT_TEST_MODULE:
            self.__logger.debug(msg)
        elif status == Utils.TEST_STATUS_WARNING:
            self.__logger.warning(msg)
        else:
            self.__logger.error(msg)
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __testFailed ------------------------------------------------------------------------{{{-
    
    def __testFailed(self, xmlNode, comError):
        assert xmlNode.tag == "TestCase"
 
        testType = xmlNode.get("type")
        if testType == "GenericTestCase":
            testName = "%s::%s" % (xmlNode.get("name"), xmlNode.get("module"))
        else:
            testName = xmlNode.get("name")
 
        # Build a mapping from function names to result nodes.
        funcDict = {}
        for funcNode in xmlNode.findall("Function"):
            funcDict.setdefault(funcNode.get("name"), funcNode)
 
        # With the previously gathered error status the reason can be determined.
        status = Utils.TEST_STATUS_ERROR
        if comError in (IPC.Error.EMPTY_MESSAGE, IPC.Error.ON_RECEIVING_2):
            status = Utils.TEST_STATUS_CRASHED
        elif comError == IPC.Error.ON_RECEIVING_TIMEOUT:
            status = Utils.TEST_STATUS_TIMEOUT
 
        stackTraceMsg = None
        if self.__stackTraceFile and os.path.exists(self.__stackTraceFile):
            with open(self.__stackTraceFile, encoding="utf8", errors="surrogateescape") as f:
                stacktrace = f.read().splitlines()
                # filter out information lines about encountered threads (which there are a lot of):
                new_lwp_re = re.compile(r"\[New LWP \d+\]", flags=re.IGNORECASE)
                stacktrace = [x for x in stacktrace if not new_lwp_re.fullmatch(x)]
                # remove the stack frames from the signal handler itself:
                lastSignalHandlerFrame = -1
                for i in range(len(stacktrace)):
                    if "/mlabLinuxSignalHandler.cpp:" in stacktrace[i]:
                        lastSignalHandlerFrame = i
                        # the last one counts, therefore no break here
                if lastSignalHandlerFrame != -1:
                    stacktrace = stacktrace[lastSignalHandlerFrame + 1 :]
                if stacktrace:
                    stackTraceMsg = "MeVisLab crashed with the following stacktrace:\n" + "\n".join(stacktrace)
            os.unlink(self.__stackTraceFile)
 
        # Read the slave's logfile and parse it to get as much results as possible.
        logHandler = LogHandler(self.__config.getSlaveLogFilePath())
        logHandler.parseLogFile(testType, testName, status, funcDict, stackTraceMsg=stackTraceMsg)
 
        return status
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __buildTestAgenda -------------------------------------------------------------------{{{-
    
    def __buildTestAgenda(self):
        resultNode = self.__sendRequest("BuildTestAgenda", self.__testCfg)
        if resultNode.get("errorCode") != "Ok":
            self.__logger.critical(
                "Error (%s) in generating the test agenda!\n%s"
                % (resultNode.get("errorCode"), resultNode.find("Error").text)
            )
            return False
        self.__xmlRoot = resultNode.find("TestRun")
        self.__testCfg = self.__verifyConfiguration(resultNode.find("Configuration"))
 
        # Set package list as testing is started afterwards.
        self.__sendRequest("SetPackageList", self.__testCfg.find("Packages"), 5, restart=True)
        return True
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __buildTestCaseAgenda -------------------------------------------------------------------{{{-
    def __buildTestCaseAgenda(self, testCaseNode):
        parameterNode = etree.Element("Parameters")
        genericTestCase = True  # is it possible to determine the testcase type here?
        if genericTestCase:
            moduleList = []
            for module in self.__xmlRoot.findall("Information/Modules/Module"):
                moduleList.append(module.attrib["name"])
            parameterNode.attrib["modules"] = ",".join(moduleList)
            if len(self.__testedPkgList) > 0:
                parameterNode.attrib["packages"] = ",".join(self.__testedPkgList)
            else:
                # test every package
                parameterNode.attrib["packages"] = "*/*"
        parameterNode.append(testCaseNode)
        resultNode = self.__sendRequest("BuildTestCaseAgenda", parameterNode, restart=True)
        if resultNode.get("errorCode") != "Ok":
            self.__logger.critical(
                "Error (%s) in generating the test case agenda!\n%s"
                % (resultNode.get("errorCode"), resultNode.find("Error").text)
            )
            return None
 
        return resultNode
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __verifyConfiguration ---------------------------------------------------------------{{{-
    
    def __verifyConfiguration(self, testCfg):
        # Verify package settings.
        packageRoot = testCfg.find("Packages")
 
        tPkgNode = packageRoot.find("Tested")
        for packageNode in tPkgNode.findall("Package"):
            if packageNode.get("status") not in ("Ok", "Added", "Substituted"):
                self.__logger.error(
                    "Failed to verify package (%s with status '%s')!"
                    % (packageNode.get("name"), packageNode.get("status"))
                )
 
        aPkgNode = packageRoot.find("Available")
        for packageNode in aPkgNode.findall("Package"):
            if packageNode.get("status") not in ("Ok", "Added", "Substituted"):
                self.__logger.error(
                    "Failed to verify package (%s with status '%s')!"
                    % (packageNode.get("name"), packageNode.get("status"))
                )
            else:
                if packageNode.get("status") not in ("Substituted"):
                    packageRoot.append(packageNode)
 
        packageRoot.remove(tPkgNode)
        packageRoot.remove(aPkgNode)
 
        iPkgNode = packageRoot.find("Ignored")
        packageRoot.remove(iPkgNode)
 
        # Verify the module settings.
        for moduleNode in testCfg.findall("Modules/Module"):
            isModuleFiltered = moduleNode.get("isModuleFiltered") == str(True)
            if not isModuleFiltered and moduleNode.get("status") != str(Utils.TEST_STATUS_OK):
                self.__logger.error(
                    "Failed to verify module (%s with status '%s')" % (moduleNode.get("name"), moduleNode.get("status"))
                )
        testCfg.find("Modules").clear()
 
        # Verify the test case settings.
        for testCaseNode in testCfg.findall("TestCases/TestCase"):
            isNotInTestGroups = testCaseNode.get("isNotInTestGroups") == str(True)
            if not isNotInTestGroups and testCaseNode.get("status") != str(Utils.TEST_STATUS_OK):
                self.__logger.error(
                    "Failed to verify test case (%s with status '%s')"
                    % (testCaseNode.get("name"), testCaseNode.get("status"))
                )
        testCfg.find("TestCases").clear()
 
        return testCfg
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def __createTimeoutTooHighErrorFunction(self, testCaseInfoNode, testResultNode, timeout):
        functionName = "TEST001_VerifyTestCaseTimeout"
        testFunctions = testCaseInfoNode.find("TestFunctions")
        testFunction = etree.SubElement(testFunctions, "Function")
        testFunction.attrib = {"basename": "VerifyTestCaseTimeout", "is_disabled": "False", "name": functionName}
        etree.SubElement(testFunction, "Documentation").text = "Verifies if the TestCase timeout."
        timeoutTooHighTestFunction = etree.SubElement(testResultNode, "Function")
        timeoutTooHighTestFunction.attrib = {
            "duration": "0",
            "name": functionName,
            "status": "2",
            "is_disabled": "False",
            "try": "1",
        }
        events = etree.SubElement(timeoutTooHighTestFunction, "Events")
        filename = testCaseInfoNode.find("File").text
        line = testCaseInfoNode.find("Line").text
        event = etree.SubElement(events, "Event")
        event.attrib = {
            "file": filename,
            "internal": "true",
            "line": line,
            "origin": "",
            "type": "Error",
            "timestamp": datetime.datetime.now().strftime("%Y-%m-%d %H:%M:%S"),
        }
        error = "The TestCase timeout (%ss) exceeds the maximum allowed timeout (%ss)" % (
            timeout,
            self.__config.getMaxTestTimeoutSeconds(),
        )
        etree.SubElement(event, "Message").text = error
 
    def __buildListOfTestFunctionsToExecute(self, testCaseInfoNode, testCaseNode, funcList=None):
        # Build up list of test functions that must be executed.
        testFuncList = []
        for funcNode in testCaseInfoNode.findall(".//Function"):
            funcName = funcNode.get("name")
            # If user selected to process only specific functions ignore the rest.
            if funcList and funcName not in funcList and not funcName in Utils.VIRTUAL_TEST_CASE_FUNCTIONS:
                continue
 
            isDisabled = funcNode.get("is_disabled", str(False)) == str(True)
            if testCaseInfoNode.get("name") in self.__testCasesToIgnoreList__testCasesToIgnoreList:
                isDisabled = True
            if isDisabled and funcList:
                # If a user selected the function, then it should be executed
                isDisabled = False
                funcNode.set("is_disabled", str(False))
            funcResultNode = etree.SubElement(testCaseNode, "Function", name=funcName, is_disabled=str(isDisabled))
            testFuncList.append(funcName)
        return testFuncList
 
    # -- def __doTest ----------------------------------------------------------------------------{{{-
    
 
    def __doTest(self, testCaseInfoNode, testResultNode, funcList=None):
        assert testResultNode.tag == "TestCase"
 
        testCaseNode = deepcopy(testResultNode)
 
        # Build up list of test functions that must be executed.
        testFuncList = self.__buildListOfTestFunctionsToExecute(testCaseInfoNode, testCaseNode, funcList)
 
        testCaseName = testCaseInfoNode.get("name")
        if self.__testCaseListener:
            self.__testCaseListener.startTestCase(testCaseName, testFuncList)
 
        # Gather time till timeout.
        hasValidTimeout = True
        timeout = int(testCaseInfoNode.get("timeout"))
        if timeout == 0:
            timeout = self.__config.getDefaultTestTimeoutSeconds()
        if self.__config.getMaxTestTimeoutSeconds():
            if timeout > self.__config.getMaxTestTimeoutSeconds():
                self.__createTimeoutTooHighErrorFunction(testCaseInfoNode, testResultNode, timeout)
                hasValidTimeout = False
 
        # Use a bigger timeout if coverage or bullseye are enabled
        if self.__config.isPythonCoverageEnabled():
            timeout = timeout * 4.0
        if self.__config.isBullseyeCoverageEnabled():
            timeout = timeout * 4.0
 
        if hasValidTimeout:
            retries, status = self.__executeTestFunctions(
                testCaseInfoNode, testResultNode, testCaseNode, testFuncList, timeout
            )
        else:
            retries = 0
            status = Utils.TEST_STATUS_ERROR
 
        # Set status and number of retries for the given test case.
        testResultNode.set("status", unicode(status))
        testResultNode.set("retries", unicode(retries))
        # Print status message.
        self.__statusMessage(testResultNode, status)
        if self.__testCaseListener:
            self.__testCaseListener.endTestCase()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def transferNodeFromExecutionToResultXML(self, nodeName, executionNode, testResultNode):
        coverageFile = executionNode.get(nodeName)
        if executionNode.get(nodeName) is not None:
            testResultNode.set(nodeName, coverageFile)
 
    def __executeTestFunctions(self, testCaseInfoNode, testResultNode, testCaseNode, testFuncList, timeout):
        if testCaseNode.get("status") == str(Utils.TEST_STATUS_DO_NOT_TEST_MODULE):
            return 0, Utils.TEST_STATUS_DO_NOT_TEST_MODULE
 
        retries = 0
        failedFuncList = []
        timer = TestCaseTimer(timeout)
 
        status = Utils.TEST_STATUS_OK
        maxFuncStatus = Utils.TEST_STATUS_OK
        cancelled = False
        while testFuncList and not timer.isExpired() and not cancelled:
            # If not set status to timeout and stop execution of remaining test functions.
 
            if self.shouldStop():
                cancelled = True
                status = Utils.TEST_STATUS_CANCELLED
                break
 
            # if we have a test case listener, we request progress calls from the slave:
            if self.__testCaseListener:
                testCaseNode.set("requestProgress", "1")
 
            testCaseNode.set(
                "maxErrorMessagesPerTestFunction", str(self.__config.getReportOptions().maxErrorMessagesPerTestFunction)
            )
            testCaseNode.set(
                "maxInfoMessagesPerTestFunction", str(self.__config.getReportOptions().maxInfoMessagesPerTestFunction)
            )
 
            # Initiate the processing of the remaining test functions.
            executionNode = self.__sendRequest("DoTest", testCaseNode, timeout=timer, tries=1)
            if executionNode.get("errorCode") != "Ok":
                self.__logger.debug("Restarting due to error in test execution.\n%s" % executionNode.find("Error").text)
 
                # Try to determine what was the reason for the test to fail.
                comError = self.__com.getLastError() if self.__com else 0
 
                # Delete slave process.
                self.stopSlave()
 
                # Handle logfile to get gathered results.
                status = self.__testFailed(testCaseNode, comError)
                # Restart slave.
                if not self.__startSlave():
                    self.__logger.debug("Failed to re-start slave.")
            else:
                testCaseNode = executionNode.find("TestCase")
 
                self.transferNodeFromExecutionToResultXML("pythonCoverage", executionNode, testResultNode)
                self.transferNodeFromExecutionToResultXML("bullseyeCoverage", executionNode, testResultNode)
 
            extraTestCasesResults = testCaseNode.find("ExtraTestCasesResults")
            if extraTestCasesResults != None:
                testResultNode.append(deepcopy(extraTestCasesResults))
 
            # functions to test.
            for funcResultNode in testCaseNode.findall("Function"):
                funcName = funcResultNode.get("name")
 
                # If status is not set, the function has not been executed yet.
                funcStatus = funcResultNode.get("status")
                if not funcStatus:
                    # Function not processed yet.
                    continue
                else:
                    funcStatus = int(funcStatus)
                    if maxFuncStatus < funcStatus:
                        maxFuncStatus = funcStatus
 
                if funcName not in failedFuncList:
                    funcResultNode.set("try", "1")
 
                    if funcStatus in (Utils.TEST_STATUS_CRASHED, Utils.TEST_STATUS_TIMEOUT):
                        failedFuncList.append(funcName)
                        retries += 1
                        # Create copy of node as it will be overwritten in the next iteration.
                        testResultNode.append(deepcopy(funcResultNode))
                        funcResultNode.remove(funcResultNode.find("Events"))
                else:
                    funcResultNode.set("try", "2")
                    failedFuncList.remove(funcName)
 
                # Remove all processed but not failed for the first time functions from
                # the temporary node.
                if funcName not in failedFuncList:
                    testFuncList.remove(funcName)
                    # Move the processed function to the result node.
                    testResultNode.append(funcResultNode)
                    testCaseNode.remove(funcResultNode)
                if funcStatus == Utils.TEST_STATUS_CANCELLED or funcStatus == Utils.TEST_STATUS_FUNCTION_NOT_FOUND:
                    cancelled = True
                    break
 
        if timer.isExpired():
            status = Utils.TEST_STATUS_TIMEOUT
 
        # The status variable is used for status > 2 to handle situations where:
        #  - all test functions worked but the slave crashed or timed out.
        #  - the test case timed out but had crashes, too (global status should be
        #    timeout).
        # Otherwise the maximum function status found in the reports is used.
        status = status if status > Utils.TEST_STATUS_ERROR else maxFuncStatus
        return retries, status
 
    # -- def __handleExtraTestCaseResults --------------------------------------------------------{{{-
    
    def __handleExtraTestCaseResults(self, testCaseInfos, resultNode, testResultNode):
        node = testResultNode.find("ExtraTestCasesResults")
        if node != None:
            testResultNode.remove(node)
            for node in node.findall("ExtraTestCaseResult"):
                testCaseInfos.append(node.find("Information/TestCase"))
                extraTestCaseResult = node.find("Result/TestCase")
                extraTestCaseResult.set("slave_id", testResultNode.get("slave_id"))
                resultNode.append(extraTestCaseResult)
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def shouldMeasurePythonCoverageGlobally -------------------------------------------------{{{-
    def shouldMeasurePythonCoverageGlobally(self):
        return self.__config.isPythonCoverageEnabled() and self.__config.isGlobalPythonCoverageEnabled()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def run ---------------------------------------------------------------------------------{{{-
    
    def run(self, funcDict=None, stopSlaveAfterTestRun=True):
        if not self.__buildTestAgenda():
            self.__logger.error("Failed to build test agenda.")
            return None
 
        # Start the timer.
        timeStarted = time.time()
 
        testCaseInfos = self.__xmlRoot.find("Information/TestCases")
 
        # Fetch counters which control after what number of testCases MLAB
        # should be restarted.
        freshCounterValue = self.__config.getRestartInterval()
        restartCounter = freshCounterValue
        restartDisabled = restartCounter == 0
 
        testCaseInfosTestCases = testCaseInfos.findall("TestCase")
        testCaseInfosTestCases, testAgendas = self.__sortNodes(testCaseInfosTestCases)
            
        if self.__testCaseListener:
            testNames = []
            for node in testCaseInfosTestCases:
                testNames.append(node.get("name"))
            self.__testCaseListener.startTestRun(testNames)
 
        self.resetTestProgress(len(testCaseInfosTestCases))
 
        failedTestCases = 0
        finishedTestCases = 0
        totalTestCases = len(testCaseInfosTestCases)
 
        resultNode = self.__xmlRoot.find("Results")
        cancelled = False
        previousRenderer = ""
        for testCaseNode in testCaseInfosTestCases:
            if cancelled:
                testCaseInfos.remove(testCaseNode)
                self.updateTestProgress(finishedTestCase=testCaseNode)
                continue
            try:
                testCaseAgenda = testAgendas[testCaseNode]
                if testCaseAgenda != None:
 
                    testCaseInfoNodes = testCaseAgenda.findall("TestCase")
                    assert len(testCaseInfoNodes) == 1
                    
                    testCaseInfoNode = testCaseInfoNodes[0]
                    
                    testCaseInfos.remove(testCaseNode)
                    testCaseInfos.append(testCaseInfoNode)
 
                    preferredRendererNode = testCaseInfoNode.find("preferredRenderer")
                    preferredRenderer = (
                        "" if preferredRendererNode is None else preferredRendererNode.text.lower()
                    )
                    if preferredRenderer == "hardware" and Utils.isMesaForced():
                        self.__logger.warning(
                            'preferredRenderer settings "hardware" detected but use of software driver is enforced.'
                        )
                    restartNeeded = previousRenderer != preferredRenderer and (preferredRenderer == "software" or previousRenderer == "software")
                    previousRenderer = preferredRenderer
                    
                    testResultNodes = testCaseAgenda.find("Results").findall("TestCase")
                    if len(testResultNodes) > 1:
                        self.updateTestProgress(additionalTestCaseCount=len(testResultNodes) - 1)
                        totalTestCases += len(testResultNodes) - 1
                    for testResultNode in testResultNodes:
                        if cancelled:
                            break
                        try:
                            testCaseName = testCaseInfoNode.get("name")
                            debugType, debugName = self.__testTypeAndName(testResultNode)
 
                            if not restartDisabled or restartNeeded:
                                shouldRestart = restartCounter == 0
                                if shouldRestart or restartNeeded:
                                    self.__logger.info("Restart slave for test case %s::%s" % (debugType, debugName))
                                    if not self.__startSlave(forceSoftwareRendering=(preferredRenderer == "software")):
                                        resultNode.append(testResultNode)
                                        raise Exception("Failed to start slave.")
                                    
                                    restartNeeded = False
                                    restartCounter = freshCounterValue
 
                                # decrement counter on each pass
                                restartCounter -= 1
 
                            self.setActiveTestCase(testCaseName)
 
                            if self.__updateProgressFunc is not None:
                                self.__updateProgressFunc(
                                    testCaseName, failedTestCases, finishedTestCases, totalTestCases
                                )
 
                            timeFunctionStarted = time.time()
                            funcList = funcDict[testCaseName] if (funcDict and testCaseName in funcDict) else None
                            self.__doTest(testCaseInfoNode, testResultNode, funcList)
                            timeFunctionStopped = time.time()
                            if int(testResultNode.get("status")) == Utils.TEST_STATUS_CANCELLED:
                                cancelled = True
 
                            if int(testResultNode.get("status")) in (
                                Utils.TEST_STATUS_CRASHED,
                                Utils.TEST_STATUS_ERROR,
                                Utils.TEST_STATUS_FUNCTION_NOT_FOUND,
                                Utils.TEST_STATUS_TIMEOUT,
                            ):
                                failedTestCases += 1
                            finishedTestCases += 1
 
                            testResultNode.set("duration", str(timeFunctionStopped - timeFunctionStarted))
 
                            testResultNode.set("slave_id", "0" if self.__slave else str(self.__slaveProc.getID()))
 
                            resultNode.append(testResultNode)
 
                            self.__handleExtraTestCaseResults(testCaseInfos, resultNode, testResultNode)
 
                        except Exception as e:
                            traceback.print_exc()
                            self.__logger.error("Error executing test case %s::%s\n%s" % (debugType, debugName, e))
                            testResultNode.set("status", unicode(Utils.TEST_STATUS_ERROR))
                        self.updateTestProgress(finishedTestCase=testResultNode)
                else:
                    self.__logger.error(
                        "Failed to build the test agenda for test case %s." % testCaseNode.get("name", "unknown")
                    )
            except Exception as e:
                self.__logger.error("Error executing test case %s" % e)
 
        if self.shouldMeasurePythonCoverageGlobally():
            resultNode.set("combinePythonCoverage", "True")
 
        # Stop the timer.
        timeStopped = time.time()
 
        self.__xmlRoot.set("timestamp", str(timeStarted))
        self.__xmlRoot.set("duration", str(timeStopped - timeStarted))
 
        if stopSlaveAfterTestRun:
            self.stopSlave()
 
        xml = Utils.saveXMLTree(self.__xmlRoot, self.__config.getResultFile())
 
        if self.__testCaseListener:
            self.__testCaseListener.endTestRun()
 
        return xml
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def reset() -----------------------------------------------------------------------------{{{-
    
    def reset(self):
        self.__xmlRoot = None
        self.__testCfg = self.__testConfigSkeleton()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def getConfig() -------------------------------------------------------------------------{{{-
    def getConfig(self):
        return self.__config
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __isSlaveRunning -------------------------------------------------------------------------{{{-
    
    def __isSlaveRunning(self):
        return self.__slaveProc and self.__slaveProc.isRunning()
 
    def __isSlaveStopped(self):
        return not self.__isSlaveRunning()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def logMessageWithPID(self, message):
        pidString = str(self.__slaveProc.getPID()) if self.__slaveProc is not None else str(None)
 
        return "%s (PID: %s)" % (message, pidString)
 
    def logDebugWithPID(self, message):
        self.__logger.debug(self.logMessageWithPID(message))
 
    def logErrorWithPID(self, message):
        self.__logger.error(self.logMessageWithPID(message))
 
    def logMessageWithLastError(self, message):
        errorCode, errorMessage = self.__com.getLastErrorWithMessage()
        return "%s ([%d] %s)" % (message, errorCode, errorMessage)
 
    # -- def __startSlave ------------------------------------------------------------------------{{{-
    
    def __startSlave(self, forceSoftwareRendering=False):
        if self.__slave:
            return True
 
        if self.__isSlaveRunning():
            if not self.stopSlave():
                self.__logger.error("Failed to stop the slave before restart.")
 
        env = Utils.setForceMesa(self.__slaveEnvironment) if forceSoftwareRendering else self.__slaveEnvironment
        if self.__com:
            # server port is given through environment variable
            env = Utils.setTestCenterPort(env, self.__com.getPort())
        slaveProc = SlaveProcess(self.__config, self.logfileDir, env, self.__isInsideTestCaseManager)
        if slaveProc.hasStarted():
            self.__slaveProc = slaveProc
        else:
            return False
 
        return self.__connectToSlave()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    def __connectToSlave(self):
        retries = 0
        timerSleep = 1
        maxTries = 15
        while retries < maxTries and not self.__com.connect(timeout=self.__config.getIPCConnectionTimeout()):
            retries += 1
            self.logDebugWithPID(self.logMessageWithLastError("Failed to connect to slave in %i. try" % retries))
 
            if not self.__slaveProc.isRunning():
                self.__logger.error("Slave died with exit code %s" % self.__slaveProc.getExitCode())
                self.__slaveProc.finish(printLog=True)
                return False
 
            # Use a sleep timer to give the slave process more time to start up.
            self.__logger.debug("Sleeping for %s seconds" % (timerSleep))
            time.sleep(timerSleep)
 
        if not self.__com.isConnected():
            # quit the mlab that we were not able to talk to
            self.logErrorWithPID("Failed to connect to slave within %d seconds." % (maxTries * timerSleep))
            if not self.stopSlave():
                self.__logger.error("Failed to stop the slave after connection error.")
                self.__slaveProc.finish(printLog=True)
            return False
        else:
            self.logDebugWithPID("Connected to slave in %s. try" % (retries + 1))
 
        # Send slave a list of packages that are available. On first run an empty
        # string is sent; in the __buildTestAgenda call this list will be
        # retrieved. Later the verified list of tests will be sent.
        if self.__xmlRoot:
            resultNode = self.__sendRequest("SetPackageList", self.__testCfg.find("Packages"), 5)
            return resultNode.get("errorCode") == "Ok"
 
        return True
 
    # -- def stopSlave ---------------------------------------------------------------------------{{{-
    # # Stop the slave process.
    #  If the slave is running this method tries to stop the slave. This method
    #  will run until the slave has stopped. After 3 tries on unix a KILL signal
    #  is sent.
    #  @return True if the slave was stopped.
    def stopSlave(self):
        if self.__slave:
            # ugly special condition for when a running MeVisLab instance is used
            # as slave.
            return True
 
        self.logDebugWithPID("Shutting down slave")
 
        if not self.__isSlaveStopped():
            # try soft shutdown first by requesting clean quit
            xmlNode = self.__sendRequest("Quit", timeout=1, tries=1)
 
            if xmlNode.get("errorCode") == "Ok":
                self.logDebugWithPID("Response received, waiting for shutdown")
                # wait up to five seconds for the slave to stop:
                i = 0
                while not self.__isSlaveStopped() and i < 10:
                    time.sleep(0.5)
                    i += 1
 
            # kindly asking for shutdown was obviously not enough, enforce shutdown
            if not self.__isSlaveStopped():
                self.logDebugWithPID("No response, killing slave")
                self.__slaveProc.kill()
 
        if self.__isSlaveStopped():
            self.__slaveProc.finish(printLog=self.__slaveProc.wasKilled())
        else:
            self.logErrorWithPID("Failed to kill slave!")
            self.__hangingSlaves.append(self.__slaveProc)
        self.__slaveProc = None
 
        return self.__isSlaveStopped()
 
    # --------------------------------------------------------------------------------------------}}}-
 
    # -- def __sendRequest -----------------------------------------------------------------------{{{-
    
    def __sendRequest(self, command, parameterNode=None, timeout=None, tries=2, restart=False):
        trial = 0
 
        requestNode = etree.Element("Command", type=command)
        requestNode.append(parameterNode if parameterNode != None else etree.Element("Dummy"))
 
        if self.__slave:
            self.logDebugWithPID("Handling '%s' request" % command)
            resultNode = self.__slave.runCommand(requestNode)
        else:
            self.logDebugWithPID("Sending '%s' request to slave" % command)
            resultNode = None
            # The default timeout is taken from the configuration file.
            if not timeout:
                timeout = self.__config.getDefaultTestTimeoutSeconds()
 
            string = None
            while not string and (trial < tries):
                timer = timeout if isinstance(timeout, TestCaseTimer) else TestCaseTimer(timeout)
                if self.__com.send(etree.tostring(requestNode), timer.getSecondsRemaining()):
                    # since we allow receiving intermediate "Progress" result values,
                    # we loop until we receive something that is not a "Progress" message:
                    while not string and not timer.isExpired():
                        string = self.__com.recv(timer.getSecondsRemaining())
                        if string:
                            recvNode = Utils.filterXMLString(string)
                            self.logDebugWithPID("Received node of type '%s'" % recvNode.tag)
                            if recvNode.tag == "Progress":
                                shouldStop = False
                                if self.__testCaseListener:
                                    try:
                                        self.__testCaseListener.startTestCaseFunction(
                                            recvNode.get("testType"),
                                            recvNode.get("testCase"),
                                            recvNode.get("testFunction"),
                                        )
                                    except TestSupport.TestHelper.CancelTestException:
                                        shouldStop = True
                                # tell slave if it should stop or go on:
                                self.__com.send("0" if shouldStop else "1", 5)
                                string = None
                            elif recvNode.tag == "Status":
                                if self.__testCaseListener:
                                    self.__testCaseListener.endTestCaseFunction(int(recvNode.get("status")), 0)
                                string = None
                            else:
                                resultNode = recvNode
                        else:
                            if self.__stackTraceFile and os.path.exists(self.__stackTraceFile):
                                self.__logger.warning(
                                    "It seems the test client is crashing. Collecting the stacktrace may take some while."
                                )
                                # Add additional grace period to timer
                                timer.extendTimeout(300)
                                # wait for slave process to stop
                                while not self.__isSlaveStopped() and not timer.isExpired():
                                    time.sleep(0.5)
                            break
 
                if not string:
                    trial += 1
 
                    if restart and (trial < tries):
                        self.__logger.info("Restarting due to communication error ...")
                        self.__startSlave()
 
            if resultNode == None:
                self.logDebugWithPID("Error: Received no result from slave.")
                resultNode = etree.Element("Result", errorCode="CommunicationError")
                etree.SubElement(resultNode, "Error").text = (
                    "Communication error [%d]: %s" % self.__com.getLastErrorWithMessage()
                )
        self.logDebugWithPID("Result error code: %s" % resultNode.get("errorCode"))
        content = etree.tostring(resultNode).decode()
        self.logDebugWithPID("Result content: %s%s" % (content[:150], " [...]" if len(content) > 150 else ""))
        return resultNode
 
    # --------------------------------------------------------------------------------------------}}}-
 
 
# ----------------------------------------------------------------------------------------------}}}-