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 __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 == u"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.
    if self.__config.isBullseyeCoverageEnabled():
      timeout = timeout * 4.
 
    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')
    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
    for testCaseNode in testCaseInfosTestCases:
      if cancelled:
        testCaseInfos.remove(testCaseNode)
        self.updateTestProgress(finishedTestCase=testCaseNode)
        continue
      try:
        testCaseAgenda = self.__buildTestCaseAgenda(testCaseNode)
        if testCaseAgenda != None:
 
            testCaseInfoNodes = testCaseAgenda.findall('TestCase')
            assert(len(testCaseInfoNodes) == 1)
            testCaseInfoNode = testCaseInfoNodes[0]
 
            testCaseInfos.remove(testCaseNode)
            testCaseInfos.append(testCaseInfoNode)
 
            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)
 
                preferredRendererNode = testCaseInfoNode.find('preferredRenderer')
                preferredRenderer = "" if preferredRendererNode is None else preferredRendererNode.text.lower()
                forceSoftwareRendering = (preferredRenderer == "software")
                if preferredRenderer == "hardware" and Utils.isMesaForced():
                  self.__logger.warning('preferredRenderer settings "hardware" detected but use of software driver is enforced.')
 
                if not restartDisabled or forceSoftwareRendering:
                  shouldRestart = (restartCounter == 0)
                  if shouldRestart or forceSoftwareRendering:
                    self.__logger.info("Restart slave for test case %s::%s"  % (debugType, debugName))
                    if not self.__startSlave(forceSoftwareRendering=forceSoftwareRendering):
                      raise Exception('Failed to start slave.')
 
                    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_TIMEOUT))
              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
  # --------------------------------------------------------------------------------------------}}}-
# ----------------------------------------------------------------------------------------------}}}-