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 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.startstart = time.time()
    self.availableSecondsavailableSeconds = seconds
 
  def getSecondsRemaining(self):
    passedSeconds = time.time() - self.startstart
    return self.availableSecondsavailableSeconds - passedSeconds
 
  def isExpired(self):
    return self.getSecondsRemaininggetSecondsRemaining() <= 0.0
 
 
# ----------------------------------------------------------------------------------------------}}}-
  
class SlaveProcess:
  nextSlaveId = 0
 
  def __init__(self, config, logfileDir, env, isInsideTestCaseManager):
    self.__id__id = SlaveProcess.nextSlaveId
    SlaveProcess.nextSlaveId += 1
    self.__wasKilled__wasKilled = False
    self.__hasStarted__hasStarted = False
    self.__logFileFD__logFileFD = None
    self.__logFile__logFile = None
    self.__slaveLogFile__slaveLogFile = None
    self.__logger__logger = logging.getLogger("TestCenter")
    self.__workDir__workDir = os.path.join(config.getResultDir(), "work")
    
    cmd = self.__getCommandLine__getCommandLine(config, logfileDir, isInsideTestCaseManager)
    if cmd:
      self.__startProcess__startProcess(cmd, config, env)
    
  def hasStarted(self):
    return self.__hasStarted__hasStarted
  
  def __getCommandLine(self, config, logfileDir, isInsideTestCaseManager):
    try:
      cmd = config.getMLABTestCenterCommand(macroName="TestCenter")
      if cmd:
        self.__slaveLogFile__slaveLogFile = os.path.join(logfileDir, f"slaveLogfile_{self.getID()}.log")
        cmd.insert(1, '-logfile')
        cmd.insert(2, self.__slaveLogFile__slaveLogFile)
        if isInsideTestCaseManager:
          cmd.append('--started-from-test-case-manager')
    except Config.MLABExecutableNotFoundException:
      cmd = None
 
    if not cmd:
      self.__logger__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__logFileFD, self.__logFile__logFile = tempfile.mkstemp()
    self.__logger__logger.debug('Starting slave with command line %s' % ' '.join(cmd))
    try:
      preexec_fn = os.setpgrp if Utils.isUnix else None
      self.__process__process = subprocess.Popen(cmd, cwd=self.__workDir__workDir, preexec_fn=preexec_fn, env=env, 
                                        stdin=subprocess.PIPE,
                                        stdout=self.__logFileFD__logFileFD, stderr=self.__logFileFD__logFileFD)
      self.__hasStarted__hasStarted = True
    except OSError:
      self.__logger__logger.error("Failed to start slave (%s)\n%s" % (cmd, traceback.format_exc()))
 
  def getID(self):
    return self.__id__id
 
  def getPID(self):
    return self.__process__process.pid
  
  def isRunning(self):
    return self.getExitCodegetExitCode() is None
  
  def getExitCode(self):
    return self.__process__process.poll()
  
  def kill(self):
    self.__wasKilled__wasKilled = Utils.kill(self.__process__process)
    return self.__wasKilled__wasKilled
  
  def wasKilled(self):
    return self.__wasKilled__wasKilled
  
  def __printLogsAfterError(self):
    try:
      output = ''
      if self.__slaveLogFile__slaveLogFile is not None and os.path.exists(self.__slaveLogFile__slaveLogFile):
        with open(self.__slaveLogFile__slaveLogFile, 'r', errors="replace") as fh:
          output = fh.read()
      if os.path.exists(self.__logFile__logFile):
        with open(self.__logFile__logFile, 'r', errors="replace") as fh:
          output += fh.read()  
      if not output:
        output = 'none'
      self.logErrorWithPIDlogErrorWithPID('Slave output: %s' % output)
    except IOError as e:
      self.logErrorWithPIDlogErrorWithPID(f"Could not read log file: {e}")
  
  def finish(self, printLog):
    try:
      os.fsync(self.__logFileFD__logFileFD)
      os.close(self.__logFileFD__logFileFD)
    except IOError as e:
      self.logErrorWithPIDlogErrorWithPID("Could not close log file: %s" % str(e))
    if printLog:
      self.__printLogsAfterError__printLogsAfterError()
    if os.path.exists(self.__logFile__logFile):
      try:
        Utils.removeFile(self.__logFile__logFile)
      except IOError as e:
        self.logErrorWithPIDlogErrorWithPID("Could not remove log file: %s" % str(e))
    else:
      self.logMessageWithPIDlogMessageWithPID("Log file does not exist: %s" % self.__logFile__logFile)
        
  def logMessageWithPID(self, message):
    return "%s (PID: %s)" % (message, str(self.getPIDgetPID()))
 
  def logDebugWithPID(self, message):
    self.__logger__logger.debug(self.logMessageWithPIDlogMessageWithPID(message))
 
  def logErrorWithPID(self, message):
    self.__logger__logger.error(self.logMessageWithPIDlogMessageWithPID(message))
 
 
class ProgressTestCase(object):
  def __init__(self, name, status, errorCount, warningCount, duration):
    self.durationduration = duration
    self.namename = name
    self.statusstatus = status
    self.errorCounterrorCount = errorCount
    self.warningCountwarningCount = warningCount
 
 
class TestProgress(object):
  def __init__(self):
    self.activeTestCaseactiveTestCase = None
    self.finishedTestCasesfinishedTestCases = []
    self.testCaseCounttestCaseCount = 0
    
  def reset(self, testCaseCount):
    self.activeTestCaseactiveTestCase = None
    self.finishedTestCasesfinishedTestCases = []
    self.testCaseCounttestCaseCount = testCaseCount
    
 
# -- Class Master ------------------------------------------------------------------------------{{{-
 
class Master (object):
  # -- 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 = []
 
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def __init__ ----------------------------------------------------------------------------{{{-
  
  def __init__ (self, cfgFile=None, verbose=False, slave=None, slaveEnvironment=None, 
                isInsideTestCaseManager=False):
    self.__logger__logger       = logging.getLogger("TestCenter")
 
    self.__config__config       = Config.Configuration(cfgFile)
 
    self.__com__com          = None if slave is not None else IPC.ComMaster(connectTimeout=self.__config__config.getIPCConnectionTimeout())
    self.__slave__slave        = slave
    self.__slaveEnvironment__slaveEnvironment = slaveEnvironment
    
    self.__testProgress__testProgress = TestProgress()
    self.__shouldStop__shouldStop = False
    self.__lock__lock = threading.Lock()
 
    self.__testCaseListener__testCaseListener = None
 
    self.__testedPkgList__testedPkgList = []
 
    # Clean up existing result directory or create it.
    resultDir = self.__config__config.getResultDir()
    imgDir = os.path.join(resultDir, "images")
    fileDir = os.path.join(resultDir, "files")
    workDir = os.path.join(resultDir, "work")
    self.logfileDirlogfileDir = 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.logfileDirlogfileDir)
    os.makedirs(self.logfileDirlogfileDir)
    
    self.__isInsideTestCaseManager__isInsideTestCaseManager = isInsideTestCaseManager
 
    self.__testCfg__testCfg = self.__testConfigSkeleton__testConfigSkeleton()
    
    self.__updateProgressFunc__updateProgressFunc = None
 
    # If not running offline start a second MeVisLab instance.
    if self.__slave__slave is None:
        if not self.__startSlave__startSlave():
            raise Exception("Failed to start slave")
 
  # --------------------------------------------------------------------------------------------}}}-
 
  def onExit(self):
    for slaveProc in self.__hangingSlaves__hangingSlaves:
      slaveProc.finish(printLog=True)
      if not slaveProc.kill():
        self.__logger__logger.error("Finally killing process %s failed." % slaveProc.getPID())
    self.__hangingSlaves__hangingSlaves.clear()
 
  def __enter__(self):
    return self
 
  def __exit__(self, *_):
    self.onExitonExit()
 
  def __del__(self):
    self.onExitonExit()
 
  # --------------------------------------------------------------------------------------------}}}-
  
  def stop(self):
    self.__lock__lock.acquire()
    self.__shouldStop__shouldStop = True
    self.__lock__lock.release()
        
  def shouldStop(self):
    self.__lock__lock.acquire()
    result = self.__shouldStop__shouldStop
    self.__lock__lock.release()
    return result
  
  def getTestProgress(self):
    self.__lock__lock.acquire()
    result = copy.deepcopy(self.__testProgress__testProgress)
    self.__lock__lock.release()
    return result
    
  def resetTestProgress(self, testCaseCount):
    self.__lock__lock.acquire()
    self.__testProgress__testProgress.reset(testCaseCount)
    self.__lock__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__lock.acquire()
    if progressTestCase is not None:
      self.__testProgress__testProgress.finishedTestCases.append(progressTestCase)
    if additionalTestCaseCount is not None:
      self.__testProgress__testProgress.testCaseCount += additionalTestCaseCount
    self.__lock__lock.release()
    
  def setUpdateProgressFunc(self, updateProgressFunc):
    self.__updateProgressFunc__updateProgressFunc = updateProgressFunc
    
  def setActiveTestCase(self, testCase):
    self.__lock__lock.acquire()
    self.__testProgress__testProgress.activeTestCase = testCase
    self.__lock__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__testCaseListener = listener
 
  # -- def setTestCases ------------------------------------------------------------------------{{{-
  
  def setTestCases (self, testCaseList):
    assert self.__xmlRoot__xmlRoot == None
 
    xmlNode = self.__testCfg__testCfg.find("TestCases")
    for testCaseName in testCaseList:
      etree.SubElement(xmlNode, "TestCase", name=testCaseName)
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def setIgnoreTestCases ------------------------------------------------------------------------{{{-
  
  def setTestCasesToIgnore (self, testCaseToIgnoreList):
    self.__testCasesToIgnoreList__testCasesToIgnoreList__testCasesToIgnoreList = testCaseToIgnoreList
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def setTestGroups -----------------------------------------------------------------------{{{-
  
  def setTestGroups (self, testGroupList):
    assert self.__xmlRoot__xmlRoot == None
 
    xmlNode = self.__testCfg__testCfg.find("TestGroups")
    for testGroupName in testGroupList:
      etree.SubElement(xmlNode, "TestGroup", name=testGroupName)
  # --------------------------------------------------------------------------------------------}}}-
  
  def setTestSuites (self, testSuiteList):
    assert self.__xmlRoot__xmlRoot == None
 
    xmlNode = self.__testCfg__testCfg.find("TestSuites")
    for testSuiteName in testSuiteList:
      etree.SubElement(xmlNode, "TestSuite", name=testSuiteName)
    
 
  # -- def setModules --------------------------------------------------------------------------{{{-
  
  def setModules (self, moduleList=[], filterList=[]):
    assert self.__xmlRoot__xmlRoot == None
 
    xmlNode = self.__testCfg__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__xmlRoot == None
 
    self.__testedPkgList__testedPkgList = testedPkgList
 
    xmlNode = self.__testCfg__testCfg.find("Packages/Tested")
    for packageID in testedPkgList:
      etree.SubElement(xmlNode, "Package", name=packageID)
 
    xmlNode = self.__testCfg__testCfg.find("Packages/Available")
    for packageID in availablePkgList:
      etree.SubElement(xmlNode, "Package", name=packageID)
      
    xmlNode = self.__testCfg__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__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__logger.debug(msg)
    elif status == Utils.TEST_STATUS_WARNING:
      self.__logger__logger.warning(msg)
    else:
      self.__logger__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
 
    # Read the slave's logfile and parse it to get as much results as possible.
    logHandler = LogHandler(self.__config__config.getSlaveLogFilePath())
    logHandler.parseLogFile(testType, testName, status, funcDict)
 
    return status
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def __buildTestAgenda -------------------------------------------------------------------{{{-
  
  def __buildTestAgenda (self):
    resultNode = self.__sendRequest__sendRequest("BuildTestAgenda", self.__testCfg__testCfg)
    if resultNode.get('errorCode') != "Ok":
      self.__logger__logger.critical("Error (%s) in generating the test agenda!\n%s" % (resultNode.get('errorCode'), resultNode.find('Error').text))
      return False
    self.__xmlRoot__xmlRoot = resultNode.find('TestRun')
    self.__testCfg__testCfg = self.__verifyConfiguration__verifyConfiguration(resultNode.find('Configuration'))
 
    # Set package list as testing is started afterwards.
    self.__sendRequest__sendRequest('SetPackageList', self.__testCfg__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__xmlRoot.findall('Information/Modules/Module'):
            moduleList.append(module.attrib['name'])
        parameterNode.attrib['modules'] = ','.join(moduleList)
        if len(self.__testedPkgList__testedPkgList) > 0:
            parameterNode.attrib['packages'] = ','.join(self.__testedPkgList__testedPkgList)
        else:
            # test every package
            parameterNode.attrib['packages'] = '*/*'
    parameterNode.append(testCaseNode)
    resultNode = self.__sendRequest__sendRequest("BuildTestCaseAgenda", parameterNode, restart=True)
    if resultNode.get('errorCode') != "Ok":
      self.__logger__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__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__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__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__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__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__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__buildListOfTestFunctionsToExecute(testCaseInfoNode, testCaseNode, funcList)
 
    testCaseName = testCaseInfoNode.get('name')
    if self.__testCaseListener__testCaseListener:
      self.__testCaseListener__testCaseListener.startTestCase(testCaseName, testFuncList)
 
    # Gather time till timeout.
    hasValidTimeout = True
    timeout = int(testCaseInfoNode.get('timeout'))
    if timeout == 0:
      timeout = self.__config__config.getDefaultTestTimeoutSeconds()
    if self.__config__config.getMaxTestTimeoutSeconds():
      if timeout > self.__config__config.getMaxTestTimeoutSeconds():
        self.__createTimeoutTooHighErrorFunction__createTimeoutTooHighErrorFunction(testCaseInfoNode, testResultNode, timeout)
        hasValidTimeout = False
 
    # Use a bigger timeout if coverage or bullseye are enabled
    if self.__config__config.isPythonCoverageEnabled():
      timeout = timeout * 4.
    if self.__config__config.isBullseyeCoverageEnabled():
      timeout = timeout * 4.
 
    if hasValidTimeout:
      retries, status = self.__executeTestFunctions__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__statusMessage(testResultNode, status)
    if self.__testCaseListener__testCaseListener:
      self.__testCaseListener__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.shouldStopshouldStop():
        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__testCaseListener:
        testCaseNode.set("requestProgress", "1")
      
      testCaseNode.set("maxErrorMessagesPerTestFunction", str(self.__config__config.getReportOptions().maxErrorMessagesPerTestFunction))
      testCaseNode.set("maxInfoMessagesPerTestFunction", str(self.__config__config.getReportOptions().maxInfoMessagesPerTestFunction))
      
      # Initiate the processing of the remaining test functions.
      executionNode = self.__sendRequest__sendRequest("DoTest", testCaseNode, timeout=timer.getSecondsRemaining(), tries=1)
      if executionNode.get('errorCode') != "Ok":
        self.__logger__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__com.getLastError() if self.__com__com else 0
 
        # Delete slave process.
        self.stopSlavestopSlave()
 
        # Handle logfile to get gathered results.
        status = self.__testFailed__testFailed(testCaseNode, comError)
        # Restart slave.
        if not self.__startSlave__startSlave():
          self.__logger__logger.debug('Failed to re-start slave.')
      else:
        testCaseNode = executionNode.find('TestCase')
 
        self.transferNodeFromExecutionToResultXMLtransferNodeFromExecutionToResultXML('pythonCoverage', executionNode, testResultNode)
        self.transferNodeFromExecutionToResultXMLtransferNodeFromExecutionToResultXML('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__config.isPythonCoverageEnabled() and self.__config__config.isGlobalPythonCoverageEnabled()
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def run ---------------------------------------------------------------------------------{{{-
  
  def run(self, funcDict=None, stopSlaveAfterTestRun=True):
    if not self.__buildTestAgenda__buildTestAgenda():
      self.__logger__logger.error("Failed to build test agenda.")
      return None
 
    # Start the timer.
    timeStarted = time.time()
 
    testCaseInfos = self.__xmlRoot__xmlRoot.find('Information/TestCases')
 
    # Fetch counters which control after what number of testCases MLAB
    # should be restarted.
    freshCounterValue = self.__config__config.getRestartInterval()
    restartCounter    = freshCounterValue
    restartDisabled   = (restartCounter == 0)
 
    testCaseInfosTestCases = testCaseInfos.findall('TestCase')
    if self.__testCaseListener__testCaseListener:
      testNames = []
      for node in testCaseInfosTestCases:
        testNames.append(node.get('name'))
      self.__testCaseListener__testCaseListener.startTestRun(testNames)
 
    self.resetTestProgressresetTestProgress(len(testCaseInfosTestCases))
 
    failedTestCases = 0
    finishedTestCases = 0
    totalTestCases = len(testCaseInfosTestCases)
 
    resultNode = self.__xmlRoot__xmlRoot.find('Results')
    cancelled = False
    for testCaseNode in testCaseInfosTestCases:
      if cancelled:
        testCaseInfos.remove(testCaseNode)
        self.updateTestProgressupdateTestProgress(finishedTestCase=testCaseNode)
        continue
      try:
        testCaseAgenda = self.__buildTestCaseAgenda__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.updateTestProgressupdateTestProgress(additionalTestCaseCount=len(testResultNodes)-1)
              totalTestCases += len(testResultNodes)-1
            for testResultNode in testResultNodes:
              if cancelled:
                break
              try:
                testCaseName = testCaseInfoNode.get('name')
                debugType, debugName = self.__testTypeAndName__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__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__logger.info("Restart slave for test case %s::%s"  % (debugType, debugName))
                    if not self.__startSlave__startSlave(forceSoftwareRendering=forceSoftwareRendering):
                      raise Exception('Failed to start slave.')
 
                    restartCounter = freshCounterValue
 
                  #decrement counter on each pass
                  restartCounter -= 1
 
                self.setActiveTestCasesetActiveTestCase(testCaseName)
 
                if self.__updateProgressFunc__updateProgressFunc is not None:
                  self.__updateProgressFunc__updateProgressFunc(testCaseName, failedTestCases, finishedTestCases, totalTestCases)
                  
                timeFunctionStarted = time.time()
                funcList = funcDict[testCaseName] if (funcDict and testCaseName in funcDict) else None
                self.__doTest__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__slave else str(self.__slaveProc__slaveProc.getID()))
 
                resultNode.append(testResultNode)
 
                self.__handleExtraTestCaseResults__handleExtraTestCaseResults(testCaseInfos, resultNode, testResultNode)
 
              except Exception as e:
                traceback.print_exc()
                self.__logger__logger.error("Error executing test case %s::%s\n%s"  % (debugType, debugName, e))
                testResultNode.set("status", unicode(Utils.TEST_STATUS_TIMEOUT))
              self.updateTestProgressupdateTestProgress(finishedTestCase=testResultNode)
        else:
          self.__logger__logger.error("Failed to build the test agenda for test case %s." % testCaseNode.get('name', 'unknown'))
      except Exception as e:
        self.__logger__logger.error("Error executing test case %s" % e)
 
    if self.shouldMeasurePythonCoverageGloballyshouldMeasurePythonCoverageGlobally():
      resultNode.set("combinePythonCoverage", "True")
 
    # Stop the timer.
    timeStopped = time.time()
 
    self.__xmlRoot__xmlRoot.set('timestamp', str(timeStarted))
    self.__xmlRoot__xmlRoot.set('duration', str(timeStopped-timeStarted))
 
    if stopSlaveAfterTestRun:
      self.stopSlavestopSlave()
 
    xml = Utils.saveXMLTree(self.__xmlRoot__xmlRoot, self.__config__config.getResultFile())
 
    if self.__testCaseListener__testCaseListener:
      self.__testCaseListener__testCaseListener.endTestRun()
 
    return xml
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def reset() -----------------------------------------------------------------------------{{{-
  
  def reset(self):
    self.__xmlRoot__xmlRoot = None
    self.__testCfg__testCfg = self.__testConfigSkeleton__testConfigSkeleton()
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def getConfig() -------------------------------------------------------------------------{{{-
  def getConfig (self):
    return self.__config__config
  # --------------------------------------------------------------------------------------------}}}-
 
  # -- def __isSlaveRunning -------------------------------------------------------------------------{{{-
  
  def __isSlaveRunning (self):
    return self.__slaveProc__slaveProc and self.__slaveProc__slaveProc.isRunning()
 
  def __isSlaveStopped(self):
    return not self.__isSlaveRunning__isSlaveRunning()
  # --------------------------------------------------------------------------------------------}}}-
 
  def logMessageWithPID(self, message):
    pidString = str(self.__slaveProc__slaveProc.getPID()) if self.__slaveProc__slaveProc is not None else str(None)
 
    return "%s (PID: %s)" % (message, pidString)
 
  def logDebugWithPID(self, message):
    self.__logger__logger.debug(self.logMessageWithPIDlogMessageWithPID(message))
 
  def logErrorWithPID(self, message):
    self.__logger__logger.error(self.logMessageWithPIDlogMessageWithPID(message))
 
  def logMessageWithLastError(self, message):
    errorCode, errorMessage = self.__com__com.getLastErrorWithMessage()
    return "%s ([%d] %s)" % (message, errorCode, errorMessage)
 
  # -- def __startSlave ------------------------------------------------------------------------{{{-
  
  def __startSlave (self, forceSoftwareRendering=False):
    if self.__slave__slave:
      return True
 
    if self.__isSlaveRunning__isSlaveRunning():
      if not self.stopSlavestopSlave():
        self.__logger__logger.error("Failed to stop the slave before restart.")
 
    env = Utils.setForceMesa(self.__slaveEnvironment__slaveEnvironment) if forceSoftwareRendering else self.__slaveEnvironment__slaveEnvironment
    if self.__com__com:
      # server port is given through environment variable
      env = Utils.setTestCenterPort(env, self.__com__com.getPort())
    slaveProc = SlaveProcess(self.__config__config, self.logfileDirlogfileDir, env, self.__isInsideTestCaseManager__isInsideTestCaseManager)
    if slaveProc.hasStarted():
      self.__slaveProc__slaveProc = slaveProc
    else:
      return False
    
    return self.__connectToSlave__connectToSlave()
  # --------------------------------------------------------------------------------------------}}}-
    
  def __connectToSlave(self):
    retries = 0
    timerSleep = 1
    maxTries = 15
    while retries < maxTries and not self.__com__com.connect(timeout = self.__config__config.getIPCConnectionTimeout()):
      retries += 1
      self.logDebugWithPIDlogDebugWithPID(self.logMessageWithLastErrorlogMessageWithLastError("Failed to connect to slave in %i. try" % retries))
 
      if not self.__slaveProc__slaveProc.isRunning():
        self.__logger__logger.error("Slave died with exit code %s" % self.__slaveProc__slaveProc.getExitCode())
        self.__slaveProc__slaveProc.finish(printLog=True)
        return False
 
      # Use a sleep timer to give the slave process more time to start up.
      self.__logger__logger.debug("Sleeping for %s seconds" % (timerSleep))
      time.sleep(timerSleep)
 
    if not self.__com__com.isConnected():
      # quit the mlab that we were not able to talk to
      self.logErrorWithPIDlogErrorWithPID("Failed to connect to slave within %d seconds." % (maxTries*timerSleep))
      if not self.stopSlavestopSlave():
        self.__logger__logger.error("Failed to stop the slave after connection error.")
        self.__slaveProc__slaveProc.finish(printLog=True)
      return False
    else:
      self.logDebugWithPIDlogDebugWithPID("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__xmlRoot:
      resultNode = self.__sendRequest__sendRequest('SetPackageList', self.__testCfg__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__slave:
      #ugly special condition for when a running MeVisLab instance is used
      #as slave.
      return True
 
    self.logDebugWithPIDlogDebugWithPID("Shutting down slave")
 
    if not self.__isSlaveStopped__isSlaveStopped():
      #try soft shutdown first by requesting clean quit
      xmlNode = self.__sendRequest__sendRequest('Quit', timeout=1, tries=1)
 
      if xmlNode.get('errorCode') == 'Ok':
        self.logDebugWithPIDlogDebugWithPID("Response received, waiting for shutdown")
        # wait up to five seconds for the slave to stop:
        i = 0
        while not self.__isSlaveStopped__isSlaveStopped() and i < 10:
          time.sleep(0.5)
          i += 1
 
      #kindly asking for shutdown was obviously not enough, enforce shutdown
      if not self.__isSlaveStopped__isSlaveStopped():
        self.logDebugWithPIDlogDebugWithPID("No response, killing slave")
        self.__slaveProc__slaveProc.kill()
 
    if self.__isSlaveStopped__isSlaveStopped():
      self.__slaveProc__slaveProc.finish(printLog=self.__slaveProc__slaveProc.wasKilled())
    else:
      self.logErrorWithPIDlogErrorWithPID("Failed to kill slave!")
      self.__hangingSlaves__hangingSlaves.append(self.__slaveProc__slaveProc)
    self.__slaveProc__slaveProc = None
 
    return self.__isSlaveStopped__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__slave:
      self.logDebugWithPIDlogDebugWithPID("Handling '%s' request" % command)
      resultNode = self.__slave__slave.runCommand(requestNode)
    else:
      self.logDebugWithPIDlogDebugWithPID("Sending '%s' request to slave" % command)
      resultNode = None
      # The default timeout is taken from the configuration file.
      if not timeout:
        timeout = self.__config__config.getDefaultTestTimeoutSeconds()
 
      string = None
      while  (    not string
              and (trial < tries)):
        timer = TestCaseTimer(timeout)
        if self.__com__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__com.recv(timer.getSecondsRemaining())
            if string:
              recvNode = Utils.filterXMLString(string)
              self.logDebugWithPIDlogDebugWithPID("Received node of type '%s'" % recvNode.tag)
              if recvNode.tag == "Progress":
                shouldStop = False
                if self.__testCaseListener__testCaseListener:
                  try:
                    self.__testCaseListener__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__com.send("0" if shouldStop else "1", 5)
                string = None
              elif recvNode.tag == "Status":
                if self.__testCaseListener__testCaseListener:
                  self.__testCaseListener__testCaseListener.endTestCaseFunction(int(recvNode.get("status")), 0)
                string = None
              else:
                resultNode = recvNode
            else:
              break
 
        if not string:
          trial += 1
 
          if restart and (trial < tries):
            self.__logger__logger.info("Restarting due to communication error ...")
            self.__startSlave__startSlave()
 
      if resultNode == None:
        self.logDebugWithPIDlogDebugWithPID("Error: Received no result from slave.")
        resultNode = etree.Element('Result', errorCode='CommunicationError')
        etree.SubElement(resultNode, 'Error').text = "Communication error [%d]: %s" % self.__com__com.getLastErrorWithMessage()
    self.logDebugWithPIDlogDebugWithPID("Result error code: %s" % resultNode.get('errorCode'))
    content = etree.tostring(resultNode).decode()
    self.logDebugWithPIDlogDebugWithPID("Result content: %s%s" % (content[:150], " [...]" if len(content)>150 else ""))
    return resultNode
  # --------------------------------------------------------------------------------------------}}}-
# ----------------------------------------------------------------------------------------------}}}-