Example #1
0
def test_getTimeLeft(mocker, batch, requiredVariables, returnValue, expected_1,
                     expected_2):
    """Test getTimeLeft()"""
    mocker.patch(
        "DIRAC.Resources.Computing.BatchSystems.TimeLeft.TimeLeft.runCommand",
        return_value=S_OK(returnValue))
    tl = TimeLeft()

    batchSystemName = "%sResourceUsage" % batch
    batchSystemPath = "DIRAC.Resources.Computing.BatchSystems.TimeLeft.%s" % batchSystemName
    batchPlugin = __import__(batchSystemPath, globals(), locals(),
                             [batchSystemName])
    # Need to be reloaded to update the mock within the module, else, it will reuse the one when loaded the first time
    reload(batchPlugin)

    batchStr = "batchPlugin.%s()" % (batchSystemName)
    tl.batchPlugin = eval(batchStr)
    tl.cpuPower = 10.0

    # Update attributes of the batch systems to get scaled CPU
    tl.batchPlugin.__dict__.update(requiredVariables)

    res = tl.getTimeLeft()
    assert res["OK"] is expected_1
    if res["OK"]:
        assert res["Value"] == expected_2
Example #2
0
    def __init__(self, pid, exeThread, spObject, jobCPUTime, memoryLimit=0, processors=1, jobArgs={}):
        """Constructor, takes system flag as argument."""
        self.stopSigStartSeconds = int(jobArgs.get("StopSigStartSeconds", 1800))  # 30 minutes
        self.stopSigFinishSeconds = int(jobArgs.get("StopSigFinishSeconds", 1800))  # 30 minutes
        self.stopSigNumber = int(jobArgs.get("StopSigNumber", 2))  # SIGINT
        self.stopSigRegex = jobArgs.get("StopSigRegex", None)
        self.stopSigSent = False

        self.log = gLogger.getSubLogger("Watchdog")
        self.exeThread = exeThread
        self.wrapperPID = pid
        self.appPID = self.exeThread.getCurrentPID()
        self.spObject = spObject
        self.jobCPUTime = jobCPUTime
        self.memoryLimit = memoryLimit
        self.calibration = 0
        self.initialValues = {}
        self.parameters = {}
        self.peekFailCount = 0
        self.peekRetry = 5
        self.profiler = Profiler(pid)
        self.checkError = ""
        self.currentStats = {}
        self.initialized = False
        self.count = 0

        # defaults
        self.testWallClock = 1
        self.testDiskSpace = 1
        self.testLoadAvg = 1
        self.maxWallClockTime = 3 * 24 * 60 * 60
        self.testCPUConsumed = 1
        self.testCPULimit = 0
        self.testMemoryLimit = 0
        self.testTimeLeft = 1
        self.pollingTime = 10  # 10 seconds
        self.checkingTime = 30 * 60  # 30 minute period
        self.minCheckingTime = 20 * 60  # 20 mins
        self.wallClockCheckSeconds = 5 * 60  # 5 minutes
        self.maxWallClockTime = 3 * 24 * 60 * 60  # e.g. 4 days
        self.jobPeekFlag = 1  # on / off
        self.minDiskSpace = 10  # MB
        self.loadAvgLimit = 1000  # > 1000 and jobs killed
        self.sampleCPUTime = 30 * 60  # e.g. up to 20mins sample
        self.jobCPUMargin = 20  # %age buffer before killing job
        self.minCPUWallClockRatio = 5  # ratio %age
        self.nullCPULimit = 5  # After 5 sample times return null CPU consumption kill job
        self.checkCount = 0
        self.wallClockCheckCount = 0
        self.nullCPUCount = 0

        self.grossTimeLeftLimit = 10 * self.checkingTime
        self.timeLeftUtil = TimeLeft()
        self.timeLeft = 0
        self.littleTimeLeft = False
        self.cpuPower = 1.0
        self.processors = processors
Example #3
0
    def initialize(self):
        """Sets default parameters and creates CE instance"""

        # Disable monitoring
        self.am_disableMonitoring()

        localCE = gConfig.getValue("/LocalSite/LocalCE", self.ceName)
        if localCE != self.ceName:
            self.log.info("Defining Inner CE from local configuration",
                          "= %s" % localCE)

        # Create backend Computing Element
        result = self._initializeComputingElement(localCE)
        if not result["OK"]:
            return result

        result = self._getCEDict(self.computingElement)
        if not result["OK"]:
            return result
        ceDict = result["Value"][0]

        self.initTimeLeft = ceDict.get("CPUTime", self.initTimeLeft)
        self.initTimeLeft = gConfig.getValue(
            "/Resources/Computing/CEDefaults/MaxCPUTime", self.initTimeLeft)
        self.timeLeft = self.initTimeLeft

        self.initTimes = os.times()
        # Localsite options
        self.siteName = siteName()
        self.pilotReference = gConfig.getValue("/LocalSite/PilotReference",
                                               self.pilotReference)
        self.defaultProxyLength = gConfig.getValue(
            "/Registry/DefaultProxyLifeTime", self.defaultProxyLength)
        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = gConfig.getValue("/LocalSite/CPUNormalizationFactor",
                                          self.cpuFactor)
        self.jobSubmissionDelay = self.am_getOption("SubmissionDelay",
                                                    self.jobSubmissionDelay)
        self.fillingMode = self.am_getOption("FillingModeFlag",
                                             self.fillingMode)
        self.minimumTimeLeft = self.am_getOption("MinimumTimeLeft",
                                                 self.minimumTimeLeft)
        self.stopOnApplicationFailure = self.am_getOption(
            "StopOnApplicationFailure", self.stopOnApplicationFailure)
        self.stopAfterFailedMatches = self.am_getOption(
            "StopAfterFailedMatches", self.stopAfterFailedMatches)
        self.extraOptions = gConfig.getValue(
            "/AgentJobRequirements/ExtraOptions", self.extraOptions)
        # Utilities
        self.timeLeftUtil = TimeLeft()
        return S_OK()
Example #4
0
def test_getScaledCPU(mocker, batch, requiredVariables, returnValue, expected):
    """ Test getScaledCPU()
  """
    mocker.patch(
        "DIRAC.Resources.Computing.BatchSystems.TimeLeft.TimeLeft.runCommand",
        return_value=S_OK(returnValue))
    tl = TimeLeft()
    res = tl.getScaledCPU()
    assert res == 0

    tl.scaleFactor = 5.0
    tl.normFactor = 5.0

    batchSystemName = '%sResourceUsage' % batch
    batchSystemPath = 'DIRAC.Resources.Computing.BatchSystems.TimeLeft.%s' % batchSystemName
    batchPlugin = __import__(batchSystemPath, globals(), locals(),
                             [batchSystemName])  # pylint: disable=unused-variable
    # Need to be reloaded to update the mock within the module, else, it will reuse the one when loaded the first time
    reload_module(batchPlugin)

    batchStr = 'batchPlugin.%s()' % (batchSystemName)
    tl.batchPlugin = eval(batchStr)

    # Update attributes of the batch systems to get scaled CPU
    tl.batchPlugin.__dict__.update(requiredVariables)

    res = tl.getScaledCPU()
    assert res == expected
Example #5
0
def test__computeCPUWorkLeft(mocker, initTimeLeft, timeLeft, cpuFactor,
                             mockTimeLeftReply, expectedTimeLeft):
    """Test JobAgent()._computeCPUWorkLeft()"""
    mocker.patch(
        "DIRAC.WorkloadManagementSystem.Agent.JobAgent.AgentModule.__init__")
    mocker.patch(
        "DIRAC.Resources.Computing.BatchSystems.TimeLeft.TimeLeft.TimeLeft.getTimeLeft",
        return_value=mockTimeLeftReply)

    jobAgent = JobAgent("Test", "Test1")
    jobAgent.log = gLogger
    jobAgent.log.setLevel("DEBUG")
    jobAgent.timeLeftUtil = TimeLeft()

    jobAgent.initTimeLeft = initTimeLeft
    jobAgent.timeLeft = timeLeft
    jobAgent.cpuFactor = cpuFactor
    result = jobAgent._computeCPUWorkLeft()

    assert abs(result - expectedTimeLeft) < 10
Example #6
0
class Watchdog(object):

    #############################################################################
    def __init__(self, pid, exeThread, spObject, jobCPUTime, memoryLimit=0, processors=1, jobArgs={}):
        """Constructor, takes system flag as argument."""
        self.stopSigStartSeconds = int(jobArgs.get("StopSigStartSeconds", 1800))  # 30 minutes
        self.stopSigFinishSeconds = int(jobArgs.get("StopSigFinishSeconds", 1800))  # 30 minutes
        self.stopSigNumber = int(jobArgs.get("StopSigNumber", 2))  # SIGINT
        self.stopSigRegex = jobArgs.get("StopSigRegex", None)
        self.stopSigSent = False

        self.log = gLogger.getSubLogger("Watchdog")
        self.exeThread = exeThread
        self.wrapperPID = pid
        self.appPID = self.exeThread.getCurrentPID()
        self.spObject = spObject
        self.jobCPUTime = jobCPUTime
        self.memoryLimit = memoryLimit
        self.calibration = 0
        self.initialValues = {}
        self.parameters = {}
        self.peekFailCount = 0
        self.peekRetry = 5
        self.profiler = Profiler(pid)
        self.checkError = ""
        self.currentStats = {}
        self.initialized = False
        self.count = 0

        # defaults
        self.testWallClock = 1
        self.testDiskSpace = 1
        self.testLoadAvg = 1
        self.maxWallClockTime = 3 * 24 * 60 * 60
        self.testCPUConsumed = 1
        self.testCPULimit = 0
        self.testMemoryLimit = 0
        self.testTimeLeft = 1
        self.pollingTime = 10  # 10 seconds
        self.checkingTime = 30 * 60  # 30 minute period
        self.minCheckingTime = 20 * 60  # 20 mins
        self.wallClockCheckSeconds = 5 * 60  # 5 minutes
        self.maxWallClockTime = 3 * 24 * 60 * 60  # e.g. 4 days
        self.jobPeekFlag = 1  # on / off
        self.minDiskSpace = 10  # MB
        self.loadAvgLimit = 1000  # > 1000 and jobs killed
        self.sampleCPUTime = 30 * 60  # e.g. up to 20mins sample
        self.jobCPUMargin = 20  # %age buffer before killing job
        self.minCPUWallClockRatio = 5  # ratio %age
        self.nullCPULimit = 5  # After 5 sample times return null CPU consumption kill job
        self.checkCount = 0
        self.wallClockCheckCount = 0
        self.nullCPUCount = 0

        self.grossTimeLeftLimit = 10 * self.checkingTime
        self.timeLeftUtil = TimeLeft()
        self.timeLeft = 0
        self.littleTimeLeft = False
        self.cpuPower = 1.0
        self.processors = processors

    #############################################################################
    def initialize(self):
        """Watchdog initialization."""
        if self.initialized:
            self.log.info("Watchdog already initialized")
            return S_OK()
        else:
            self.initialized = True

        setup = gConfig.getValue("/DIRAC/Setup", "")
        if not setup:
            return S_ERROR("Can not get the DIRAC Setup value")
        wms_instance = getSystemInstance("WorkloadManagement")
        if not wms_instance:
            return S_ERROR("Can not get the WorkloadManagement system instance")
        self.section = "/Systems/WorkloadManagement/%s/JobWrapper" % wms_instance

        self.log.verbose("Watchdog initialization")
        # Test control flags
        self.testWallClock = gConfig.getValue(self.section + "/CheckWallClockFlag", 1)
        self.testDiskSpace = gConfig.getValue(self.section + "/CheckDiskSpaceFlag", 1)
        self.testLoadAvg = gConfig.getValue(self.section + "/CheckLoadAvgFlag", 1)
        self.testCPUConsumed = gConfig.getValue(self.section + "/CheckCPUConsumedFlag", 1)
        self.testCPULimit = gConfig.getValue(self.section + "/CheckCPULimitFlag", 0)
        self.testMemoryLimit = gConfig.getValue(self.section + "/CheckMemoryLimitFlag", 0)
        self.testTimeLeft = gConfig.getValue(self.section + "/CheckTimeLeftFlag", 1)
        # Other parameters
        self.pollingTime = gConfig.getValue(self.section + "/PollingTime", 10)  # 10 seconds
        self.checkingTime = gConfig.getValue(self.section + "/CheckingTime", 30 * 60)  # 30 minute period
        self.minCheckingTime = gConfig.getValue(self.section + "/MinCheckingTime", 20 * 60)  # 20 mins
        self.maxWallClockTime = gConfig.getValue(self.section + "/MaxWallClockTime", 3 * 24 * 60 * 60)  # e.g. 4 days
        self.jobPeekFlag = gConfig.getValue(self.section + "/JobPeekFlag", 1)  # on / off
        self.minDiskSpace = gConfig.getValue(self.section + "/MinDiskSpace", 10)  # MB
        self.loadAvgLimit = gConfig.getValue(self.section + "/LoadAverageLimit", 1000)  # > 1000 and jobs killed
        self.sampleCPUTime = gConfig.getValue(self.section + "/CPUSampleTime", 30 * 60)  # e.g. up to 20mins sample
        self.jobCPUMargin = gConfig.getValue(self.section + "/JobCPULimitMargin", 20)  # %age buffer before killing job
        self.minCPUWallClockRatio = gConfig.getValue(self.section + "/MinCPUWallClockRatio", 5)  # ratio %age
        # After 5 sample times return null CPU consumption kill job
        self.nullCPULimit = gConfig.getValue(self.section + "/NullCPUCountLimit", 5)
        if self.checkingTime < self.minCheckingTime:
            self.log.info(
                "Requested CheckingTime of %s setting to %s seconds (minimum)"
                % (self.checkingTime, self.minCheckingTime)
            )
            self.checkingTime = self.minCheckingTime

        # The time left is returned in seconds @ 250 SI00 = 1 HS06,
        # the self.checkingTime and self.pollingTime are in seconds,
        # thus they need to be multiplied by a large enough factor
        self.fineTimeLeftLimit = gConfig.getValue(self.section + "/TimeLeftLimit", 150 * self.pollingTime)
        self.cpuPower = gConfig.getValue("/LocalSite/CPUNormalizationFactor", 1.0)

        return S_OK()

    def run(self):
        """The main watchdog execution method"""

        result = self.initialize()
        if not result["OK"]:
            self.log.always("Can not start watchdog for the following reason")
            self.log.always(result["Message"])
            return result

        try:
            while True:
                self.log.debug("Starting watchdog loop # %d" % self.count)
                start_cycle_time = time.time()
                result = self.execute()
                exec_cycle_time = time.time() - start_cycle_time
                if not result["OK"]:
                    self.log.error("Watchdog error during execution", result["Message"])
                    break
                elif result["Value"] == "Ended":
                    break
                self.count += 1
                if exec_cycle_time < self.pollingTime:
                    time.sleep(self.pollingTime - exec_cycle_time)
            return S_OK()
        except Exception:
            self.log.exception()
            return S_ERROR("Exception")

    #############################################################################
    def execute(self):
        """The main agent execution method of the Watchdog."""

        if not self.exeThread.is_alive():
            self.__getUsageSummary()
            self.log.info("Process to monitor has completed, Watchdog will exit.")
            return S_OK("Ended")

        # WallClock checks every self.wallClockCheckSeconds, but only if StopSigRegex is defined in JDL
        if (
            not self.stopSigSent
            and self.stopSigRegex is not None
            and (time.time() - self.initialValues["StartTime"]) > self.wallClockCheckSeconds * self.wallClockCheckCount
        ):
            self.wallClockCheckCount += 1
            self._performWallClockChecks()

        if self.littleTimeLeft:
            # if we have gone over enough iterations query again
            if self.littleTimeLeftCount == 0 and self.__timeLeft() == -1:
                self.checkError = JobMinorStatus.JOB_EXCEEDED_CPU
                self.log.error(self.checkError, self.timeLeft)
                self.__killRunningThread()
                return S_OK()
            else:
                self.littleTimeLeftCount -= 1

        # Note: need to poll regularly to see if the thread is alive
        #      but only perform checks with a certain frequency
        if (time.time() - self.initialValues["StartTime"]) > self.checkingTime * self.checkCount:
            self.checkCount += 1
            result = self._performChecks()
            if not result["OK"]:
                self.log.warn("Problem during recent checks")
                self.log.warn(result["Message"])
            return S_OK()
        else:
            # self.log.debug('Application thread is alive: checking count is %s' %(self.checkCount))
            return S_OK()

    #############################################################################
    def _performWallClockChecks(self):
        """Watchdog performs the wall clock checks based on MJF. Signals are sent
        to processes if we need to stop, but function always returns S_OK()
        """
        mjf = MJF.MJF()

        try:
            wallClockSecondsLeft = mjf.getWallClockSecondsLeft()
        except Exception as e:
            # Just stop if we can't get the wall clock seconds left
            return S_OK()

        jobstartSeconds = mjf.getIntJobFeature("jobstart_secs")
        if jobstartSeconds is None:
            # Just stop if we don't know when the job started
            return S_OK()

        if (int(time.time()) > jobstartSeconds + self.stopSigStartSeconds) and (
            wallClockSecondsLeft < self.stopSigFinishSeconds + self.wallClockCheckSeconds
        ):
            # Need to send the signal! Assume it works to avoid sending the signal more than once
            self.log.info("Sending signal to JobWrapper children", "(%s)" % self.stopSigNumber)
            self.stopSigSent = True

            try:
                for childPid in getChildrenPIDs(self.wrapperPID):
                    try:
                        cmdline = open("/proc/%d/cmdline" % childPid, "r").read().replace("\0", " ").strip()
                    except IOError:
                        # Process gone away? Not running on Linux? Skip anyway
                        continue

                    if re.search(self.stopSigRegex, cmdline) is not None:
                        self.log.info(
                            'Sending signal %d to process ID %d, cmdline = "%s"'
                            % (self.stopSigNumber, childPid, cmdline)
                        )
                        os.kill(childPid, self.stopSigNumber)

            except Exception as e:
                self.log.error("Failed to send signals to JobWrapper children!", repr(e))

        return S_OK()

    #############################################################################
    def _performChecks(self):
        """The Watchdog checks are performed at a different period to the checking of the
        application thread and correspond to the checkingTime.
        """
        self.log.verbose("------------------------------------")
        self.log.verbose("Checking loop starts for Watchdog")
        heartBeatDict = {}

        msg = ""

        loadAvg = float(os.getloadavg()[0])
        msg += "LoadAvg: %d " % loadAvg
        heartBeatDict["LoadAverage"] = loadAvg
        if "LoadAverage" not in self.parameters:
            self.parameters["LoadAverage"] = []
        self.parameters["LoadAverage"].append(loadAvg)

        memoryUsed = self.getMemoryUsed()
        msg += "MemUsed: %.1f kb " % (memoryUsed)
        heartBeatDict["MemoryUsed"] = memoryUsed
        if "MemoryUsed" not in self.parameters:
            self.parameters["MemoryUsed"] = []
        self.parameters["MemoryUsed"].append(memoryUsed)

        result = self.profiler.vSizeUsage(withChildren=True)
        if not result["OK"]:
            self.log.warn("Could not get vSize info from profiler", result["Message"])
        else:
            vsize = result["Value"] * 1024.0
            heartBeatDict["Vsize"] = vsize
            self.parameters.setdefault("Vsize", [])
            self.parameters["Vsize"].append(vsize)
            msg += "Job Vsize: %.1f kb " % vsize

        result = self.profiler.memoryUsage(withChildren=True)
        if not result["OK"]:
            self.log.warn("Could not get rss info from profiler", result["Message"])
        else:
            rss = result["Value"] * 1024.0
            heartBeatDict["RSS"] = rss
            self.parameters.setdefault("RSS", [])
            self.parameters["RSS"].append(rss)
            msg += "Job RSS: %.1f kb " % rss

        if "DiskSpace" not in self.parameters:
            self.parameters["DiskSpace"] = []

        # We exclude fuse so that mountpoints can be cleaned up by automount after a period unused
        # (specific request from CERN batch service).
        result = self.getDiskSpace(exclude="fuse")
        if not result["OK"]:
            self.log.warn("Could not establish DiskSpace", result["Message"])
        else:
            msg += "DiskSpace: %.1f MB " % (result["Value"])
            self.parameters["DiskSpace"].append(result["Value"])
            heartBeatDict["AvailableDiskSpace"] = result["Value"]

        cpu = self.__getCPU()
        if not cpu["OK"]:
            msg += "CPU: ERROR "
            hmsCPU = 0
        else:
            cpu = cpu["Value"]
            msg += "CPU: %s (h:m:s) " % (cpu)
            if "CPUConsumed" not in self.parameters:
                self.parameters["CPUConsumed"] = []
            self.parameters["CPUConsumed"].append(cpu)
            hmsCPU = cpu
            rawCPU = self.__convertCPUTime(hmsCPU)
            if rawCPU["OK"]:
                heartBeatDict["CPUConsumed"] = rawCPU["Value"]

        result = self.__getWallClockTime()
        if not result["OK"]:
            self.log.warn("Failed determining wall clock time", result["Message"])
        else:
            msg += "WallClock: %.2f s " % (result["Value"])
            self.parameters.setdefault("WallClockTime", list()).append(result["Value"])
            heartBeatDict["WallClockTime"] = result["Value"] * self.processors
        self.log.info(msg)

        result = self._checkProgress()
        if not result["OK"]:
            self.checkError = result["Message"]
            self.log.warn(self.checkError)

            if self.jobPeekFlag:
                result = self.__peek()
                if result["OK"]:
                    outputList = result["Value"]
                    self.log.info("Last lines of available application output:")
                    self.log.info("================START================")
                    for line in outputList:
                        self.log.info(line)

                    self.log.info("=================END=================")

            self.__killRunningThread()
            return S_OK()

        recentStdOut = "None"
        if self.jobPeekFlag:
            result = self.__peek()
            if result["OK"]:
                outputList = result["Value"]
                size = len(outputList)
                recentStdOut = "Last %s lines of application output from Watchdog on %s [UTC]:" % (
                    size,
                    Time.dateTime(),
                )
                border = "=" * len(recentStdOut)
                cpuTotal = "Last reported CPU consumed for job is %s (h:m:s)" % (hmsCPU)
                if self.timeLeft:
                    cpuTotal += ", Batch Queue Time Left %s (s @ HS06)" % self.timeLeft
                recentStdOut = "\n%s\n%s\n%s\n%s\n" % (border, recentStdOut, cpuTotal, border)
                self.log.info(recentStdOut)
                for line in outputList:
                    self.log.info(line)
                    recentStdOut += line + "\n"
            else:
                recentStdOut = (
                    "Watchdog is initializing and will attempt to obtain standard output from application thread"
                )
                self.log.info(recentStdOut)
                self.peekFailCount += 1
                if self.peekFailCount > self.peekRetry:
                    self.jobPeekFlag = 0
                    self.log.warn("Turning off job peeking for remainder of execution")

        if "JOBID" not in os.environ:
            self.log.info("Running without JOBID so parameters will not be reported")
            return S_OK()

        jobID = os.environ["JOBID"]
        staticParamDict = {"StandardOutput": recentStdOut}
        self.__sendSignOfLife(int(jobID), heartBeatDict, staticParamDict)
        return S_OK("Watchdog checking cycle complete")

    #############################################################################
    def __getCPU(self):
        """Uses the profiler to get CPU time for current process, its child, and the terminated child,
        and returns HH:MM:SS after conversion.
        """
        result = self.profiler.cpuUsageUser(withChildren=True, withTerminatedChildren=True)
        if not result["OK"]:
            self.log.warn("Issue while checking consumed CPU for user", result["Message"])
            if result["Errno"] == errno.ESRCH:
                self.log.warn("The main process does not exist (anymore). This might be correct.")
            return result
        cpuUsageUser = result["Value"]

        result = self.profiler.cpuUsageSystem(withChildren=True, withTerminatedChildren=True)
        if not result["OK"]:
            self.log.warn("Issue while checking consumed CPU for system", result["Message"])
            if result["Errno"] == errno.ESRCH:
                self.log.warn("The main process does not exist (anymore). This might be correct.")
            return result
        cpuUsageSystem = result["Value"]

        cpuTimeTotal = cpuUsageUser + cpuUsageSystem
        if cpuTimeTotal:
            self.log.verbose("Raw CPU time consumed (s) =", cpuTimeTotal)
            return self.__getCPUHMS(cpuTimeTotal)
        self.log.error("CPU time consumed found to be 0")
        return S_ERROR()

    #############################################################################
    def __getCPUHMS(self, cpuTime):
        mins, secs = divmod(cpuTime, 60)
        hours, mins = divmod(mins, 60)
        humanTime = "%02d:%02d:%02d" % (hours, mins, secs)
        self.log.verbose("Human readable CPU time is: %s" % humanTime)
        return S_OK(humanTime)

    #############################################################################
    def __interpretControlSignal(self, signalDict):
        """This method is called whenever a signal is sent via the result of
        sending a sign of life.
        """
        self.log.info("Received control signal")
        if isinstance(signalDict, dict):
            if "Kill" in signalDict:
                self.log.info("Received Kill signal, stopping job via control signal")
                self.checkError = JobMinorStatus.RECEIVED_KILL_SIGNAL
                self.__killRunningThread()
            else:
                self.log.info("The following control signal was sent but not understood by the watchdog:")
                self.log.info(signalDict)
        else:
            self.log.info("Expected dictionary for control signal", "received:\n%s" % (signalDict))

        return S_OK()

    #############################################################################
    def _checkProgress(self):
        """This method calls specific tests to determine whether the job execution
        is proceeding normally.  CS flags can easily be added to add or remove
        tests via central configuration.
        """
        report = ""

        if self.testWallClock:
            result = self.__checkWallClockTime()
            if not result["OK"]:
                self.log.warn(result["Message"])
                return result
            report += "WallClock: OK, "
        else:
            report += "WallClock: NA,"

        if self.testDiskSpace:
            result = self.__checkDiskSpace()
            if not result["OK"]:
                self.log.warn(result["Message"])
                return result
            report += "DiskSpace: OK, "
        else:
            report += "DiskSpace: NA,"

        if self.testLoadAvg:
            result = self.__checkLoadAverage()
            if not result["OK"]:
                self.log.warn(
                    "Check of load average failed, but won't fail because of that", ": %s" % result["Message"]
                )
                report += "LoadAverage: ERROR, "
                return S_OK()
            report += "LoadAverage: OK, "
        else:
            report += "LoadAverage: NA,"

        if self.testCPUConsumed:
            result = self.__checkCPUConsumed()
            if not result["OK"]:
                return result
            report += "CPUConsumed: OK, "
        else:
            report += "CPUConsumed: NA, "

        if self.testCPULimit:
            result = self.__checkCPULimit()
            if not result["OK"]:
                self.log.warn(result["Message"])
                return result
            report += "CPULimit OK, "
        else:
            report += "CPULimit: NA, "

        if self.testTimeLeft:
            self.__timeLeft()
            if self.timeLeft:
                report += "TimeLeft: OK"
        else:
            report += "TimeLeft: NA"

        if self.testMemoryLimit:
            result = self.__checkMemoryLimit()
            if not result["OK"]:
                self.log.warn(result["Message"])
                return result
            report += "MemoryLimit OK, "
        else:
            report += "MemoryLimit: NA, "

        self.log.info(report)
        return S_OK("All enabled checks passed")

    #############################################################################
    def __checkCPUConsumed(self):
        """Checks whether the CPU consumed by application process is reasonable. This
        method will report stalled jobs to be killed.
        """
        self.log.info("Checking CPU Consumed")

        if "WallClockTime" not in self.parameters:
            return S_ERROR("Missing WallClockTime info")
        if "CPUConsumed" not in self.parameters:
            return S_ERROR("Missing CPUConsumed info")

        wallClockTime = self.parameters["WallClockTime"][-1]
        if wallClockTime < self.sampleCPUTime:
            self.log.info(
                "Stopping check, wallclock time is still smaller than sample time",
                "(%s) < (%s)" % (wallClockTime, self.sampleCPUTime),
            )
            return S_OK()

        intervals = max(1, int(self.sampleCPUTime / self.checkingTime))
        if len(self.parameters["CPUConsumed"]) < intervals + 1:
            self.log.info(
                "Not enough snapshots to calculate",
                "there are %s and we need %s" % (len(self.parameters["CPUConsumed"]), intervals + 1),
            )
            return S_OK()

        wallClockTime = self.parameters["WallClockTime"][-1] - self.parameters["WallClockTime"][-1 - intervals]
        try:
            cpuTime = self.__convertCPUTime(self.parameters["CPUConsumed"][-1])["Value"]
            # For some reason, some times the CPU consumed estimation returns 0
            # if cpuTime == 0:
            #   return S_OK()
            cpuTime -= self.__convertCPUTime(self.parameters["CPUConsumed"][-1 - intervals])["Value"]
            if cpuTime < 0:
                self.log.warn("Consumed CPU time negative, something wrong may have happened, ignore")
                return S_OK()
            if wallClockTime <= 0:
                self.log.warn("Wallclock time should not be negative or zero, Ignore")
                return S_OK()

            ratio = (cpuTime / wallClockTime) * 100

            self.log.info("CPU/Wallclock ratio is %.2f%%" % ratio)
            # in case of error cpuTime might be 0, exclude this
            if ratio < self.minCPUWallClockRatio:
                if (
                    os.path.exists("DISABLE_WATCHDOG_CPU_WALLCLOCK_CHECK")
                    or "DISABLE_WATCHDOG_CPU_WALLCLOCK_CHECK" in os.environ
                ):
                    self.log.warn(
                        "N.B. job would be declared as stalled but CPU / WallClock check is disabled by payload"
                    )
                    return S_OK()
                self.log.info("Job is stalled!")
                return S_ERROR(JobMinorStatus.WATCHDOG_STALLED)
        except Exception as e:
            self.log.error("Cannot convert CPU consumed from string to int", str(e))

        return S_OK()

    #############################################################################

    def __convertCPUTime(self, cputime):
        """Method to convert the CPU time as returned from the Watchdog
        instances to the equivalent DIRAC normalized CPU time to be compared
        to the Job CPU requirement.
        """
        cpuValue = 0
        cpuHMS = cputime.split(":")
        # for i in range( len( cpuHMS ) ):
        #   cpuHMS[i] = cpuHMS[i].replace( '00', '0' )

        try:
            hours = float(cpuHMS[0]) * 60 * 60
            mins = float(cpuHMS[1]) * 60
            secs = float(cpuHMS[2])
            cpuValue = float(hours + mins + secs)
        except Exception as x:
            self.log.warn(str(x))
            return S_ERROR("Could not calculate CPU time")

        # Normalization to be implemented
        normalizedCPUValue = cpuValue

        result = S_OK()
        result["Value"] = normalizedCPUValue
        self.log.debug("CPU value %s converted to %s" % (cputime, normalizedCPUValue))
        return result

    #############################################################################

    def __checkCPULimit(self):
        """Checks that the job has consumed more than the job CPU requirement
        (plus a configurable margin) and kills them as necessary.
        """
        consumedCPU = 0
        if "CPUConsumed" in self.parameters:
            consumedCPU = self.parameters["CPUConsumed"][-1]

        consumedCPUDict = self.__convertCPUTime(consumedCPU)
        if consumedCPUDict["OK"]:
            currentCPU = consumedCPUDict["Value"]
        else:
            return S_OK("Not possible to determine current CPU consumed")

        if consumedCPU:
            limit = int(self.jobCPUTime + self.jobCPUTime * (self.jobCPUMargin / 100))
            cpuConsumed = float(currentCPU)
            if cpuConsumed > limit:
                self.log.info(
                    "Job has consumed more than the specified CPU limit",
                    "with an additional %s%% margin" % (self.jobCPUMargin),
                )
                return S_ERROR("Job has exceeded maximum CPU time limit")
            return S_OK("Job within CPU limit")

        if not currentCPU:
            self.log.verbose("Both initial and current CPU consumed are null")
            return S_OK("CPU consumed is not measurable yet")

        return S_OK("Not possible to determine CPU consumed")

    def __checkMemoryLimit(self):
        """Checks that the job memory consumption is within a limit"""
        vsize = 0
        if "Vsize" in self.parameters:
            vsize = self.parameters["Vsize"][-1]

        if vsize and self.memoryLimit:
            if vsize > self.memoryLimit:
                vsize = vsize
                # Just a warning for the moment
                self.log.warn(
                    "Job has consumed %f.2 KB of memory with the limit of %f.2 KB" % (vsize, self.memoryLimit)
                )

        return S_OK()

    #############################################################################
    def __checkDiskSpace(self):
        """Checks whether the CS defined minimum disk space is available."""
        if "DiskSpace" in self.parameters:
            availSpace = self.parameters["DiskSpace"][-1]
            if availSpace >= 0 and availSpace < self.minDiskSpace:
                self.log.info(
                    "Not enough local disk space for job to continue, defined in CS as %s MB" % (self.minDiskSpace)
                )
                return S_ERROR(JobMinorStatus.JOB_INSUFFICIENT_DISK)
            else:
                return S_OK("Job has enough disk space available")
        else:
            return S_ERROR("Available disk space could not be established")

    #############################################################################
    def __checkWallClockTime(self):
        """Checks whether the job has been running for the CS defined maximum
        wall clock time.
        """
        if "StartTime" in self.initialValues:
            startTime = self.initialValues["StartTime"]
            if time.time() - startTime > self.maxWallClockTime:
                self.log.info("Job has exceeded maximum wall clock time of %s seconds" % (self.maxWallClockTime))
                return S_ERROR(JobMinorStatus.JOB_EXCEEDED_WALL_CLOCK)
            else:
                return S_OK("Job within maximum wall clock time")
        else:
            return S_ERROR("Job start time could not be established")

    #############################################################################
    def __checkLoadAverage(self):
        """Checks whether the CS defined maximum load average is exceeded."""
        if "LoadAverage" in self.parameters:
            loadAvg = self.parameters["LoadAverage"][-1]
            if loadAvg > float(self.loadAvgLimit):
                self.log.info("Maximum load average exceeded, defined in CS as %s " % (self.loadAvgLimit))
                return S_ERROR("Job exceeded maximum load average")
            return S_OK("Job running with normal load average")
        return S_ERROR("Job load average not established")

    #############################################################################
    def __peek(self):
        """Uses ExecutionThread.getOutput() method to obtain standard output
        from running thread via subprocess callback function.
        """
        result = self.exeThread.getOutput()
        if not result["OK"]:
            self.log.warn("Could not obtain output from running application thread")
            self.log.warn(result["Message"])

        return result

    #############################################################################
    def calibrate(self):
        """The calibrate method obtains the initial values for system memory and load
        and calculates the margin for error for the rest of the Watchdog cycle.
        """
        self.__getWallClockTime()
        self.parameters["WallClockTime"] = []

        cpuConsumed = self.__getCPU()
        if not cpuConsumed["OK"]:
            self.log.warn("Could not establish CPU consumed, setting to 0.0")
            cpuConsumed = 0.0
        else:
            cpuConsumed = cpuConsumed["Value"]

        self.initialValues["CPUConsumed"] = cpuConsumed
        self.parameters["CPUConsumed"] = []

        self.initialValues["LoadAverage"] = float(os.getloadavg()[0])
        self.parameters["LoadAverage"] = []

        memUsed = self.getMemoryUsed()

        self.initialValues["MemoryUsed"] = memUsed
        self.parameters["MemoryUsed"] = []

        result = self.profiler.vSizeUsage(withChildren=True)
        if not result["OK"]:
            self.log.warn("Could not get vSize info from profiler", result["Message"])
        else:
            vsize = result["Value"] * 1024.0
            self.initialValues["Vsize"] = vsize
            self.log.verbose("Vsize(kb)", "%.1f" % vsize)
        self.parameters["Vsize"] = []

        result = self.profiler.memoryUsage(withChildren=True)
        if not result["OK"]:
            self.log.warn("Could not get rss info from profiler", result["Message"])
        else:
            rss = result["Value"] * 1024.0
            self.initialValues["RSS"] = rss
            self.log.verbose("RSS(kb)", "%.1f" % rss)
        self.parameters["RSS"] = []

        # We exclude fuse so that mountpoints can be cleaned up by automount after a period unused
        # (specific request from CERN batch service).
        result = self.getDiskSpace(exclude="fuse")
        self.log.verbose("DiskSpace: %s" % (result))
        if not result["OK"]:
            self.log.warn("Could not establish DiskSpace")
        else:
            self.initialValues["DiskSpace"] = result["Value"]
        self.parameters["DiskSpace"] = []

        result = self.getNodeInformation()
        self.log.verbose("NodeInfo", result)

        if "LSB_JOBID" in os.environ:
            result["LocalJobID"] = os.environ["LSB_JOBID"]
        if "PBS_JOBID" in os.environ:
            result["LocalJobID"] = os.environ["PBS_JOBID"]
        if "QSUB_REQNAME" in os.environ:
            result["LocalJobID"] = os.environ["QSUB_REQNAME"]
        if "JOB_ID" in os.environ:
            result["LocalJobID"] = os.environ["JOB_ID"]

        self.__reportParameters(result, "NodeInformation", True)
        self.__reportParameters(self.initialValues, "InitialValues")
        return S_OK()

    def __timeLeft(self):
        """
        return Normalized CPU time left in the batch system
        0 if not available
        update self.timeLeft and self.littleTimeLeft
        """
        # Get CPU time left in the batch system
        result = self.timeLeftUtil.getTimeLeft(0.0)
        if not result["OK"]:
            # Could not get CPU time left, we might need to wait for the first loop
            # or the Utility is not working properly for this batch system
            # or we are in a batch system
            timeLeft = 0
        else:
            timeLeft = result["Value"]

        self.timeLeft = timeLeft
        if not self.littleTimeLeft:
            if timeLeft and timeLeft < self.grossTimeLeftLimit:
                self.log.info("TimeLeft bellow %s, now checking with higher frequency" % timeLeft)
                self.littleTimeLeft = True
                # TODO: better configurable way of doing this to be coded
                self.littleTimeLeftCount = 15
        else:
            if self.timeLeft and self.timeLeft < self.fineTimeLeftLimit:
                timeLeft = -1

        return timeLeft

    #############################################################################
    def __getUsageSummary(self):
        """Returns average load, memory etc. over execution of job thread"""
        summary = {}
        # CPUConsumed
        if "CPUConsumed" in self.parameters:
            cpuList = self.parameters["CPUConsumed"]
            if cpuList:
                hmsCPU = cpuList[-1]
                rawCPU = self.__convertCPUTime(hmsCPU)
                if rawCPU["OK"]:
                    summary["LastUpdateCPU(s)"] = rawCPU["Value"]
            else:
                summary["LastUpdateCPU(s)"] = "Could not be estimated"
        # DiskSpace
        if "DiskSpace" in self.parameters:
            space = self.parameters["DiskSpace"]
            if space:
                value = abs(float(space[-1]) - float(self.initialValues["DiskSpace"]))
                if value < 0:
                    value = 0
                summary["DiskSpace(MB)"] = value
            else:
                summary["DiskSpace(MB)"] = "Could not be estimated"
        # MemoryUsed
        if "MemoryUsed" in self.parameters:
            memory = self.parameters["MemoryUsed"]
            if memory:
                summary["MemoryUsed(kb)"] = abs(float(memory[-1]) - float(self.initialValues["MemoryUsed"]))
            else:
                summary["MemoryUsed(kb)"] = "Could not be estimated"
        # LoadAverage
        if "LoadAverage" in self.parameters:
            laList = self.parameters["LoadAverage"]
            if laList:
                summary["LoadAverage"] = sum(laList) / len(laList)
            else:
                summary["LoadAverage"] = "Could not be estimated"

        result = self.__getWallClockTime()
        if not result["OK"]:
            self.log.warn("Failed determining wall clock time", result["Message"])
            summary["WallClockTime(s)"] = 0
            summary["ScaledCPUTime(s)"] = 0
        else:
            wallClock = result["Value"]
            summary["WallClockTime(s)"] = wallClock * self.processors
            summary["ScaledCPUTime(s)"] = wallClock * self.cpuPower * self.processors

        self.__reportParameters(summary, "UsageSummary", True)
        self.currentStats = summary

    #############################################################################
    def __reportParameters(self, params, title=None, report=False):
        """Will report parameters for job."""
        try:
            parameters = []
            self.log.info("", "==========================================================")
            if title:
                self.log.info("Watchdog will report", title)
            else:
                self.log.info("Watchdog will report parameters")
            self.log.info("", "==========================================================")
            vals = params
            if "Value" in params:
                if vals["Value"]:
                    vals = params["Value"]
            for k, v in vals.items():
                if v:
                    self.log.info(str(k) + " = " + str(v))
                    parameters.append([k, v])
            if report:
                self.__setJobParamList(parameters)

            self.log.info("", "==========================================================")
        except Exception as x:
            self.log.warn("Problem while reporting parameters")
            self.log.warn(repr(x))

    #############################################################################
    def __getWallClockTime(self):
        """Establishes the Wall Clock time spent since the Watchdog initialization"""
        result = S_OK()
        if "StartTime" in self.initialValues:
            currentTime = time.time()
            wallClock = currentTime - self.initialValues["StartTime"]
            result["Value"] = wallClock
        else:
            self.initialValues["StartTime"] = time.time()
            result["Value"] = 0.0

        return result

    #############################################################################
    def __killRunningThread(self):
        """Will kill the running thread process and any child processes."""
        self.log.info("Sending kill signal to application PID %s" % (self.spObject.getChildPID()))
        result = self.spObject.killChild()
        self.applicationKilled = True
        self.log.info("Subprocess.killChild() returned:%s " % (result))
        return S_OK("Thread killed")

    #############################################################################
    def __sendSignOfLife(self, jobID, heartBeatDict, staticParamDict):
        """Sends sign of life 'heartbeat' signal and triggers control signal
        interpretation.
        """
        result = JobStateUpdateClient().sendHeartBeat(jobID, heartBeatDict, staticParamDict)
        if not result["OK"]:
            self.log.warn("Problem sending sign of life")
            self.log.warn(result)

        if result["OK"] and result["Value"]:
            self.__interpretControlSignal(result["Value"])

        return result

    #############################################################################
    def __setJobParamList(self, value):
        """Wraps around setJobParameters of state update client"""
        # job wrapper template sets the jobID variable
        if "JOBID" not in os.environ:
            self.log.info("Running without JOBID so parameters will not be reported")
            return S_OK()
        jobID = os.environ["JOBID"]
        jobParam = JobStateUpdateClient().setJobParameters(int(jobID), value)
        self.log.verbose("setJobParameters(%s,%s)" % (jobID, value))
        if not jobParam["OK"]:
            self.log.warn(jobParam["Message"])

        return jobParam

    #############################################################################
    def getNodeInformation(self):
        """Retrieves all static system information"""
        result = {}
        result["HostName"] = socket.gethostname()
        result["CPU(MHz)"] = psutil.cpu_freq()[0]
        result["Memory(kB)"] = int(psutil.virtual_memory()[1] / 1024)
        result["LocalAccount"] = getpass.getuser()

        if os.path.exists("/proc/cpuinfo"):
            with open("/proc/cpuinfo", "r") as cpuinfo:
                info = cpuinfo.readlines()
            try:
                result["ModelName"] = info[4].split(":")[1].replace(" ", "").replace("\n", "")
            except IndexError:
                pass
            try:
                result["CacheSize(kB)"] = [x.strip().split(":")[1] for x in info if "cache size" in x][0].strip()
            except IndexError:
                pass

        return result

    #############################################################################
    def getMemoryUsed(self):
        """Obtains the memory used."""
        mem = (
            resource.getrusage(resource.RUSAGE_SELF).ru_maxrss + resource.getrusage(resource.RUSAGE_CHILDREN).ru_maxrss
        )
        return float(mem)

    #############################################################################
    def getDiskSpace(self, exclude=None):
        """Obtains the available disk space."""
        result = S_OK()
        diskSpace = getDiskSpace(exclude=exclude)

        if diskSpace == -1:
            result = S_ERROR("Could not obtain disk usage")
            self.log.warn(" Could not obtain disk usage")
            result["Value"] = float(-1)
            return result

        result["Value"] = float(diskSpace)
        return result
Example #7
0
class JobAgent(AgentModule):
    """This agent is what runs in a worker node. The pilot runs it, after having prepared its configuration."""
    def __init__(self,
                 agentName,
                 loadName,
                 baseAgentName=False,
                 properties=None):
        """Just defines some default parameters"""
        if not properties:
            properties = {}
        super(JobAgent, self).__init__(agentName, loadName, baseAgentName,
                                       properties)

        # Inner CE
        # CE type the JobAgent submits to. It can be "InProcess" or "Pool" or "Singularity".
        self.ceName = "InProcess"
        # "Inner" CE submission type (e.g. for Pool CE). It can be "InProcess" or "Singularity".
        self.innerCESubmissionType = "InProcess"
        self.computingElement = None  # The ComputingElement object, e.g. SingularityComputingElement()

        # Localsite options
        self.siteName = "Unknown"
        self.pilotReference = "Unknown"
        self.defaultProxyLength = 86400 * 5

        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = 0.0
        self.jobSubmissionDelay = 10
        self.fillingMode = True
        self.minimumTimeLeft = 5000
        self.stopOnApplicationFailure = True
        self.stopAfterFailedMatches = 10
        self.jobCount = 0
        self.matchFailedCount = 0
        self.extraOptions = ""

        # Timeleft
        self.initTimes = os.times()
        self.initTimeLeft = 0.0
        self.timeLeft = self.initTimeLeft
        self.timeLeftUtil = None
        self.pilotInfoReportedFlag = False

    #############################################################################
    def initialize(self):
        """Sets default parameters and creates CE instance"""

        localCE = gConfig.getValue("/LocalSite/LocalCE", self.ceName)
        if localCE != self.ceName:
            self.log.info("Defining Inner CE from local configuration",
                          "= %s" % localCE)

        # Create backend Computing Element
        result = self._initializeComputingElement(localCE)
        if not result["OK"]:
            return result

        result = self._getCEDict(self.computingElement)
        if not result["OK"]:
            return result
        ceDict = result["Value"][0]

        self.initTimeLeft = ceDict.get("CPUTime", self.initTimeLeft)
        self.initTimeLeft = gConfig.getValue(
            "/Resources/Computing/CEDefaults/MaxCPUTime", self.initTimeLeft)
        self.timeLeft = self.initTimeLeft

        self.initTimes = os.times()
        # Localsite options
        self.siteName = siteName()
        self.pilotReference = gConfig.getValue("/LocalSite/PilotReference",
                                               self.pilotReference)
        self.defaultProxyLength = gConfig.getValue(
            "/Registry/DefaultProxyLifeTime", self.defaultProxyLength)
        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = gConfig.getValue("/LocalSite/CPUNormalizationFactor",
                                          self.cpuFactor)
        self.jobSubmissionDelay = self.am_getOption("SubmissionDelay",
                                                    self.jobSubmissionDelay)
        self.fillingMode = self.am_getOption("FillingModeFlag",
                                             self.fillingMode)
        self.minimumTimeLeft = self.am_getOption("MinimumTimeLeft",
                                                 self.minimumTimeLeft)
        self.stopOnApplicationFailure = self.am_getOption(
            "StopOnApplicationFailure", self.stopOnApplicationFailure)
        self.stopAfterFailedMatches = self.am_getOption(
            "StopAfterFailedMatches", self.stopAfterFailedMatches)
        self.extraOptions = gConfig.getValue(
            "/AgentJobRequirements/ExtraOptions", self.extraOptions)
        # Utilities
        self.timeLeftUtil = TimeLeft()
        return S_OK()

    def _initializeComputingElement(self, localCE):
        """Generate a ComputingElement and configure it"""
        ceFactory = ComputingElementFactory()
        self.ceName = localCE.split("/")[
            0]  # It might be "Pool/Singularity", or simply "Pool"
        self.innerCESubmissionType = (localCE.split("/")[1] if len(
            localCE.split("/")) == 2 else self.innerCESubmissionType)
        ceInstance = ceFactory.getCE(self.ceName)
        if not ceInstance["OK"]:
            self.log.warn("Can't instantiate a CE", ceInstance["Message"])
            return ceInstance
        self.computingElement = ceInstance["Value"]
        self.computingElement.setParameters(
            {"InnerCESubmissionType": self.innerCESubmissionType})

        return S_OK()

    #############################################################################
    def execute(self):
        """The JobAgent execution method."""

        # Temporary mechanism to pass a shutdown message to the agent
        if os.path.exists("/var/lib/dirac_drain"):
            return self._finish("Node is being drained by an operator")

        self.log.verbose("Job Agent execution loop")

        # Check that there is enough slots to match a job
        result = self._checkCEAvailability(self.computingElement)
        if not result["OK"]:
            return self._finish(result["Message"])
        if result["OK"] and result["Value"]:
            return result

        # Check that we are allowed to continue and that time left is sufficient
        if self.jobCount:
            cpuWorkLeft = self._computeCPUWorkLeft()
            result = self._checkCPUWorkLeft(cpuWorkLeft)
            if not result["OK"]:
                return result
            result = self._setCPUWorkLeft(cpuWorkLeft)
            if not result["OK"]:
                return result

        # Get environment details and enhance them
        result = self._getCEDict(self.computingElement)
        if not result["OK"]:
            return result
        ceDictList = result["Value"]

        for ceDict in ceDictList:
            self._setCEDict(ceDict)

        # Try to match a job
        jobRequest = self._matchAJob(ceDictList)

        self.stopAfterFailedMatches = self.am_getOption(
            "StopAfterFailedMatches", self.stopAfterFailedMatches)
        if not jobRequest["OK"]:
            res = self._checkMatchingIssues(jobRequest)
            if not res["OK"]:
                self._finish(res["Message"])
                return res

            # if we don't match a job, independently from the reason,
            # we wait a bit longer before trying again
            time.sleep(
                int(self.am_getOption("PollingTime")) *
                (self.matchFailedCount + 1) * 2)
            return res

        # If we are, we matched a job
        # Reset the Counter
        self.matchFailedCount = 0

        # Check matcher information returned
        matcherParams = ["JDL", "DN", "Group"]
        matcherInfo = jobRequest["Value"]
        jobID = matcherInfo["JobID"]
        jobReport = JobReport(jobID, "JobAgent@%s" % self.siteName)
        result = self._checkMatcherInfo(matcherInfo, matcherParams, jobReport)
        if not result["OK"]:
            return self._finish(result["Message"])

        # Get matcher information
        if not self.pilotInfoReportedFlag:
            # Check the flag after the first access to the Matcher
            self.pilotInfoReportedFlag = matcherInfo.get(
                "PilotInfoReportedFlag", False)

        jobJDL = matcherInfo["JDL"]
        jobGroup = matcherInfo["Group"]
        ownerDN = matcherInfo["DN"]
        ceDict = matcherInfo["CEDict"]
        matchTime = matcherInfo["matchTime"]

        optimizerParams = {}
        for key in matcherInfo:
            if key not in matcherParams:
                optimizerParams[key] = matcherInfo[key]

        # Get JDL paramters
        parameters = self._getJDLParameters(jobJDL)
        if not parameters["OK"]:
            jobReport.setJobStatus(
                status=JobStatus.FAILED,
                minorStatus="Could Not Extract JDL Parameters")
            self.log.warn("Could Not Extract JDL Parameters",
                          parameters["Message"])
            return self._finish("JDL Problem")

        params = parameters["Value"]
        result = self._extractValuesFromJobParams(params, jobReport)
        if not result["OK"]:
            return self._finish(result["Value"])
        submissionParams = result["Value"]
        jobID = submissionParams["jobID"]
        jobType = submissionParams["jobType"]

        self.log.verbose("Job request successful: \n", jobRequest["Value"])
        self.log.info(
            "Received", "JobID=%s, JobType=%s, OwnerDN=%s, JobGroup=%s" %
            (jobID, jobType, ownerDN, jobGroup))
        self.jobCount += 1
        try:
            jobReport.setJobParameter(par_name="MatcherServiceTime",
                                      par_value=str(matchTime),
                                      sendFlag=False)

            if "BOINC_JOB_ID" in os.environ:
                # Report BOINC environment
                for thisp in ("BoincUserID", "BoincHostID",
                              "BoincHostPlatform", "BoincHostName"):
                    jobReport.setJobParameter(par_name=thisp,
                                              par_value=gConfig.getValue(
                                                  "/LocalSite/%s" % thisp,
                                                  "Unknown"),
                                              sendFlag=False)

            jobReport.setJobStatus(minorStatus="Job Received by Agent",
                                   sendFlag=False)
            result_setupProxy = self._setupProxy(ownerDN, jobGroup)
            if not result_setupProxy["OK"]:
                result = self._rescheduleFailedJob(
                    jobID, result_setupProxy["Message"])
                return self._finish(result["Message"],
                                    self.stopOnApplicationFailure)
            proxyChain = result_setupProxy.get("Value")

            # Save the job jdl for external monitoring
            self._saveJobJDLRequest(jobID, jobJDL)

            # Check software and install them if required
            software = self._checkInstallSoftware(jobID, params, ceDict,
                                                  jobReport)
            if not software["OK"]:
                self.log.error("Failed to install software for job",
                               "%s" % (jobID))
                errorMsg = software["Message"]
                if not errorMsg:
                    errorMsg = "Failed software installation"
                result = self._rescheduleFailedJob(jobID, errorMsg)
                return self._finish(result["Message"],
                                    self.stopOnApplicationFailure)

            gridCE = gConfig.getValue("/LocalSite/GridCE", "")
            if gridCE:
                jobReport.setJobParameter(par_name="GridCE",
                                          par_value=gridCE,
                                          sendFlag=False)

            queue = gConfig.getValue("/LocalSite/CEQueue", "")
            if queue:
                jobReport.setJobParameter(par_name="CEQueue",
                                          par_value=queue,
                                          sendFlag=False)

            self.log.debug("Before self._submitJob() (%sCE)" % (self.ceName))
            result_submitJob = self._submitJob(
                jobID=jobID,
                jobParams=params,
                resourceParams=ceDict,
                optimizerParams=optimizerParams,
                proxyChain=proxyChain,
                jobReport=jobReport,
                processors=submissionParams["processors"],
                wholeNode=submissionParams["wholeNode"],
                maxNumberOfProcessors=submissionParams[
                    "maxNumberOfProcessors"],
                mpTag=submissionParams["mpTag"],
            )

            # Committing the JobReport before evaluating the result of job submission
            res = jobReport.commit()
            if not res["OK"]:
                resFD = jobReport.generateForwardDISET()
                if not resFD["OK"]:
                    self.log.error("Error generating ForwardDISET operation",
                                   resFD["Message"])
                elif resFD["Value"]:
                    # Here we create the Request.
                    op = resFD["Value"]
                    request = Request()
                    requestName = "jobAgent_%s" % jobID
                    request.RequestName = requestName.replace('"', "")
                    request.JobID = jobID
                    request.SourceComponent = "JobAgent_%s" % jobID
                    request.addOperation(op)
                    # This might fail, but only a message would be printed.
                    self._sendFailoverRequest(request)

            if not result_submitJob["OK"]:
                return self._finish(result_submitJob["Message"])
            elif "PayloadFailed" in result_submitJob:
                # Do not keep running and do not overwrite the Payload error
                message = "Payload execution failed with error code %s" % result_submitJob[
                    "PayloadFailed"]
                if self.stopOnApplicationFailure:
                    return self._finish(message, self.stopOnApplicationFailure)
                else:
                    self.log.info(message)

            self.log.debug("After %sCE submitJob()" % (self.ceName))
        except Exception as subExcept:  # pylint: disable=broad-except
            self.log.exception("Exception in submission",
                               "",
                               lException=subExcept,
                               lExcInfo=True)
            result = self._rescheduleFailedJob(
                jobID, "Job processing failed with exception", direct=True)
            return self._finish(result["Message"],
                                self.stopOnApplicationFailure)

        return S_OK("Job Agent cycle complete")

    #############################################################################
    def _saveJobJDLRequest(self, jobID, jobJDL):
        """Save job JDL local to JobAgent."""
        classAdJob = ClassAd(jobJDL)
        classAdJob.insertAttributeString("LocalCE", self.ceName)
        jdlFileName = jobID + ".jdl"
        jdlFile = open(jdlFileName, "w")
        jdl = classAdJob.asJDL()
        jdlFile.write(jdl)
        jdlFile.close()

    #############################################################################
    def _getCEDict(self, computingElement):
        """Get CE description

        :param ComputingElement computingElement: ComputingElement instance
        :return: list of dict of attributes
        """
        # if we are here we assume that a job can be matched
        result = computingElement.getDescription()
        if not result["OK"]:
            self.log.warn("Can not get the CE description")
            return result

        # We can have several prioritized job retrieval strategies
        if isinstance(result["Value"], dict):
            ceDictList = [result["Value"]]
        else:
            # This is the case for Pool ComputingElement, and parameter 'MultiProcessorStrategy'
            ceDictList = result["Value"]

        return S_OK(ceDictList)

    def _setCEDict(self, ceDict):
        """Set CEDict"""
        # Add pilot information
        gridCE = gConfig.getValue("LocalSite/GridCE", "Unknown")
        if gridCE != "Unknown":
            ceDict["GridCE"] = gridCE
        if "PilotReference" not in ceDict:
            ceDict["PilotReference"] = str(self.pilotReference)
        ceDict["PilotBenchmark"] = self.cpuFactor
        ceDict["PilotInfoReportedFlag"] = self.pilotInfoReportedFlag

        # Add possible job requirements
        result = gConfig.getOptionsDict("/AgentJobRequirements")
        if result["OK"]:
            requirementsDict = result["Value"]
            ceDict.update(requirementsDict)
            self.log.info("Requirements:", requirementsDict)

    def _checkCEAvailability(self, computingElement):
        """Check availability of computingElement"""
        result = computingElement.available()
        if not result["OK"]:
            self.log.info("Resource is not available", result["Message"])
            return S_ERROR("CE Not Available")

        ceInfoDict = result["CEInfoDict"]
        runningJobs = ceInfoDict.get("RunningJobs")
        availableSlots = result["Value"]

        if not availableSlots:
            if runningJobs:
                self.log.info("No available slots",
                              ": %d running jobs" % runningJobs)
                return S_OK("Job Agent cycle complete with %d running jobs" %
                            runningJobs)
            self.log.info(
                "CE is not available (and there are no running jobs)")
            return S_ERROR("CE Not Available")
        return S_OK()

    #############################################################################
    def _computeCPUWorkLeft(self, processors=1):
        """
        Compute CPU Work Left in hepspec06 seconds

        :param int processors: number of processors available
        :return: cpu work left (cpu time left * cpu power of the cpus)
        """
        # Sum all times but the last one (elapsed_time) and remove times at init (is this correct?)
        cpuTimeConsumed = sum(os.times()[:-1]) - sum(self.initTimes[:-1])
        result = self.timeLeftUtil.getTimeLeft(cpuTimeConsumed, processors)
        if not result["OK"]:
            self.log.warn(
                "There were errors calculating time left using the Timeleft utility",
                result["Message"])
            self.log.warn(
                "The time left will be calculated using os.times() and the info in our possession"
            )
            self.log.info("Current raw CPU time consumed is %s" %
                          cpuTimeConsumed)
            if self.cpuFactor:
                return self.initTimeLeft - cpuTimeConsumed * self.cpuFactor
            return self.timeLeft
        return result["Value"]

    def _checkCPUWorkLeft(self, cpuWorkLeft):
        """Check that fillingMode is enabled and time left is sufficient to continue the execution"""
        # Only call timeLeft utility after a job has been picked up
        self.log.info("Attempting to check CPU time left for filling mode")
        if not self.fillingMode:
            return self._finish("Filling Mode is Disabled")

        self.log.info("normalized CPU units remaining in slot", cpuWorkLeft)
        if cpuWorkLeft <= self.minimumTimeLeft:
            return self._finish("No more time left")
        return S_OK()

    def _setCPUWorkLeft(self, cpuWorkLeft):
        """Update the TimeLeft within the CE and the configuration for next matching request"""
        self.timeLeft = cpuWorkLeft

        result = self.computingElement.setCPUTimeLeft(
            cpuTimeLeft=self.timeLeft)
        if not result["OK"]:
            return self._finish(result["Message"])

        self._updateConfiguration("CPUTimeLeft", self.timeLeft)
        return S_OK()

    #############################################################################
    def _updateConfiguration(self, key, value, path="/LocalSite"):
        """Update local configuration to be used by submitted job wrappers"""
        localCfg = CFG()
        if self.extraOptions:
            localConfigFile = os.path.join(".", self.extraOptions)
        else:
            localConfigFile = os.path.join(rootPath, "etc", "dirac.cfg")
        localCfg.loadFromFile(localConfigFile)

        section = "/"
        for p in path.split("/")[1:]:
            section = os.path.join(section, p)
            if not localCfg.isSection(section):
                localCfg.createNewSection(section)

        localCfg.setOption("%s/%s" % (section, key), value)
        localCfg.writeToFile(localConfigFile)

    #############################################################################
    def _setupProxy(self, ownerDN, ownerGroup):
        """
        Retrieve a proxy for the execution of the job
        """
        if gConfig.getValue("/DIRAC/Security/UseServerCertificate", False):
            proxyResult = self._requestProxyFromProxyManager(
                ownerDN, ownerGroup)
            if not proxyResult["OK"]:
                self.log.error("Failed to setup proxy", proxyResult["Message"])
                return S_ERROR("Failed to setup proxy: %s" %
                               proxyResult["Message"])
            return S_OK(proxyResult["Value"])
        else:
            ret = getProxyInfo(disableVOMS=True)
            if not ret["OK"]:
                self.log.error("Invalid Proxy", ret["Message"])
                return S_ERROR("Invalid Proxy")

            proxyChain = ret["Value"]["chain"]
            if "groupProperties" not in ret["Value"]:
                print(ret["Value"])
                print(proxyChain.dumpAllToString())
                self.log.error("Invalid Proxy",
                               "Group has no properties defined")
                return S_ERROR("Proxy has no group properties defined")

            groupProps = ret["Value"]["groupProperties"]
            if Properties.GENERIC_PILOT in groupProps or Properties.PILOT in groupProps:
                proxyResult = self._requestProxyFromProxyManager(
                    ownerDN, ownerGroup)
                if not proxyResult["OK"]:
                    self.log.error("Invalid Proxy", proxyResult["Message"])
                    return S_ERROR("Failed to setup proxy: %s" %
                                   proxyResult["Message"])
                proxyChain = proxyResult["Value"]

        return S_OK(proxyChain)

    def _requestProxyFromProxyManager(self, ownerDN, ownerGroup):
        """Retrieves user proxy with correct role for job and sets up environment to
        run job locally.
        """

        self.log.info("Requesting proxy', 'for %s@%s" % (ownerDN, ownerGroup))
        token = gConfig.getValue("/Security/ProxyToken", "")
        if not token:
            self.log.verbose(
                "No token defined. Trying to download proxy without token")
            token = False
        retVal = gProxyManager.getPayloadProxyFromDIRACGroup(
            ownerDN, ownerGroup, self.defaultProxyLength, token)
        if not retVal["OK"]:
            self.log.error("Could not retrieve payload proxy",
                           retVal["Message"])
            os.system("dirac-proxy-info")
            sys.stdout.flush()
            return S_ERROR("Error retrieving proxy")

        chain = retVal["Value"]
        return S_OK(chain)

    #############################################################################
    def _checkInstallSoftware(self, jobID, jobParams, resourceParams,
                              jobReport):
        """Checks software requirement of job and whether this is already present
        before installing software locally.
        """
        if "SoftwareDistModule" not in jobParams:
            msg = "Job has no software installation requirement"
            self.log.verbose(msg)
            return S_OK(msg)

        jobReport.setJobStatus(minorStatus="Installing Software",
                               sendFlag=False)
        softwareDist = jobParams["SoftwareDistModule"]
        self.log.verbose("Found VO Software Distribution module",
                         ": %s" % (softwareDist))
        argumentsDict = {"Job": jobParams, "CE": resourceParams}
        moduleFactory = ModuleFactory()
        moduleInstance = moduleFactory.getModule(softwareDist, argumentsDict)
        if not moduleInstance["OK"]:
            return moduleInstance

        module = moduleInstance["Value"]
        return module.execute()

    #############################################################################
    def _matchAJob(self, ceDictList):
        """Call the Matcher with each ceDict until we get a job"""
        jobRequest = S_ERROR("No CE Dictionary available")
        for ceDict in ceDictList:
            self.log.verbose("CE dict", ceDict)

            start = time.time()
            jobRequest = MatcherClient().requestJob(ceDict)
            matchTime = time.time() - start

            self.log.info("MatcherTime", "= %.2f (s)" % (matchTime))
            if jobRequest["OK"]:
                jobRequest["Value"]["matchTime"] = matchTime
                jobRequest["Value"]["CEDict"] = ceDict
                break
        return jobRequest

    def _checkMatchingIssues(self, jobRequest):
        """Check the source of the matching issue

        :param dict jobRequest: S_ERROR returned by the matcher
        :return: S_OK/S_ERROR
        """
        if DErrno.cmpError(jobRequest, DErrno.EWMSPLTVER):
            self.log.error("Pilot version mismatch", jobRequest["Message"])
            return jobRequest

        if DErrno.cmpError(jobRequest, DErrno.EWMSNOMATCH):
            self.log.notice("Job request OK, but no match found",
                            jobRequest["Message"])
        elif jobRequest["Message"].find("seconds timeout") != -1:
            self.log.error("Timeout while requesting job",
                           jobRequest["Message"])
        else:
            self.log.notice("Failed to get jobs", jobRequest["Message"])

        self.matchFailedCount += 1
        if self.matchFailedCount > self.stopAfterFailedMatches:
            return self._finish("Nothing to do for more than %d cycles" %
                                self.stopAfterFailedMatches)
        return S_OK()

    def _checkMatcherInfo(self, matcherInfo, matcherParams, jobReport):
        """Check that all relevant information about the job are available"""
        for param in matcherParams:
            if param not in matcherInfo:
                jobReport.setJobStatus(
                    status=JobStatus.FAILED,
                    minorStatus="Matcher did not return %s" % (param))
                return S_ERROR("Matcher Failed")

            if not matcherInfo[param]:
                jobReport.setJobStatus(status=JobStatus.FAILED,
                                       minorStatus="Matcher returned null %s" %
                                       (param))
                return S_ERROR("Matcher Failed")

            self.log.verbose("Matcher returned",
                             "%s = %s " % (param, matcherInfo[param]))
        return S_OK()

    #############################################################################
    def _submitJob(
        self,
        jobID,
        jobParams,
        resourceParams,
        optimizerParams,
        proxyChain,
        jobReport,
        processors=1,
        wholeNode=False,
        maxNumberOfProcessors=0,
        mpTag=False,
    ):
        """Submit job to the Computing Element instance after creating a custom
        Job Wrapper with the available job parameters.
        """
        logLevel = self.am_getOption("DefaultLogLevel", "INFO")
        defaultWrapperLocation = self.am_getOption(
            "JobWrapperTemplate",
            "DIRAC/WorkloadManagementSystem/JobWrapper/JobWrapperTemplate.py")

        # Add the number of requested processors to the job environment
        if "ExecutionEnvironment" in jobParams:
            if isinstance(jobParams["ExecutionEnvironment"], six.string_types):
                jobParams["ExecutionEnvironment"] = jobParams[
                    "ExecutionEnvironment"].split(";")
        jobParams.setdefault("ExecutionEnvironment",
                             []).append("DIRAC_JOB_PROCESSORS=%d" % processors)

        jobDesc = {
            "jobID": jobID,
            "jobParams": jobParams,
            "resourceParams": resourceParams,
            "optimizerParams": optimizerParams,
            "extraOptions": self.extraOptions,
            "defaultWrapperLocation": defaultWrapperLocation,
        }
        result = createJobWrapper(log=self.log, logLevel=logLevel, **jobDesc)
        if not result["OK"]:
            return result

        wrapperFile = result["Value"][0]
        inputs = list(result["Value"][1:])
        jobReport.setJobStatus(minorStatus="Submitting To CE")

        self.log.info(
            "Submitting JobWrapper",
            "%s to %sCE" % (os.path.basename(wrapperFile), self.ceName))

        # Pass proxy to the CE
        proxy = proxyChain.dumpAllToString()
        if not proxy["OK"]:
            self.log.error("Invalid proxy", proxy)
            return S_ERROR("Payload Proxy Not Found")

        payloadProxy = proxy["Value"]
        submission = self.computingElement.submitJob(
            wrapperFile,
            payloadProxy,
            numberOfProcessors=processors,
            maxNumberOfProcessors=maxNumberOfProcessors,
            wholeNode=wholeNode,
            mpTag=mpTag,
            jobDesc=jobDesc,
            log=self.log,
            logLevel=logLevel,
            inputs=inputs,
        )
        submissionResult = S_OK("Job submitted")

        if submission["OK"]:
            batchID = submission["Value"]
            self.log.info("Job submitted",
                          "(DIRAC JobID: %s; Batch ID: %s" % (jobID, batchID))
            if "PayloadFailed" in submission:
                submissionResult["PayloadFailed"] = submission["PayloadFailed"]
            time.sleep(self.jobSubmissionDelay)
        else:
            self.log.error("Job submission failed", jobID)
            jobReport.setJobParameter(par_name="ErrorMessage",
                                      par_value="%s CE Submission Error" %
                                      (self.ceName),
                                      sendFlag=False)
            if "ReschedulePayload" in submission:
                result = self._rescheduleFailedJob(jobID,
                                                   submission["Message"])
                self._finish(result["Message"], self.stopOnApplicationFailure)
                return S_OK()  # Without this, the job is marked as failed
            else:
                if "Value" in submission:  # yes, it's "correct", S_ERROR with 'Value' key
                    self.log.error(
                        "Error in DIRAC JobWrapper or inner CE execution:",
                        "exit code = %s" % (str(submission["Value"])),
                    )
            self.log.error("CE Error",
                           "%s : %s" % (self.ceName, submission["Message"]))
            submissionResult = submission

        return submissionResult

    #############################################################################
    def _getJDLParameters(self, jdl):
        """Returns a dictionary of JDL parameters."""
        try:
            parameters = {}
            #      print jdl
            if not re.search(r"\[", jdl):
                jdl = "[" + jdl + "]"
            classAdJob = ClassAd(jdl)
            paramsDict = classAdJob.contents
            for param, value in paramsDict.items():
                if value.strip().startswith("{"):
                    self.log.debug("Found list type parameter %s" % (param))
                    rawValues = value.replace("{",
                                              "").replace("}", "").replace(
                                                  '"', "").split()
                    valueList = []
                    for val in rawValues:
                        if re.search(",$", val):
                            valueList.append(val[:-1])
                        else:
                            valueList.append(val)
                    parameters[param] = valueList
                else:
                    parameters[param] = value.replace('"', "").replace(
                        "{", '"{').replace("}", '}"')
                    self.log.debug("Found standard parameter %s: %s" %
                                   (param, parameters[param]))
            return S_OK(parameters)
        except Exception as x:
            self.log.exception(lException=x)
            return S_ERROR("Exception while extracting JDL parameters for job")

    def _extractValuesFromJobParams(self, params, jobReport):
        """Extract values related to the job from the job parameter dictionary"""
        submissionDict = {}

        submissionDict["jobID"] = params.get("JobID")
        if not submissionDict["jobID"]:
            msg = "Job has not JobID defined in JDL parameters"
            jobReport.setJobStatus(status=JobStatus.FAILED, minorStatus=msg)
            self.log.warn(msg)
            return S_ERROR("JDL Problem")

        submissionDict["jobType"] = params.get("JobType", "Unknown")
        if submissionDict["jobType"] == "Unknown":
            self.log.warn("Job has no JobType defined in JDL parameters")

        if "CPUTime" not in params:
            self.log.warn(
                "Job has no CPU requirement defined in JDL parameters")

        # Job requirements for determining the number of processors
        # the minimum number of processors requested
        submissionDict["processors"] = int(
            params.get("NumberOfProcessors",
                       int(params.get("MinNumberOfProcessors", 1))))
        # the maximum number of processors allowed to the payload
        submissionDict["maxNumberOfProcessors"] = int(
            params.get("MaxNumberOfProcessors", 0))
        # need or not the whole node for the job
        submissionDict["wholeNode"] = "WholeNode" in params
        submissionDict["mpTag"] = "MultiProcessor" in params.get("Tags", [])

        if self.extraOptions and "dirac-jobexec" in params.get(
                "Executable", "").strip():
            params["Arguments"] = (params.get("Arguments", "") + " " +
                                   self.extraOptions).strip()
            params["ExtraOptions"] = self.extraOptions

        return S_OK(submissionDict)

    #############################################################################
    def _finish(self, message, stop=True):
        """Force the JobAgent to complete gracefully."""
        if stop:
            self.log.info("JobAgent will stop",
                          'with message "%s", execution complete.' % message)
            self.am_stopExecution()
            return S_ERROR(message)

        return S_OK(message)

    #############################################################################
    def _rescheduleFailedJob(self, jobID, message, direct=False):
        """
        Set Job Status to "Rescheduled" and issue a reschedule command to the Job Manager
        """

        self.log.warn("Failure ==> rescheduling", "(during %s)" % (message))

        if direct:
            JobStateUpdateClient().setJobStatus(int(jobID),
                                                status=JobStatus.RESCHEDULED,
                                                applicationStatus=message,
                                                source="JobAgent@%s",
                                                force=True)
        else:
            jobReport = JobReport(int(jobID), "JobAgent@%s" % self.siteName)
            # Setting a job parameter does not help since the job will be rescheduled,
            # instead set the status with the cause and then another status showing the
            # reschedule operation.
            jobReport.setJobStatus(status=JobStatus.RESCHEDULED,
                                   applicationStatus=message,
                                   sendFlag=True)

        self.log.info("Job will be rescheduled")
        result = JobManagerClient().rescheduleJob(jobID)
        if not result["OK"]:
            self.log.error("Failed to reschedule job", result["Message"])
            return S_ERROR("Problem Rescheduling Job")

        self.log.info("Job Rescheduled", jobID)
        return S_ERROR("Job Rescheduled")

    #############################################################################
    def _sendFailoverRequest(self, request):
        """Send failover reques per Job.
        This request would basically be a DISET request for setting the job status.

        If this fails, it only prints a message.

        :param Request request: Request() object
        :return: None
        """
        if len(request):
            self.log.info("Trying to send the failover request")
            # The request is ready, send it now
            isValid = RequestValidator().validate(request)
            if not isValid["OK"]:
                self.log.error("Failover request is not valid",
                               isValid["Message"])
                self.log.error("Printing out the content of the request")
                reqToJSON = request.toJSON()
                if reqToJSON["OK"]:
                    print(str(reqToJSON["Value"]))
                else:
                    self.log.error(
                        "Something went wrong creating the JSON from request",
                        reqToJSON["Message"])
            else:
                # Now trying to send the request
                requestClient = ReqClient()
                result = requestClient.putRequest(request)
                if not result["OK"]:
                    self.log.error("Failed to set failover request",
                                   result["Message"])

    def finalize(self):
        """Job Agent finalization method"""

        # wait for all jobs to be completed
        res = self.computingElement.shutdown()
        if not res["OK"]:
            self.log.error("CE could not be properly shut down",
                           res["Message"])
        elif res["Value"]:
            self.log.info("Job submission(s) result", res["Value"])

        gridCE = gConfig.getValue("/LocalSite/GridCE", "")
        queue = gConfig.getValue("/LocalSite/CEQueue", "")
        result = PilotManagerClient().setPilotStatus(str(self.pilotReference),
                                                     PilotStatus.DONE, gridCE,
                                                     "Report from JobAgent",
                                                     self.siteName, queue)
        if not result["OK"]:
            self.log.warn("Issue setting the pilot status", result["Message"])

        return S_OK()
Example #8
0
    def initialize(self, loops=0):
        """Sets default parameters and creates CE instance
    """
        # Disable monitoring, logLevel INFO, limited cycles
        self.am_setOption('MonitoringEnabled', False)
        self.am_setOption('MaxCycles', loops)

        ceType = self.am_getOption('CEType', self.ceName)
        localCE = gConfig.getValue('/LocalSite/LocalCE', '')
        if localCE:
            self.log.info('Defining CE from local configuration',
                          '= %s' % localCE)
            ceType = localCE

        # Create backend Computing Element
        ceFactory = ComputingElementFactory()
        self.ceName = ceType
        ceInstance = ceFactory.getCE(ceType)
        if not ceInstance['OK']:
            self.log.warn("Can't instantiate a CE", ceInstance['Message'])
            return ceInstance
        self.computingElement = ceInstance['Value']

        result = self.computingElement.getDescription()
        if not result['OK']:
            self.log.warn("Can not get the CE description")
            return result
        if isinstance(result['Value'], list):
            ceDict = result['Value'][0]
        else:
            ceDict = result['Value']
        self.timeLeft = ceDict.get('CPUTime', self.timeLeft)
        self.timeLeft = gConfig.getValue(
            '/Resources/Computing/CEDefaults/MaxCPUTime', self.timeLeft)

        self.initTimes = os.times()
        # Localsite options
        self.siteName = gConfig.getValue('/LocalSite/Site', self.siteName)
        self.pilotReference = gConfig.getValue('/LocalSite/PilotReference',
                                               self.pilotReference)
        self.defaultProxyLength = gConfig.getValue(
            '/Registry/DefaultProxyLifeTime', self.defaultProxyLength)
        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = gConfig.getValue('/LocalSite/CPUNormalizationFactor',
                                          self.cpuFactor)
        self.jobSubmissionDelay = self.am_getOption('SubmissionDelay',
                                                    self.jobSubmissionDelay)
        self.fillingMode = self.am_getOption('FillingModeFlag',
                                             self.fillingMode)
        self.minimumTimeLeft = self.am_getOption('MinimumTimeLeft',
                                                 self.minimumTimeLeft)
        self.stopOnApplicationFailure = self.am_getOption(
            'StopOnApplicationFailure', self.stopOnApplicationFailure)
        self.stopAfterFailedMatches = self.am_getOption(
            'StopAfterFailedMatches', self.stopAfterFailedMatches)
        self.extraOptions = gConfig.getValue(
            '/AgentJobRequirements/ExtraOptions', self.extraOptions)
        # Timeleft
        self.timeLeftUtil = TimeLeft()
        return S_OK()
Example #9
0
class JobAgent(AgentModule):
    """ This agent is what runs in a worker node. The pilot runs it, after having prepared its configuration.
  """
    def __init__(self,
                 agentName,
                 loadName,
                 baseAgentName=False,
                 properties=None):
        """ Just defines some default parameters
    """
        if not properties:
            properties = {}
        super(JobAgent, self).__init__(agentName, loadName, baseAgentName,
                                       properties)

        self.ceName = 'InProcess'
        self.computingElement = None
        self.timeLeft = 0.0

        self.initTimes = os.times()
        # Localsite options
        self.siteName = 'Unknown'
        self.pilotReference = 'Unknown'
        self.defaultProxyLength = 86400 * 5
        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = 0.0
        self.jobSubmissionDelay = 10
        self.fillingMode = False
        self.minimumTimeLeft = 1000
        self.stopOnApplicationFailure = True
        self.stopAfterFailedMatches = 10
        self.jobCount = 0
        self.matchFailedCount = 0
        self.extraOptions = ''
        # Timeleft
        self.timeLeftUtil = None
        self.timeLeftError = ''
        self.pilotInfoReportedFlag = False

    #############################################################################
    def initialize(self, loops=0):
        """Sets default parameters and creates CE instance
    """
        # Disable monitoring, logLevel INFO, limited cycles
        self.am_setOption('MonitoringEnabled', False)
        self.am_setOption('MaxCycles', loops)

        ceType = self.am_getOption('CEType', self.ceName)
        localCE = gConfig.getValue('/LocalSite/LocalCE', '')
        if localCE:
            self.log.info('Defining CE from local configuration',
                          '= %s' % localCE)
            ceType = localCE

        # Create backend Computing Element
        ceFactory = ComputingElementFactory()
        self.ceName = ceType
        ceInstance = ceFactory.getCE(ceType)
        if not ceInstance['OK']:
            self.log.warn("Can't instantiate a CE", ceInstance['Message'])
            return ceInstance
        self.computingElement = ceInstance['Value']

        result = self.computingElement.getDescription()
        if not result['OK']:
            self.log.warn("Can not get the CE description")
            return result
        if isinstance(result['Value'], list):
            ceDict = result['Value'][0]
        else:
            ceDict = result['Value']
        self.timeLeft = ceDict.get('CPUTime', self.timeLeft)
        self.timeLeft = gConfig.getValue(
            '/Resources/Computing/CEDefaults/MaxCPUTime', self.timeLeft)

        self.initTimes = os.times()
        # Localsite options
        self.siteName = gConfig.getValue('/LocalSite/Site', self.siteName)
        self.pilotReference = gConfig.getValue('/LocalSite/PilotReference',
                                               self.pilotReference)
        self.defaultProxyLength = gConfig.getValue(
            '/Registry/DefaultProxyLifeTime', self.defaultProxyLength)
        # Agent options
        # This is the factor to convert raw CPU to Normalized units (based on the CPU Model)
        self.cpuFactor = gConfig.getValue('/LocalSite/CPUNormalizationFactor',
                                          self.cpuFactor)
        self.jobSubmissionDelay = self.am_getOption('SubmissionDelay',
                                                    self.jobSubmissionDelay)
        self.fillingMode = self.am_getOption('FillingModeFlag',
                                             self.fillingMode)
        self.minimumTimeLeft = self.am_getOption('MinimumTimeLeft',
                                                 self.minimumTimeLeft)
        self.stopOnApplicationFailure = self.am_getOption(
            'StopOnApplicationFailure', self.stopOnApplicationFailure)
        self.stopAfterFailedMatches = self.am_getOption(
            'StopAfterFailedMatches', self.stopAfterFailedMatches)
        self.extraOptions = gConfig.getValue(
            '/AgentJobRequirements/ExtraOptions', self.extraOptions)
        # Timeleft
        self.timeLeftUtil = TimeLeft()
        return S_OK()

    #############################################################################
    def execute(self):
        """The JobAgent execution method.
    """
        if self.jobCount:
            # Temporary mechanism to pass a shutdown message to the agent
            if os.path.exists('/var/lib/dirac_drain'):
                return self.__finish('Node is being drained by an operator')
            # Only call timeLeft utility after a job has been picked up
            self.log.info('Attempting to check CPU time left for filling mode')
            if self.fillingMode:
                if self.timeLeftError:
                    self.log.warn(
                        "Disabling filling mode as errors calculating time left",
                        self.timeLeftError)
                    return self.__finish(self.timeLeftError)
                self.log.info('normalized CPU units remaining in slot',
                              self.timeLeft)
                if self.timeLeft <= self.minimumTimeLeft:
                    return self.__finish('No more time left')
                # Need to update the Configuration so that the new value is published in the next matching request
                result = self.computingElement.setCPUTimeLeft(
                    cpuTimeLeft=self.timeLeft)
                if not result['OK']:
                    return self.__finish(result['Message'])

                # Update local configuration to be used by submitted job wrappers
                localCfg = CFG()
                if self.extraOptions:
                    localConfigFile = os.path.join('.', self.extraOptions)
                else:
                    localConfigFile = os.path.join(rootPath, "etc",
                                                   "dirac.cfg")
                localCfg.loadFromFile(localConfigFile)
                if not localCfg.isSection('/LocalSite'):
                    localCfg.createNewSection('/LocalSite')
                localCfg.setOption('/LocalSite/CPUTimeLeft', self.timeLeft)
                localCfg.writeToFile(localConfigFile)

            else:
                return self.__finish('Filling Mode is Disabled')

        self.log.verbose('Job Agent execution loop')
        result = self.computingElement.available()
        if not result['OK']:
            self.log.info('Resource is not available', result['Message'])
            return self.__finish('CE Not Available')

        ceInfoDict = result['CEInfoDict']
        runningJobs = ceInfoDict.get("RunningJobs")
        availableSlots = result['Value']

        if not availableSlots:
            if runningJobs:
                self.log.info('No available slots',
                              '%d running jobs' % runningJobs)
                return S_OK('Job Agent cycle complete with %d running jobs' %
                            runningJobs)
            else:
                self.log.info('CE is not available')
                return self.__finish('CE Not Available')

        result = self.computingElement.getDescription()
        if not result['OK']:
            return result

        # We can have several prioritized job retrieval strategies
        if isinstance(result['Value'], dict):
            ceDictList = [result['Value']]
        elif isinstance(result['Value'], list):
            # This is the case for Pool ComputingElement, and parameter 'MultiProcessorStrategy'
            ceDictList = result['Value']

        for ceDict in ceDictList:

            # Add pilot information
            gridCE = gConfig.getValue('LocalSite/GridCE', 'Unknown')
            if gridCE != 'Unknown':
                ceDict['GridCE'] = gridCE
            if 'PilotReference' not in ceDict:
                ceDict['PilotReference'] = str(self.pilotReference)
            ceDict['PilotBenchmark'] = self.cpuFactor
            ceDict['PilotInfoReportedFlag'] = self.pilotInfoReportedFlag

            # Add possible job requirements
            result = gConfig.getOptionsDict('/AgentJobRequirements')
            if result['OK']:
                requirementsDict = result['Value']
                ceDict.update(requirementsDict)
                self.log.info('Requirements:', requirementsDict)

            self.log.verbose('CE dict', ceDict)

            # here finally calling the matcher
            start = time.time()
            jobRequest = MatcherClient().requestJob(ceDict)
            matchTime = time.time() - start
            self.log.info('MatcherTime', '= %.2f (s)' % (matchTime))
            if jobRequest['OK']:
                break

        self.stopAfterFailedMatches = self.am_getOption(
            'StopAfterFailedMatches', self.stopAfterFailedMatches)

        if not jobRequest['OK']:
            if re.search('No match found', jobRequest['Message']):
                self.log.notice('Job request OK, but no match found',
                                ': %s' % (jobRequest['Message']))
                self.matchFailedCount += 1
                if self.matchFailedCount > self.stopAfterFailedMatches:
                    return self.__finish(
                        'Nothing to do for more than %d cycles' %
                        self.stopAfterFailedMatches)
                return S_OK(jobRequest['Message'])
            elif jobRequest['Message'].find("seconds timeout") != -1:
                self.log.error('Timeout while requesting job',
                               jobRequest['Message'])
                self.matchFailedCount += 1
                if self.matchFailedCount > self.stopAfterFailedMatches:
                    return self.__finish(
                        'Nothing to do for more than %d cycles' %
                        self.stopAfterFailedMatches)
                return S_OK(jobRequest['Message'])
            elif jobRequest['Message'].find(
                    "Pilot version does not match") != -1:
                errorMsg = 'Pilot version does not match the production version'
                self.log.error(errorMsg,
                               jobRequest['Message'].replace(errorMsg, ''))
                return S_ERROR(jobRequest['Message'])
            else:
                self.log.notice('Failed to get jobs',
                                ': %s' % (jobRequest['Message']))
                self.matchFailedCount += 1
                if self.matchFailedCount > self.stopAfterFailedMatches:
                    return self.__finish(
                        'Nothing to do for more than %d cycles' %
                        self.stopAfterFailedMatches)
                return S_OK(jobRequest['Message'])

        # Reset the Counter
        self.matchFailedCount = 0

        matcherInfo = jobRequest['Value']
        if not self.pilotInfoReportedFlag:
            # Check the flag after the first access to the Matcher
            self.pilotInfoReportedFlag = matcherInfo.get(
                'PilotInfoReportedFlag', False)
        jobID = matcherInfo['JobID']
        matcherParams = ['JDL', 'DN', 'Group']
        for param in matcherParams:
            if param not in matcherInfo:
                self.__report(jobID, 'Failed',
                              'Matcher did not return %s' % (param))
                return self.__finish('Matcher Failed')
            elif not matcherInfo[param]:
                self.__report(jobID, 'Failed',
                              'Matcher returned null %s' % (param))
                return self.__finish('Matcher Failed')
            else:
                self.log.verbose('Matcher returned',
                                 '%s = %s ' % (param, matcherInfo[param]))

        jobJDL = matcherInfo['JDL']
        jobGroup = matcherInfo['Group']
        ownerDN = matcherInfo['DN']

        optimizerParams = {}
        for key in matcherInfo:
            if key not in matcherParams:
                optimizerParams[key] = matcherInfo[key]

        parameters = self._getJDLParameters(jobJDL)
        if not parameters['OK']:
            self.__report(jobID, 'Failed', 'Could Not Extract JDL Parameters')
            self.log.warn('Could Not Extract JDL Parameters',
                          parameters['Message'])
            return self.__finish('JDL Problem')

        params = parameters['Value']
        if 'JobID' not in params:
            msg = 'Job has not JobID defined in JDL parameters'
            self.__report(jobID, 'Failed', msg)
            self.log.warn(msg)
            return self.__finish('JDL Problem')
        else:
            jobID = params['JobID']

        if 'JobType' not in params:
            self.log.warn('Job has no JobType defined in JDL parameters')
            jobType = 'Unknown'
        else:
            jobType = params['JobType']

        if 'CPUTime' not in params:
            self.log.warn(
                'Job has no CPU requirement defined in JDL parameters')

        # Job requirements for determining the number of processors
        # the minimum number of processors requested
        processors = int(
            params.get('NumberOfProcessors',
                       int(params.get('MinNumberOfProcessors', 1))))
        # the maximum number of processors allowed to the payload
        maxNumberOfProcessors = int(params.get('MaxNumberOfProcessors', 0))
        # need or not the whole node for the job
        wholeNode = 'WholeNode' in params
        mpTag = 'MultiProcessor' in params.get('Tags', [])

        if self.extraOptions:
            params['Arguments'] += ' ' + self.extraOptions
            params['ExtraOptions'] = self.extraOptions

        self.log.verbose('Job request successful: \n', jobRequest['Value'])
        self.log.info(
            'Received', 'JobID=%s, JobType=%s, OwnerDN=%s, JobGroup=%s' %
            (jobID, jobType, ownerDN, jobGroup))
        self.jobCount += 1
        try:
            jobReport = JobReport(jobID, 'JobAgent@%s' % self.siteName)
            jobReport.setJobParameter('MatcherServiceTime',
                                      str(matchTime),
                                      sendFlag=False)

            if 'BOINC_JOB_ID' in os.environ:
                # Report BOINC environment
                for thisp in ('BoincUserID', 'BoincHostID',
                              'BoincHostPlatform', 'BoincHostName'):
                    jobReport.setJobParameter(thisp,
                                              gConfig.getValue(
                                                  '/LocalSite/%s' % thisp,
                                                  'Unknown'),
                                              sendFlag=False)

            jobReport.setJobStatus('Matched', 'Job Received by Agent')
            result = self._setupProxy(ownerDN, jobGroup)
            if not result['OK']:
                return self._rescheduleFailedJob(jobID, result['Message'],
                                                 self.stopOnApplicationFailure)
            proxyChain = result.get('Value')

            # Save the job jdl for external monitoring
            self.__saveJobJDLRequest(jobID, jobJDL)

            software = self._checkInstallSoftware(jobID, params, ceDict)
            if not software['OK']:
                self.log.error('Failed to install software for job',
                               '%s' % (jobID))
                errorMsg = software['Message']
                if not errorMsg:
                    errorMsg = 'Failed software installation'
                return self._rescheduleFailedJob(jobID, errorMsg,
                                                 self.stopOnApplicationFailure)

            self.log.debug('Before self._submitJob() (%sCE)' % (self.ceName))
            result = self._submitJob(jobID, params, ceDict, optimizerParams,
                                     proxyChain, processors, wholeNode,
                                     maxNumberOfProcessors, mpTag)
            if not result['OK']:
                self.__report(jobID, 'Failed', result['Message'])
                return self.__finish(result['Message'])
            elif 'PayloadFailed' in result:
                # Do not keep running and do not overwrite the Payload error
                message = 'Payload execution failed with error code %s' % result[
                    'PayloadFailed']
                if self.stopOnApplicationFailure:
                    return self.__finish(message,
                                         self.stopOnApplicationFailure)
                else:
                    self.log.info(message)

            self.log.debug('After %sCE submitJob()' % (self.ceName))
        except Exception as subExcept:  # pylint: disable=broad-except
            self.log.exception("Exception in submission",
                               "",
                               lException=subExcept,
                               lExcInfo=True)
            return self._rescheduleFailedJob(
                jobID, 'Job processing failed with exception',
                self.stopOnApplicationFailure)

        # Sum all times but the last one (elapsed_time) and remove times at init (is this correct?)
        cpuTime = sum(os.times()[:-1]) - sum(self.initTimes[:-1])

        result = self.timeLeftUtil.getTimeLeft(cpuTime, processors)
        if result['OK']:
            self.timeLeft = result['Value']
        else:
            if result['Message'] != 'Current batch system is not supported':
                self.timeLeftError = result['Message']
            else:
                # if the batch system is not defined, use the process time and the CPU normalization defined locally
                self.timeLeft = self._getCPUTimeLeft()

        return S_OK('Job Agent cycle complete')

    #############################################################################
    def __saveJobJDLRequest(self, jobID, jobJDL):
        """Save job JDL local to JobAgent.
    """
        classAdJob = ClassAd(jobJDL)
        classAdJob.insertAttributeString('LocalCE', self.ceName)
        jdlFileName = jobID + '.jdl'
        jdlFile = open(jdlFileName, 'w')
        jdl = classAdJob.asJDL()
        jdlFile.write(jdl)
        jdlFile.close()

    #############################################################################
    def _getCPUTimeLeft(self):
        """Return the TimeLeft as estimated by DIRAC using the Normalization Factor in the Local Config.
    """
        cpuTime = sum(os.times()[:-1])
        self.log.info('Current raw CPU time consumed is %s' % cpuTime)
        timeleft = self.timeLeft
        if self.cpuFactor:
            timeleft -= cpuTime * self.cpuFactor
        return timeleft

    #############################################################################
    def _setupProxy(self, ownerDN, ownerGroup):
        """
    Retrieve a proxy for the execution of the job
    """
        if gConfig.getValue('/DIRAC/Security/UseServerCertificate', False):
            proxyResult = self._requestProxyFromProxyManager(
                ownerDN, ownerGroup)
            if not proxyResult['OK']:
                self.log.error('Failed to setup proxy', proxyResult['Message'])
                return S_ERROR('Failed to setup proxy: %s' %
                               proxyResult['Message'])
            return S_OK(proxyResult['Value'])
        else:
            ret = getProxyInfo(disableVOMS=True)
            if not ret['OK']:
                self.log.error('Invalid Proxy', ret['Message'])
                return S_ERROR('Invalid Proxy')

            proxyChain = ret['Value']['chain']
            if 'groupProperties' not in ret['Value']:
                print(ret['Value'])
                print(proxyChain.dumpAllToString())
                self.log.error('Invalid Proxy',
                               'Group has no properties defined')
                return S_ERROR('Proxy has no group properties defined')

            groupProps = ret['Value']['groupProperties']
            if Properties.GENERIC_PILOT in groupProps or Properties.PILOT in groupProps:
                proxyResult = self._requestProxyFromProxyManager(
                    ownerDN, ownerGroup)
                if not proxyResult['OK']:
                    self.log.error('Invalid Proxy', proxyResult['Message'])
                    return S_ERROR('Failed to setup proxy: %s' %
                                   proxyResult['Message'])
                proxyChain = proxyResult['Value']

        return S_OK(proxyChain)

    #############################################################################
    def _requestProxyFromProxyManager(self, ownerDN, ownerGroup):
        """Retrieves user proxy with correct role for job and sets up environment to
       run job locally.
    """

        self.log.info("Requesting proxy', 'for %s@%s" % (ownerDN, ownerGroup))
        token = gConfig.getValue("/Security/ProxyToken", "")
        if not token:
            self.log.info(
                "No token defined. Trying to download proxy without token")
            token = False
        retVal = gProxyManager.getPayloadProxyFromDIRACGroup(
            ownerDN, ownerGroup, self.defaultProxyLength, token)
        if not retVal['OK']:
            self.log.error('Could not retrieve payload proxy',
                           retVal['Message'])
            os.system('dirac-proxy-info')
            sys.stdout.flush()
            return S_ERROR('Error retrieving proxy')

        chain = retVal['Value']
        return S_OK(chain)

    #############################################################################
    def _checkInstallSoftware(self, jobID, jobParams, resourceParams):
        """Checks software requirement of job and whether this is already present
       before installing software locally.
    """
        if 'SoftwareDistModule' not in jobParams:
            msg = 'Job has no software installation requirement'
            self.log.verbose(msg)
            return S_OK(msg)

        self.__report(jobID, 'Matched', 'Installing Software')
        softwareDist = jobParams['SoftwareDistModule']
        self.log.verbose('Found VO Software Distribution module',
                         ': %s' % (softwareDist))
        argumentsDict = {'Job': jobParams, 'CE': resourceParams}
        moduleFactory = ModuleFactory()
        moduleInstance = moduleFactory.getModule(softwareDist, argumentsDict)
        if not moduleInstance['OK']:
            return moduleInstance

        module = moduleInstance['Value']
        return module.execute()

    #############################################################################
    def _submitJob(self,
                   jobID,
                   jobParams,
                   resourceParams,
                   optimizerParams,
                   proxyChain,
                   processors=1,
                   wholeNode=False,
                   maxNumberOfProcessors=0,
                   mpTag=False):
        """ Submit job to the Computing Element instance after creating a custom
        Job Wrapper with the available job parameters.
    """
        logLevel = self.am_getOption('DefaultLogLevel', 'INFO')
        defaultWrapperLocation = self.am_getOption(
            'JobWrapperTemplate',
            'DIRAC/WorkloadManagementSystem/JobWrapper/JobWrapperTemplate.py')
        jobDesc = {
            "jobID": jobID,
            "jobParams": jobParams,
            "resourceParams": resourceParams,
            "optimizerParams": optimizerParams,
            "extraOptions": self.extraOptions,
            "defaultWrapperLocation": defaultWrapperLocation
        }
        result = createJobWrapper(log=self.log, logLevel=logLevel, **jobDesc)
        if not result['OK']:
            return result

        wrapperFile = result['Value']
        self.__report(jobID, 'Matched', 'Submitted To CE')

        self.log.info(
            'Submitting JobWrapper',
            '%s to %sCE' % (os.path.basename(wrapperFile), self.ceName))

        # Pass proxy to the CE
        proxy = proxyChain.dumpAllToString()
        if not proxy['OK']:
            self.log.error('Invalid proxy', proxy)
            return S_ERROR('Payload Proxy Not Found')

        payloadProxy = proxy['Value']
        submission = self.computingElement.submitJob(
            wrapperFile,
            payloadProxy,
            numberOfProcessors=processors,
            maxNumberOfProcessors=maxNumberOfProcessors,
            wholeNode=wholeNode,
            mpTag=mpTag,
            jobDesc=jobDesc,
            log=self.log,
            logLevel=logLevel)
        ret = S_OK('Job submitted')

        if submission['OK']:
            batchID = submission['Value']
            self.log.info('Job submitted', '%s as %s' % (jobID, batchID))
            if 'PayloadFailed' in submission:
                ret['PayloadFailed'] = submission['PayloadFailed']
                return ret
            time.sleep(self.jobSubmissionDelay)
        else:
            self.log.error('Job submission failed', jobID)
            self.__setJobParam(jobID, 'ErrorMessage',
                               '%s CE Submission Error' % (self.ceName))
            if 'ReschedulePayload' in submission:
                rescheduleFailedJob(jobID, submission['Message'])
                return S_OK()  # Without this, the job is marked as failed
            else:
                if 'Value' in submission:
                    self.log.error(
                        'Error in DIRAC JobWrapper:',
                        'exit code = %s' % (str(submission['Value'])))
            return S_ERROR('%s CE Error: %s' %
                           (self.ceName, submission['Message']))

        return ret

    #############################################################################
    def _getJDLParameters(self, jdl):
        """Returns a dictionary of JDL parameters.
    """
        try:
            parameters = {}
            #      print jdl
            if not re.search(r'\[', jdl):
                jdl = '[' + jdl + ']'
            classAdJob = ClassAd(jdl)
            paramsDict = classAdJob.contents
            for param, value in paramsDict.items():
                if value.strip().startswith('{'):
                    self.log.debug('Found list type parameter %s' % (param))
                    rawValues = value.replace('{',
                                              '').replace('}', '').replace(
                                                  '"', '').split()
                    valueList = []
                    for val in rawValues:
                        if re.search(',$', val):
                            valueList.append(val[:-1])
                        else:
                            valueList.append(val)
                    parameters[param] = valueList
                else:
                    parameters[param] = value.replace('"', '').replace(
                        '{', '"{').replace('}', '}"')
                    self.log.debug('Found standard parameter %s: %s' %
                                   (param, parameters[param]))
            return S_OK(parameters)
        except Exception as x:
            self.log.exception(lException=x)
            return S_ERROR('Exception while extracting JDL parameters for job')

    #############################################################################
    def __report(self, jobID, status, minorStatus):
        """Wraps around setJobStatus of state update client
    """
        jobStatus = JobStateUpdateClient().setJobStatus(
            int(jobID), status, minorStatus, 'JobAgent@%s' % self.siteName)
        self.log.verbose(
            'Setting job status', 'setJobStatus(%s,%s,%s,%s)' %
            (jobID, status, minorStatus, 'JobAgent@%s' % self.siteName))
        if not jobStatus['OK']:
            self.log.warn('Issue setting the job status', jobStatus['Message'])

        return jobStatus

    #############################################################################
    def __setJobParam(self, jobID, name, value):
        """Wraps around setJobParameter of state update client
    """
        jobParam = JobStateUpdateClient().setJobParameter(
            int(jobID), str(name), str(value))
        self.log.verbose('Setting job parameter',
                         'setJobParameter(%s,%s,%s)' % (jobID, name, value))
        if not jobParam['OK']:
            self.log.warn('Issue setting the job parameter',
                          jobParam['Message'])

        return jobParam

    #############################################################################
    def __finish(self, message, stop=True):
        """Force the JobAgent to complete gracefully.
    """
        if stop:
            self.log.info('JobAgent will stop',
                          'with message "%s", execution complete.' % message)
            self.am_stopExecution()
            return S_ERROR(message)
        else:
            return S_OK(message)

    #############################################################################
    def _rescheduleFailedJob(self, jobID, message, stop=True):
        """
    Set Job Status to "Rescheduled" and issue a reschedule command to the Job Manager
    """

        self.log.warn('Failure ==> rescheduling', '(during %s)' % (message))

        jobReport = JobReport(int(jobID), 'JobAgent@%s' % self.siteName)

        # Setting a job parameter does not help since the job will be rescheduled,
        # instead set the status with the cause and then another status showing the
        # reschedule operation.

        jobReport.setJobStatus(status='Rescheduled',
                               application=message,
                               sendFlag=True)

        self.log.info('Job will be rescheduled')
        result = JobManagerClient().rescheduleJob(jobID)
        if not result['OK']:
            self.log.error('Failed to reschedule job', result['Message'])
            return self.__finish('Problem Rescheduling Job', stop)

        self.log.info('Job Rescheduled', jobID)
        return self.__finish('Job Rescheduled', stop)

    #############################################################################
    def finalize(self):
        """ Job Agent finalization method
    """

        gridCE = gConfig.getValue('/LocalSite/GridCE', '')
        queue = gConfig.getValue('/LocalSite/CEQueue', '')
        result = PilotManagerClient().setPilotStatus(str(self.pilotReference),
                                                     'Done', gridCE,
                                                     'Report from JobAgent',
                                                     self.siteName, queue)
        if not result['OK']:
            self.log.warn('Issue setting the pilot status', result['Message'])

        return S_OK()
Example #10
0
class Watchdog(object):

    #############################################################################
    def __init__(self,
                 pid,
                 exeThread,
                 spObject,
                 jobCPUTime,
                 memoryLimit=0,
                 processors=1,
                 systemFlag='linux',
                 jobArgs={}):
        """ Constructor, takes system flag as argument.
    """
        self.stopSigStartSeconds = int(jobArgs.get('StopSigStartSeconds',
                                                   1800))  # 30 minutes
        self.stopSigFinishSeconds = int(
            jobArgs.get('StopSigFinishSeconds', 1800))  # 30 minutes
        self.stopSigNumber = int(jobArgs.get('StopSigNumber', 2))  # SIGINT
        self.stopSigRegex = jobArgs.get('StopSigRegex', None)
        self.stopSigSent = False

        self.log = gLogger.getSubLogger("Watchdog")
        self.systemFlag = systemFlag
        self.exeThread = exeThread
        self.wrapperPID = pid
        self.appPID = self.exeThread.getCurrentPID()
        self.spObject = spObject
        self.jobCPUTime = jobCPUTime
        self.memoryLimit = memoryLimit
        self.calibration = 0
        self.initialValues = {}
        self.parameters = {}
        self.peekFailCount = 0
        self.peekRetry = 5
        self.profiler = Profiler(pid)
        self.checkError = ''
        self.currentStats = {}
        self.initialized = False
        self.count = 0

        # defaults
        self.testWallClock = 1
        self.testDiskSpace = 1
        self.testLoadAvg = 1
        self.maxWallClockTime = 3 * 24 * 60 * 60
        self.testCPUConsumed = 1
        self.testCPULimit = 0
        self.testMemoryLimit = 0
        self.testTimeLeft = 1
        self.pollingTime = 10  # 10 seconds
        self.checkingTime = 30 * 60  # 30 minute period
        self.minCheckingTime = 20 * 60  # 20 mins
        self.wallClockCheckSeconds = 5 * 60  # 5 minutes
        self.maxWallClockTime = 3 * 24 * 60 * 60  # e.g. 4 days
        self.jobPeekFlag = 1  # on / off
        self.minDiskSpace = 10  # MB
        self.loadAvgLimit = 1000  # > 1000 and jobs killed
        self.sampleCPUTime = 30 * 60  # e.g. up to 20mins sample
        self.jobCPUMargin = 20  # %age buffer before killing job
        self.minCPUWallClockRatio = 5  # ratio %age
        self.nullCPULimit = 5  # After 5 sample times return null CPU consumption kill job
        self.checkCount = 0
        self.wallClockCheckCount = 0
        self.nullCPUCount = 0

        self.grossTimeLeftLimit = 10 * self.checkingTime
        self.timeLeftUtil = TimeLeft()
        self.timeLeft = 0
        self.littleTimeLeft = False
        self.scaleFactor = 1.0
        self.processors = processors

    #############################################################################
    def initialize(self, loops=0):
        """ Watchdog initialization.
    """
        if self.initialized:
            self.log.info('Watchdog already initialized')
            return S_OK()
        else:
            self.initialized = True

        setup = gConfig.getValue('/DIRAC/Setup', '')
        if not setup:
            return S_ERROR('Can not get the DIRAC Setup value')
        wms_instance = getSystemInstance("WorkloadManagement")
        if not wms_instance:
            return S_ERROR(
                'Can not get the WorkloadManagement system instance')
        self.section = '/Systems/WorkloadManagement/%s/JobWrapper' % wms_instance

        self.maxcount = loops
        self.log.verbose('Watchdog initialization')
        self.log.info('Attempting to Initialize Watchdog for: %s' %
                      (self.systemFlag))
        # Test control flags
        self.testWallClock = gConfig.getValue(
            self.section + '/CheckWallClockFlag', 1)
        self.testDiskSpace = gConfig.getValue(
            self.section + '/CheckDiskSpaceFlag', 1)
        self.testLoadAvg = gConfig.getValue(self.section + '/CheckLoadAvgFlag',
                                            1)
        self.testCPUConsumed = gConfig.getValue(
            self.section + '/CheckCPUConsumedFlag', 1)
        self.testCPULimit = gConfig.getValue(
            self.section + '/CheckCPULimitFlag', 0)
        self.testMemoryLimit = gConfig.getValue(
            self.section + '/CheckMemoryLimitFlag', 0)
        self.testTimeLeft = gConfig.getValue(
            self.section + '/CheckTimeLeftFlag', 1)
        # Other parameters
        self.pollingTime = gConfig.getValue(self.section + '/PollingTime',
                                            10)  # 10 seconds
        self.checkingTime = gConfig.getValue(self.section + '/CheckingTime',
                                             30 * 60)  # 30 minute period
        self.minCheckingTime = gConfig.getValue(
            self.section + '/MinCheckingTime', 20 * 60)  # 20 mins
        self.maxWallClockTime = gConfig.getValue(
            self.section + '/MaxWallClockTime',
            3 * 24 * 60 * 60)  # e.g. 4 days
        self.jobPeekFlag = gConfig.getValue(self.section + '/JobPeekFlag',
                                            1)  # on / off
        self.minDiskSpace = gConfig.getValue(self.section + '/MinDiskSpace',
                                             10)  # MB
        self.loadAvgLimit = gConfig.getValue(
            self.section + '/LoadAverageLimit', 1000)  # > 1000 and jobs killed
        self.sampleCPUTime = gConfig.getValue(self.section + '/CPUSampleTime',
                                              30 *
                                              60)  # e.g. up to 20mins sample
        self.jobCPUMargin = gConfig.getValue(
            self.section + '/JobCPULimitMargin',
            20)  # %age buffer before killing job
        self.minCPUWallClockRatio = gConfig.getValue(
            self.section + '/MinCPUWallClockRatio', 5)  # ratio %age
        # After 5 sample times return null CPU consumption kill job
        self.nullCPULimit = gConfig.getValue(
            self.section + '/NullCPUCountLimit', 5)
        if self.checkingTime < self.minCheckingTime:
            self.log.info(
                'Requested CheckingTime of %s setting to %s seconds (minimum)'
                % (self.checkingTime, self.minCheckingTime))
            self.checkingTime = self.minCheckingTime

        # The time left is returned in seconds @ 250 SI00 = 1 HS06,
        # the self.checkingTime and self.pollingTime are in seconds,
        # thus they need to be multiplied by a large enough factor
        self.fineTimeLeftLimit = gConfig.getValue(
            self.section + '/TimeLeftLimit', 150 * self.pollingTime)
        self.scaleFactor = gConfig.getValue('/LocalSite/CPUScalingFactor', 1.0)

        return S_OK()

    def run(self):
        """ The main watchdog execution method
    """

        result = self.initialize()
        if not result['OK']:
            self.log.always('Can not start watchdog for the following reason')
            self.log.always(result['Message'])
            return result

        try:
            while True:
                self.log.debug('Starting watchdog loop # %d' % self.count)
                start_cycle_time = time.time()
                result = self.execute()
                exec_cycle_time = time.time() - start_cycle_time
                if not result['OK']:
                    self.log.error("Watchdog error during execution",
                                   result['Message'])
                    break
                elif result['Value'] == "Ended":
                    break
                self.count += 1
                if exec_cycle_time < self.pollingTime:
                    time.sleep(self.pollingTime - exec_cycle_time)
            return S_OK()
        except Exception:
            self.log.exception()
            return S_ERROR('Exception')

    #############################################################################
    def execute(self):
        """ The main agent execution method of the Watchdog.
    """

        if not self.exeThread.isAlive():
            self.__getUsageSummary()
            self.log.info(
                'Process to monitor has completed, Watchdog will exit.')
            return S_OK("Ended")

        # WallClock checks every self.wallClockCheckSeconds, but only if StopSigRegex is defined in JDL
        if not self.stopSigSent and self.stopSigRegex is not None and (
                time.time() - self.initialValues['StartTime']
        ) > self.wallClockCheckSeconds * self.wallClockCheckCount:
            self.wallClockCheckCount += 1
            self._performWallClockChecks()

        if self.littleTimeLeft:
            # if we have gone over enough iterations query again
            if self.littleTimeLeftCount == 0 and self.__timeLeft() == -1:
                self.checkError = 'Job has reached the CPU limit of the queue'
                self.log.error(self.checkError, self.timeLeft)
                self.__killRunningThread()
                return S_OK()
            else:
                self.littleTimeLeftCount -= 1

        # Note: need to poll regularly to see if the thread is alive
        #      but only perform checks with a certain frequency
        if (time.time() - self.initialValues['StartTime']
            ) > self.checkingTime * self.checkCount:
            self.checkCount += 1
            result = self._performChecks()
            if not result['OK']:
                self.log.warn('Problem during recent checks')
                self.log.warn(result['Message'])
            return S_OK()
        else:
            # self.log.debug('Application thread is alive: checking count is %s' %(self.checkCount))
            return S_OK()

    #############################################################################
    def _performWallClockChecks(self):
        """Watchdog performs the wall clock checks based on MJF. Signals are sent
       to processes if we need to stop, but function always returns S_OK()
    """
        mjf = MJF.MJF()

        try:
            wallClockSecondsLeft = mjf.getWallClockSecondsLeft()
        except Exception as e:
            # Just stop if we can't get the wall clock seconds left
            return S_OK()

        jobstartSeconds = mjf.getIntJobFeature('jobstart_secs')
        if jobstartSeconds is None:
            # Just stop if we don't know when the job started
            return S_OK()

        if (int(time.time()) > jobstartSeconds + self.stopSigStartSeconds) and \
           (wallClockSecondsLeft < self.stopSigFinishSeconds + self.wallClockCheckSeconds):
            # Need to send the signal! Assume it works to avoid sending the signal more than once
            self.log.info('Sending signal %d to JobWrapper children' %
                          self.stopSigNumber)
            self.stopSigSent = True

            try:
                for childPid in getChildrenPIDs(self.wrapperPID):
                    try:
                        cmdline = open('/proc/%d/cmdline' % childPid,
                                       'r').read().replace('\0', ' ').strip()
                    except IOError:
                        # Process gone away? Not running on Linux? Skip anyway
                        continue

                    if re.search(self.stopSigRegex, cmdline) is not None:
                        self.log.info(
                            'Sending signal %d to process ID %d, cmdline = "%s"'
                            % (self.stopSigNumber, childPid, cmdline))
                        os.kill(childPid, self.stopSigNumber)

            except Exception as e:
                self.log.error(
                    'Failed to send signals to JobWrapper children! (%s)' %
                    str(e))

        return S_OK()

    #############################################################################
    def _performChecks(self):
        """The Watchdog checks are performed at a different period to the checking of the
       application thread and correspond to the checkingTime.
    """
        self.log.verbose('------------------------------------')
        self.log.verbose('Checking loop starts for Watchdog')
        heartBeatDict = {}

        msg = ''

        loadAvg = float(os.getloadavg()[0])
        msg += 'LoadAvg: %d ' % loadAvg
        heartBeatDict['LoadAverage'] = loadAvg
        if 'LoadAverage' not in self.parameters:
            self.parameters['LoadAverage'] = []
        self.parameters['LoadAverage'].append(loadAvg)

        memoryUsed = self.getMemoryUsed()
        msg += 'MemUsed: %.1f kb ' % (memoryUsed)
        heartBeatDict['MemoryUsed'] = memoryUsed
        if 'MemoryUsed' not in self.parameters:
            self.parameters['MemoryUsed'] = []
        self.parameters['MemoryUsed'].append(memoryUsed)

        result = self.profiler.vSizeUsage(withChildren=True)
        if not result['OK']:
            self.log.warn("Could not get vSize info from profiler",
                          result['Message'])
        else:
            vsize = result['Value'] * 1024.
            heartBeatDict['Vsize'] = vsize
            self.parameters.setdefault('Vsize', [])
            self.parameters['Vsize'].append(vsize)
            msg += "Job Vsize: %.1f kb " % vsize

        result = self.profiler.memoryUsage(withChildren=True)
        if not result['OK']:
            self.log.warn("Could not get rss info from profiler",
                          result['Message'])
        else:
            rss = result['Value'] * 1024.
            heartBeatDict['RSS'] = rss
            self.parameters.setdefault('RSS', [])
            self.parameters['RSS'].append(rss)
            msg += "Job RSS: %.1f kb " % rss

        if 'DiskSpace' not in self.parameters:
            self.parameters['DiskSpace'] = []

        result = self.getDiskSpace()
        if not result['OK']:
            self.log.warn("Could not establish DiskSpace", result['Message'])
        else:
            msg += 'DiskSpace: %.1f MB ' % (result['Value'])
            self.parameters['DiskSpace'].append(result['Value'])
            heartBeatDict['AvailableDiskSpace'] = result['Value']

        cpu = self.__getCPU()
        if not cpu['OK']:
            msg += 'CPU: ERROR '
            hmsCPU = 0
        else:
            cpu = cpu['Value']
            msg += 'CPU: %s (h:m:s) ' % (cpu)
            if 'CPUConsumed' not in self.parameters:
                self.parameters['CPUConsumed'] = []
            self.parameters['CPUConsumed'].append(cpu)
            hmsCPU = cpu
            rawCPU = self.__convertCPUTime(hmsCPU)
            if rawCPU['OK']:
                heartBeatDict['CPUConsumed'] = rawCPU['Value']

        result = self.__getWallClockTime()
        if not result['OK']:
            self.log.warn("Failed determining wall clock time",
                          result['Message'])
        else:
            msg += 'WallClock: %.2f s ' % (result['Value'])
            self.parameters.setdefault('WallClockTime',
                                       list()).append(result['Value'])
            heartBeatDict['WallClockTime'] = result['Value']
        self.log.info(msg)

        result = self._checkProgress()
        if not result['OK']:
            self.checkError = result['Message']
            self.log.warn(self.checkError)

            if self.jobPeekFlag:
                result = self.__peek()
                if result['OK']:
                    outputList = result['Value']
                    size = len(outputList)
                    self.log.info(
                        'Last %s lines of available application output:' %
                        (size))
                    self.log.info('================START================')
                    for line in outputList:
                        self.log.info(line)

                    self.log.info('=================END=================')

            self.__killRunningThread()
            return S_OK()

        recentStdOut = 'None'
        if self.jobPeekFlag:
            result = self.__peek()
            if result['OK']:
                outputList = result['Value']
                size = len(outputList)
                recentStdOut = 'Last %s lines of application output from Watchdog on %s [UTC]:' % (
                    size, Time.dateTime())
                border = '=' * len(recentStdOut)
                cpuTotal = 'Last reported CPU consumed for job is %s (h:m:s)' % (
                    hmsCPU)
                if self.timeLeft:
                    cpuTotal += ', Batch Queue Time Left %s (s @ HS06)' % self.timeLeft
                recentStdOut = '\n%s\n%s\n%s\n%s\n' % (border, recentStdOut,
                                                       cpuTotal, border)
                self.log.info(recentStdOut)
                for line in outputList:
                    self.log.info(line)
                    recentStdOut += line + '\n'
            else:
                recentStdOut = 'Watchdog is initializing and will attempt to obtain standard output from application thread'
                self.log.info(recentStdOut)
                self.peekFailCount += 1
                if self.peekFailCount > self.peekRetry:
                    self.jobPeekFlag = 0
                    self.log.warn(
                        'Turning off job peeking for remainder of execution')

        if 'JOBID' not in os.environ:
            self.log.info(
                'Running without JOBID so parameters will not be reported')
            return S_OK()

        jobID = os.environ['JOBID']
        staticParamDict = {'StandardOutput': recentStdOut}
        self.__sendSignOfLife(int(jobID), heartBeatDict, staticParamDict)
        return S_OK('Watchdog checking cycle complete')

    #############################################################################
    def __getCPU(self):
        """Uses the profiler to get CPU time for current process, its child, and the terminated child,
       and returns HH:MM:SS after conversion.
    """
        result = self.profiler.cpuUsageUser(withChildren=True,
                                            withTerminatedChildren=True)
        if not result['OK']:
            self.log.warn("Issue while checking consumed CPU for user",
                          result['Message'])
            if result['Errno'] == errno.ESRCH:
                self.log.warn(
                    "The main process does not exist (anymore). This might be correct."
                )
            return result
        cpuUsageUser = result['Value']

        result = self.profiler.cpuUsageSystem(withChildren=True,
                                              withTerminatedChildren=True)
        if not result['OK']:
            self.log.warn("Issue while checking consumed CPU for system",
                          result['Message'])
            if result['Errno'] == errno.ESRCH:
                self.log.warn(
                    "The main process does not exist (anymore). This might be correct."
                )
            return result
        cpuUsageSystem = result['Value']

        cpuTimeTotal = cpuUsageUser + cpuUsageSystem
        if cpuTimeTotal:
            self.log.verbose("Raw CPU time consumed (s) =", cpuTimeTotal)
            return self.__getCPUHMS(cpuTimeTotal)
        self.log.error("CPU time consumed found to be 0")
        return S_ERROR()

    #############################################################################
    def __getCPUHMS(self, cpuTime):
        mins, secs = divmod(cpuTime, 60)
        hours, mins = divmod(mins, 60)
        humanTime = '%02d:%02d:%02d' % (hours, mins, secs)
        self.log.verbose('Human readable CPU time is: %s' % humanTime)
        return S_OK(humanTime)

    #############################################################################
    def __interpretControlSignal(self, signalDict):
        """This method is called whenever a signal is sent via the result of
       sending a sign of life.
    """
        self.log.info('Received control signal')
        if isinstance(signalDict, dict):
            if 'Kill' in signalDict:
                self.log.info(
                    'Received Kill signal, stopping job via control signal')
                self.checkError = 'Received Kill signal'
                self.__killRunningThread()
            else:
                self.log.info(
                    'The following control signal was sent but not understood by the watchdog:'
                )
                self.log.info(signalDict)
        else:
            self.log.info(
                'Expected dictionary for control signal, received:\n%s' %
                (signalDict))

        return S_OK()

    #############################################################################
    def _checkProgress(self):
        """This method calls specific tests to determine whether the job execution
       is proceeding normally.  CS flags can easily be added to add or remove
       tests via central configuration.
    """
        report = ''

        if self.testWallClock:
            result = self.__checkWallClockTime()
            if not result['OK']:
                self.log.warn(result['Message'])
                return result
            report += 'WallClock: OK, '
        else:
            report += 'WallClock: NA,'

        if self.testDiskSpace:
            result = self.__checkDiskSpace()
            if not result['OK']:
                self.log.warn(result['Message'])
                return result
            report += 'DiskSpace: OK, '
        else:
            report += 'DiskSpace: NA,'

        if self.testLoadAvg:
            result = self.__checkLoadAverage()
            if not result['OK']:
                self.log.warn(
                    "Check of load average failed, but won't fail because of that: %s"
                    % result['Message'])
                report += 'LoadAverage: ERROR, '
                return S_OK()
            report += 'LoadAverage: OK, '
        else:
            report += 'LoadAverage: NA,'

        if self.testCPUConsumed:
            result = self.__checkCPUConsumed()
            if not result['OK']:
                return result
            report += 'CPUConsumed: OK, '
        else:
            report += 'CPUConsumed: NA, '

        if self.testCPULimit:
            result = self.__checkCPULimit()
            if not result['OK']:
                self.log.warn(result['Message'])
                return result
            report += 'CPULimit OK, '
        else:
            report += 'CPULimit: NA, '

        if self.testTimeLeft:
            self.__timeLeft()
            if self.timeLeft:
                report += 'TimeLeft: OK'
        else:
            report += 'TimeLeft: NA'

        if self.testMemoryLimit:
            result = self.__checkMemoryLimit()
            if not result['OK']:
                self.log.warn(result['Message'])
                return result
            report += 'MemoryLimit OK, '
        else:
            report += 'MemoryLimit: NA, '

        self.log.info(report)
        return S_OK('All enabled checks passed')

    #############################################################################
    def __checkCPUConsumed(self):
        """ Checks whether the CPU consumed by application process is reasonable. This
        method will report stalled jobs to be killed.
    """
        self.log.info("Checking CPU Consumed")

        if 'WallClockTime' not in self.parameters:
            return S_ERROR('Missing WallClockTime info')
        if 'CPUConsumed' not in self.parameters:
            return S_ERROR('Missing CPUConsumed info')

        wallClockTime = self.parameters['WallClockTime'][-1]
        if wallClockTime < self.sampleCPUTime:
            self.log.info(
                "Stopping check, wallclock time (%s) is still smaller than sample time (%s)"
                % (wallClockTime, self.sampleCPUTime))
            return S_OK()

        intervals = max(1, int(self.sampleCPUTime / self.checkingTime))
        if len(self.parameters['CPUConsumed']) < intervals + 1:
            self.log.info(
                "Not enough snapshots to calculate, there are %s and we need %s"
                % (len(self.parameters['CPUConsumed']), intervals + 1))
            return S_OK()

        wallClockTime = self.parameters['WallClockTime'][-1] - self.parameters[
            'WallClockTime'][-1 - intervals]
        try:
            cpuTime = self.__convertCPUTime(
                self.parameters['CPUConsumed'][-1])['Value']
            # For some reason, some times the CPU consumed estimation returns 0
            # if cpuTime == 0:
            #   return S_OK()
            cpuTime -= self.__convertCPUTime(
                self.parameters['CPUConsumed'][-1 - intervals])['Value']
            if cpuTime < 0:
                self.log.warn(
                    'Consumed CPU time negative, something wrong may have happened, ignore'
                )
                return S_OK()
            if wallClockTime <= 0:
                self.log.warn(
                    'Wallclock time should not be negative or zero, Ignore')
                return S_OK()

            ratio = (cpuTime / wallClockTime) * 100.

            self.log.info("CPU/Wallclock ratio is %.2f%%" % ratio)
            # in case of error cpuTime might be 0, exclude this
            if ratio < self.minCPUWallClockRatio:
                if os.path.exists('DISABLE_WATCHDOG_CPU_WALLCLOCK_CHECK') or \
                   'DISABLE_WATCHDOG_CPU_WALLCLOCK_CHECK' in os.environ:
                    self.log.warn(
                        'N.B. job would be declared as stalled but CPU / WallClock check is disabled by payload'
                    )
                    return S_OK()
                self.log.info("Job is stalled!")
                return S_ERROR('Watchdog identified this job as stalled')
        except Exception as e:
            self.log.error("Cannot convert CPU consumed from string to int",
                           str(e))

        return S_OK()

    #############################################################################

    def __convertCPUTime(self, cputime):
        """ Method to convert the CPU time as returned from the Watchdog
        instances to the equivalent DIRAC normalized CPU time to be compared
        to the Job CPU requirement.
    """
        cpuValue = 0
        cpuHMS = cputime.split(':')
        # for i in xrange( len( cpuHMS ) ):
        #   cpuHMS[i] = cpuHMS[i].replace( '00', '0' )

        try:
            hours = float(cpuHMS[0]) * 60 * 60
            mins = float(cpuHMS[1]) * 60
            secs = float(cpuHMS[2])
            cpuValue = float(hours + mins + secs)
        except Exception as x:
            self.log.warn(str(x))
            return S_ERROR('Could not calculate CPU time')

        # Normalization to be implemented
        normalizedCPUValue = cpuValue

        result = S_OK()
        result['Value'] = normalizedCPUValue
        self.log.debug('CPU value %s converted to %s' %
                       (cputime, normalizedCPUValue))
        return result

    #############################################################################

    def __checkCPULimit(self):
        """ Checks that the job has consumed more than the job CPU requirement
        (plus a configurable margin) and kills them as necessary.
    """
        consumedCPU = 0
        if 'CPUConsumed' in self.parameters:
            consumedCPU = self.parameters['CPUConsumed'][-1]

        consumedCPUDict = self.__convertCPUTime(consumedCPU)
        if consumedCPUDict['OK']:
            currentCPU = consumedCPUDict['Value']
        else:
            return S_OK('Not possible to determine current CPU consumed')

        if consumedCPU:
            limit = self.jobCPUTime + self.jobCPUTime * (self.jobCPUMargin /
                                                         100)
            cpuConsumed = float(currentCPU)
            if cpuConsumed > limit:
                self.log.info(
                    'Job has consumed more than the specified CPU limit with an additional %s%% margin'
                    % (self.jobCPUMargin))
                return S_ERROR('Job has exceeded maximum CPU time limit')
            else:
                return S_OK('Job within CPU limit')
        elif not currentCPU:
            self.log.verbose('Both initial and current CPU consumed are null')
            return S_OK('CPU consumed is not measurable yet')
        else:
            return S_OK('Not possible to determine CPU consumed')

    def __checkMemoryLimit(self):
        """ Checks that the job memory consumption is within a limit
    """
        vsize = 0
        if 'Vsize' in self.parameters:
            vsize = self.parameters['Vsize'][-1]

        if vsize and self.memoryLimit:
            if vsize > self.memoryLimit:
                vsize = vsize
                # Just a warning for the moment
                self.log.warn(
                    "Job has consumed %f.2 KB of memory with the limit of %f.2 KB"
                    % (vsize, self.memoryLimit))

        return S_OK()

    #############################################################################
    def __checkDiskSpace(self):
        """Checks whether the CS defined minimum disk space is available.
    """
        if 'DiskSpace' in self.parameters:
            availSpace = self.parameters['DiskSpace'][-1]
            if availSpace >= 0 and availSpace < self.minDiskSpace:
                self.log.info(
                    'Not enough local disk space for job to continue, defined in CS as %s MB'
                    % (self.minDiskSpace))
                return S_ERROR('Job has insufficient disk space to continue')
            else:
                return S_OK('Job has enough disk space available')
        else:
            return S_ERROR('Available disk space could not be established')

    #############################################################################
    def __checkWallClockTime(self):
        """Checks whether the job has been running for the CS defined maximum
       wall clock time.
    """
        if 'StartTime' in self.initialValues:
            startTime = self.initialValues['StartTime']
            if time.time() - startTime > self.maxWallClockTime:
                self.log.info(
                    'Job has exceeded maximum wall clock time of %s seconds' %
                    (self.maxWallClockTime))
                return S_ERROR('Job has exceeded maximum wall clock time')
            else:
                return S_OK('Job within maximum wall clock time')
        else:
            return S_ERROR('Job start time could not be established')

    #############################################################################
    def __checkLoadAverage(self):
        """Checks whether the CS defined maximum load average is exceeded.
    """
        if 'LoadAverage' in self.parameters:
            loadAvg = self.parameters['LoadAverage'][-1]
            if loadAvg > float(self.loadAvgLimit):
                self.log.info(
                    'Maximum load average exceeded, defined in CS as %s ' %
                    (self.loadAvgLimit))
                return S_ERROR('Job exceeded maximum load average')
            else:
                return S_OK('Job running with normal load average')
        else:
            return S_ERROR('Job load average not established')

    #############################################################################
    def __peek(self):
        """ Uses ExecutionThread.getOutput() method to obtain standard output
        from running thread via subprocess callback function.
    """
        result = self.exeThread.getOutput()
        if not result['OK']:
            self.log.warn(
                'Could not obtain output from running application thread')
            self.log.warn(result['Message'])

        return result

    #############################################################################
    def calibrate(self):
        """ The calibrate method obtains the initial values for system memory and load
        and calculates the margin for error for the rest of the Watchdog cycle.
    """
        self.__getWallClockTime()
        self.parameters['WallClockTime'] = []

        cpuConsumed = self.__getCPU()
        if not cpuConsumed['OK']:
            self.log.warn("Could not establish CPU consumed, setting to 0.0")
            cpuConsumed = 0.0
        else:
            cpuConsumed = cpuConsumed['Value']

        self.initialValues['CPUConsumed'] = cpuConsumed
        self.parameters['CPUConsumed'] = []

        self.initialValues['LoadAverage'] = float(os.getloadavg()[0])
        self.parameters['LoadAverage'] = []

        memUsed = self.getMemoryUsed()

        self.initialValues['MemoryUsed'] = memUsed
        self.parameters['MemoryUsed'] = []

        result = self.profiler.vSizeUsage(withChildren=True)
        if not result['OK']:
            self.log.warn("Could not get vSize info from profiler",
                          result['Message'])
        else:
            vsize = result['Value'] * 1024.
            self.initialValues['Vsize'] = vsize
            self.log.verbose("Vsize(kb)", "%.1f" % vsize)
        self.parameters['Vsize'] = []

        result = self.profiler.memoryUsage(withChildren=True)
        if not result['OK']:
            self.log.warn("Could not get rss info from profiler",
                          result['Message'])
        else:
            rss = result['Value'] * 1024.
            self.initialValues['RSS'] = rss
            self.log.verbose("RSS(kb)", "%.1f" % rss)
        self.parameters['RSS'] = []

        result = self.getDiskSpace()
        self.log.verbose('DiskSpace', result)
        if not result['OK']:
            self.log.warn("Could not establish DiskSpace")
        else:
            self.initialValues['DiskSpace'] = result['Value']
        self.parameters['DiskSpace'] = []

        result = self.getNodeInformation()
        self.log.verbose('NodeInfo', result)
        if not result['OK']:
            self.log.warn("Could not establish static system information")

        if 'LSB_JOBID' in os.environ:
            result['LocalJobID'] = os.environ['LSB_JOBID']
        if 'PBS_JOBID' in os.environ:
            result['LocalJobID'] = os.environ['PBS_JOBID']
        if 'QSUB_REQNAME' in os.environ:
            result['LocalJobID'] = os.environ['QSUB_REQNAME']
        if 'JOB_ID' in os.environ:
            result['LocalJobID'] = os.environ['JOB_ID']

        self.__reportParameters(result, 'NodeInformation', True)
        self.__reportParameters(self.initialValues, 'InitialValues')
        return S_OK()

    def __timeLeft(self):
        """
      return Normalized CPU time left in the batch system
      0 if not available
      update self.timeLeft and self.littleTimeLeft
    """
        # Get CPU time left in the batch system
        result = self.timeLeftUtil.getTimeLeft(0.0)
        if not result['OK']:
            # Could not get CPU time left, we might need to wait for the first loop
            # or the Utility is not working properly for this batch system
            # or we are in a batch system
            timeLeft = 0
        else:
            timeLeft = result['Value']

        self.timeLeft = timeLeft
        if not self.littleTimeLeft:
            if timeLeft and timeLeft < self.grossTimeLeftLimit:
                self.log.info(
                    'TimeLeft bellow %s, now checking with higher frequency' %
                    timeLeft)
                self.littleTimeLeft = True
                # TODO: better configurable way of doing this to be coded
                self.littleTimeLeftCount = 15
        else:
            if self.timeLeft and self.timeLeft < self.fineTimeLeftLimit:
                timeLeft = -1

        return timeLeft

    #############################################################################
    def __getUsageSummary(self):
        """ Returns average load, memory etc. over execution of job thread
    """
        summary = {}
        # CPUConsumed
        if 'CPUConsumed' in self.parameters:
            cpuList = self.parameters['CPUConsumed']
            if cpuList:
                hmsCPU = cpuList[-1]
                rawCPU = self.__convertCPUTime(hmsCPU)
                if rawCPU['OK']:
                    summary['LastUpdateCPU(s)'] = rawCPU['Value']
            else:
                summary['LastUpdateCPU(s)'] = 'Could not be estimated'
        # DiskSpace
        if 'DiskSpace' in self.parameters:
            space = self.parameters['DiskSpace']
            if space:
                value = abs(
                    float(space[-1]) - float(self.initialValues['DiskSpace']))
                if value < 0:
                    value = 0
                summary['DiskSpace(MB)'] = value
            else:
                summary['DiskSpace(MB)'] = 'Could not be estimated'
        # MemoryUsed
        if 'MemoryUsed' in self.parameters:
            memory = self.parameters['MemoryUsed']
            if memory:
                summary['MemoryUsed(kb)'] = abs(
                    float(memory[-1]) -
                    float(self.initialValues['MemoryUsed']))
            else:
                summary['MemoryUsed(kb)'] = 'Could not be estimated'
        # LoadAverage
        if 'LoadAverage' in self.parameters:
            laList = self.parameters['LoadAverage']
            if laList:
                summary['LoadAverage'] = float(sum(laList)) / float(
                    len(laList))
            else:
                summary['LoadAverage'] = 'Could not be estimated'

        result = self.__getWallClockTime()
        if not result['OK']:
            self.log.warn("Failed determining wall clock time",
                          result['Message'])
            summary['WallClockTime(s)'] = 0
            summary['ScaledCPUTime(s)'] = 0
        else:
            wallClock = result['Value']
            summary['WallClockTime(s)'] = wallClock
            summary[
                'ScaledCPUTime(s)'] = wallClock * self.scaleFactor * self.processors

        self.__reportParameters(summary, 'UsageSummary', True)
        self.currentStats = summary

    #############################################################################
    def __reportParameters(self, params, title=None, report=False):
        """Will report parameters for job.
    """
        try:
            parameters = []
            self.log.info(
                '==========================================================')
            if title:
                self.log.info('Watchdog will report %s' % (title))
            else:
                self.log.info('Watchdog will report parameters')
            self.log.info(
                '==========================================================')
            vals = params
            if 'Value' in params:
                if vals['Value']:
                    vals = params['Value']
            for k, v in vals.items():
                if v:
                    self.log.info(str(k) + ' = ' + str(v))
                    parameters.append([k, v])
            if report:
                self.__setJobParamList(parameters)

            self.log.info(
                '==========================================================')
        except Exception as x:
            self.log.warn('Problem while reporting parameters')
            self.log.warn(str(x))

    #############################################################################
    def __getWallClockTime(self):
        """ Establishes the Wall Clock time spent since the Watchdog initialization"""
        result = S_OK()
        if 'StartTime' in self.initialValues:
            currentTime = time.time()
            wallClock = currentTime - self.initialValues['StartTime']
            result['Value'] = wallClock
        else:
            self.initialValues['StartTime'] = time.time()
            result['Value'] = 0.0

        return result

    #############################################################################
    def __killRunningThread(self):
        """ Will kill the running thread process and any child processes."""
        self.log.info('Sending kill signal to application PID %s' %
                      (self.spObject.getChildPID()))
        result = self.spObject.killChild()
        self.applicationKilled = True
        self.log.info('Subprocess.killChild() returned:%s ' % (result))
        return S_OK('Thread killed')

    #############################################################################
    def __sendSignOfLife(self, jobID, heartBeatDict, staticParamDict):
        """ Sends sign of life 'heartbeat' signal and triggers control signal
        interpretation.
    """
        result = JobStateUpdateClient().sendHeartBeat(jobID, heartBeatDict,
                                                      staticParamDict)
        if not result['OK']:
            self.log.warn('Problem sending sign of life')
            self.log.warn(result)

        if result['OK'] and result['Value']:
            self.__interpretControlSignal(result['Value'])

        return result

    #############################################################################
    def __setJobParamList(self, value):
        """Wraps around setJobParameters of state update client
    """
        # job wrapper template sets the jobID variable
        if 'JOBID' not in os.environ:
            self.log.info(
                'Running without JOBID so parameters will not be reported')
            return S_OK()
        jobID = os.environ['JOBID']
        jobParam = JobStateUpdateClient().setJobParameters(int(jobID), value)
        self.log.verbose('setJobParameters(%s,%s)' % (jobID, value))
        if not jobParam['OK']:
            self.log.warn(jobParam['Message'])

        return jobParam

    #############################################################################
    def getNodeInformation(self):
        """ Attempts to retrieve all static system information, should be overridden in a subclass"""
        methodName = 'getNodeInformation'
        self.log.warn('Watchdog: ' + methodName +
                      ' method should be implemented in a subclass')
        return S_ERROR('Watchdog: ' + methodName +
                       ' method should be implemented in a subclass')

    #############################################################################
    def getMemoryUsed(self):
        """Obtains the memory used.
    """
        mem = resource.getrusage(resource.RUSAGE_SELF).ru_maxrss + \
            resource.getrusage(resource.RUSAGE_CHILDREN).ru_maxrss
        return float(mem)

    #############################################################################
    def getDiskSpace(self):
        """ Attempts to get the available disk space, should be overridden in a subclass"""
        methodName = 'getDiskSpace'
        self.log.warn('Watchdog: ' + methodName +
                      ' method should be implemented in a subclass')
        return S_ERROR('Watchdog: ' + methodName +
                       ' method should be implemented in a subclass')
Example #11
0
def getCPUTime(cpuNormalizationFactor):
    """Trying to get CPUTime left for execution (in seconds).

    It will first look to get the work left looking for batch system information useing the TimeLeft utility.
    If it succeeds, it will convert it in real second, and return it.

    If it fails, it tries to get it from the static info found in CS.
    If it fails, it returns the default, which is a large 9999999, that we may consider as "Infinite".

    This is a generic method, independent from the middleware of the resource if TimeLeft doesn't return a value

    args:
      cpuNormalizationFactor (float): the CPU power of the current Worker Node.
      If not passed in, it's get from the local configuration

    returns:
      cpuTimeLeft (int): the CPU time left, in seconds
    """
    cpuTimeLeft = 0.0
    cpuWorkLeft = gConfig.getValue("/LocalSite/CPUTimeLeft", 0)

    if not cpuWorkLeft:
        # Try and get the information from the CPU left utility
        result = TimeLeft().getTimeLeft()
        if result["OK"]:
            cpuWorkLeft = result["Value"]

    if cpuWorkLeft > 0:
        # This is in HS06sseconds
        # We need to convert in real seconds
        if not cpuNormalizationFactor:  # if cpuNormalizationFactor passed in is 0, try get it from the local cfg
            cpuNormalizationFactor = gConfig.getValue("/LocalSite/CPUNormalizationFactor", 0.0)
        if cpuNormalizationFactor:
            cpuTimeLeft = cpuWorkLeft / cpuNormalizationFactor

    if not cpuTimeLeft:
        # now we know that we have to find the CPUTimeLeft by looking in the CS
        # this is not granted to be correct as the CS units may not be real seconds
        gridCE = gConfig.getValue("/LocalSite/GridCE")
        ceQueue = gConfig.getValue("/LocalSite/CEQueue")
        if not ceQueue:
            # we have to look for a ceQueue in the CS
            # A bit hacky. We should better profit from something generic
            gLogger.warn("No CEQueue in local configuration, looking to find one in CS")
            siteName = DIRAC.siteName()
            queueSection = "/Resources/Sites/%s/%s/CEs/%s/Queues" % (siteName.split(".")[0], siteName, gridCE)
            res = gConfig.getSections(queueSection)
            if not res["OK"]:
                raise RuntimeError(res["Message"])
            queues = res["Value"]
            cpuTimes = [gConfig.getValue(queueSection + "/" + queue + "/maxCPUTime", 9999999.0) for queue in queues]
            # These are (real, wall clock) minutes - damn BDII!
            cpuTimeLeft = min(cpuTimes) * 60
        else:
            queueInfo = getQueueInfo("%s/%s" % (gridCE, ceQueue))
            cpuTimeLeft = 9999999.0
            if not queueInfo["OK"] or not queueInfo["Value"]:
                gLogger.warn("Can't find a CE/queue, defaulting CPUTime to %d" % cpuTimeLeft)
            else:
                queueCSSection = queueInfo["Value"]["QueueCSSection"]
                # These are (real, wall clock) minutes - damn BDII!
                cpuTimeInMinutes = gConfig.getValue("%s/maxCPUTime" % queueCSSection, 0.0)
                if cpuTimeInMinutes:
                    cpuTimeLeft = cpuTimeInMinutes * 60.0
                    gLogger.info("CPUTime for %s: %f" % (queueCSSection, cpuTimeLeft))
                else:
                    gLogger.warn(
                        "Can't find maxCPUTime for %s, defaulting CPUTime to %f" % (queueCSSection, cpuTimeLeft)
                    )

    return int(cpuTimeLeft)