Python testboxcommons.log函数代码示例

 def _cmdSpecial(self, oResponse, oConnection):
     """
     Reserved for future fun.
     """
     oConnection.sendReplyAndClose(constants.tbreq.COMMAND_NOTSUP, constants.tbresp.CMD_SPECIAL);
     testboxcommons.log('Special command %s not supported...' % (oResponse,));
     return False;

    def _maybeSignOn(self):
        """
        Check if Test Box parameters were changed
        and do sign-in in case of positive result
        """

        # Skip sign-on check if background command is currently in
        # running state (avoid infinite signing on).
        if self._oCommand.isRunning():
            return None;

        # Refresh sign-on parameters, changes triggers sign-on.
        fNeedSignOn = (True if not self._fSignedOn or self._fNeedReSignOn else False)
        for item in self._ddSignOnParams:
            if self._ddSignOnParams[item][self.FN] is None:
                continue

            sOldValue = self._ddSignOnParams[item][self.VALUE]
            self._ddSignOnParams[item][self.VALUE] = self._ddSignOnParams[item][self.FN]()
            if sOldValue != self._ddSignOnParams[item][self.VALUE]:
                fNeedSignOn = True
                testboxcommons.log('Detected %s parameter change: %s -> %s' %
                                   (item, sOldValue, self._ddSignOnParams[item][self.VALUE]))

        if fNeedSignOn:
            self._doSignOn();
        return None;

    def __init__(self, oResponse):
        """
        Convert the HTTPResponse to a dictionary, raising TestBoxException on
        malformed response.
        """
        if oResponse is not None:
            # Read the whole response (so we can log it).
            sBody = oResponse.read();

            # Check the content type.
            sContentType = oResponse.getheader('Content-Type');
            if sContentType is None  or  sContentType != 'application/x-www-form-urlencoded; charset=utf-8':
                testboxcommons.log('SERVER RESPONSE: Content-Type: %s' % (sContentType,));
                testboxcommons.log('SERVER RESPONSE: %s' % (sBody.rstrip(),))
                raise testboxcommons.TestBoxException('Invalid server response type: "%s"' % (sContentType,));

            # Parse the body (this should be the exact reverse of what
            # TestBoxConnection.postRequestRaw).
            ##testboxcommons.log2('SERVER RESPONSE: "%s"' % (sBody,))
            self._dResponse = urlparse.parse_qs(sBody, strict_parsing=True);

            # Convert the dictionary from 'field:values' to 'field:value'. Fail
            # if a field has more than one value (i.e. given more than once).
            for sField in self._dResponse:
                if len(self._dResponse[sField]) != 1:
                    raise testboxcommons.TestBoxException('The field "%s" appears more than once in the server response' \
                                                          % (sField,));
                self._dResponse[sField] = self._dResponse[sField][0]
        else:
            # Special case, dummy response object.
            self._dResponse = dict();

    def _logInternal(self, sMessage, fPrefix = True, fFlushCheck = False):
        """
        Internal logging.
        Won't flush the backlog, returns a flush indicator so the caller can
        do it instead.
        """
        if fPrefix:
            try:
                oNow = datetime.utcnow();
                sTs = '%02u:%02u:%02u.%06u ' % (oNow.hour, oNow.minute, oNow.second, oNow.microsecond);
            except Exception as oXcpt:
                sTs = 'oXcpt=%s ' % (oXcpt);
            sFullMsg = sTs + sMessage;
        else:
            sFullMsg = sMessage;

        self._oBackLogLock.acquire();
        self._asBackLog.append(sFullMsg);
        cchBackLog = self._cchBackLog + len(sFullMsg) + 1;
        self._cchBackLog = cchBackLog;
        secTsBackLogFlush = self._secTsBackLogFlush;
        self._oBackLogLock.release();

        testboxcommons.log(sFullMsg);
        return fFlushCheck \
            and (   cchBackLog >= self.kcchMaxBackLog \
                 or utils.timestampSecond() - secTsBackLogFlush >= self.kcSecBackLogFlush);

    def doReboot(self):
        """
        Worker common to _cmdReboot and _doUpgrade that performs a system reboot.
        """
        # !! Not more exceptions beyond this point !!
        testboxcommons.log('Rebooting');

        # Stop anything that might be executing at this point.
        oCurTask = self._getCurTask();
        if oCurTask is not None:
            oCurTask.terminate();
            oCurTask.wait(self.kcSecStopBeforeRebootTimeout);

        # Invoke shutdown command line utility.
        sOs = utils.getHostOs();
        asCmd2 = None;
        if sOs == 'win':
            asCmd = ['shutdown', '/r', '/t', '0'];
        elif sOs == 'os2':
            asCmd = ['setboot', '/B'];
        elif sOs in ('solaris',):
            asCmd = ['/usr/sbin/reboot', '-p'];
            asCmd2 = ['/usr/sbin/reboot']; # Hack! S10 doesn't have -p, but don't know how to reliably detect S10.
        else:
            asCmd = ['/sbin/shutdown', '-r', 'now'];
        try:
            utils.sudoProcessOutputChecked(asCmd);
        except Exception, oXcpt:
            if asCmd2 is not None:
                try:
                    utils.sudoProcessOutputChecked(asCmd2);
                except Exception, oXcpt:
                    testboxcommons.log('Error executing reboot command "%s" as well as "%s": %s' % (asCmd, asCmd2, oXcpt));
                    return False;

    def _logFlush(self, oGivenConnection = None):
        """
        Flushes the log to the test manager.

        No exceptions.
        """
        fRc = True;
        self._oBackLogFlushLock.acquire();

        # Grab the current back log.
        self._oBackLogLock.acquire();
        asBackLog = self._asBackLog;
        self._asBackLog  = [];
        self._cchBackLog = 0;
        self._secTsBackLogFlush = utils.timestampSecond();
        self._oBackLogLock.release();

        # If there is anything to flush, flush it.
        if asBackLog:
            sBody = '';
            for sLine in asBackLog:
                sBody += sLine + '\n';

            oConnection = None;
            try:
                if oGivenConnection is None:
                    oConnection = self._oTestBoxScript.openTestManagerConnection();
                    oConnection.postRequest(constants.tbreq.LOG_MAIN, {constants.tbreq.LOG_PARAM_BODY: sBody});
                    oConnection.close();
                else:
                    oGivenConnection.postRequest(constants.tbreq.LOG_MAIN, {constants.tbreq.LOG_PARAM_BODY: sBody});
            except Exception as oXcpt:
                testboxcommons.log('_logFlush error: %s' % (oXcpt,));
                if len(sBody) < self.kcchMaxBackLog * 4:
                    self._oBackLogLock.acquire();
                    asBackLog.extend(self._asBackLog);
                    self._asBackLog = asBackLog;
                    # Don't restore _cchBackLog as there is no point in retrying immediately.
                    self._oBackLogLock.release();
                if oConnection is not None: # Be kind to apache.
                    try:    oConnection.close();
                    except: pass;
                fRc = False;

        self._oBackLogFlushLock.release();
        return fRc;

    def dispatch(self):
        """
        Receive orders from Test Manager and execute them
        """

        (self._idTestBox, self._sTestBoxName, self._fSignedOn) = self._oCommand.resumeIncompleteCommand();
        self._fNeedReSignOn = self._fSignedOn;
        if self._fSignedOn:
            os.environ['TESTBOX_ID']   = str(self._idTestBox);
            os.environ['TESTBOX_NAME'] = self._sTestBoxName;

        while True:
            # Make sure we're signed on before trying to do anything.
            self._maybeSignOn();
            while not self._fSignedOn:
                iFactor = 1 if self._cSignOnAttempts < 100 else 4;
                time.sleep(random.randint(self.kcSecMinSignOnDelay * iFactor, self.kcSecMaxSignOnDelay * iFactor));
                self._maybeSignOn();

            # Retrieve and handle command from the TM.
            (oResponse, oConnection) = TestBoxConnection.requestCommandWithConnection(self._oOptions.sTestManagerUrl,
                                                                                      self._idTestBox,
                                                                                      self._sTestBoxUuid,
                                                                                      self._oCommand.isRunning());
            if oResponse is not None:
                self._oCommand.handleCommand(oResponse, oConnection);
            if oConnection is not None:
                if oConnection.isConnected():
                    self._oCommand.flushLogOnConnection(oConnection);
                oConnection.close();

            # Automatically reboot if scratch init fails.
            if self._cReinitScratchErrors > 8 and self.reinitScratch() is False:
                testboxcommons.log('Scratch does not initialize cleanly after %d attempts, rebooting...'
                                   % ( self._cReinitScratchErrors, ));
                self._oCommand.doReboot();

            # delay a wee bit before looping.
            ## @todo We shouldn't bother the server too frequently.  We should try combine the test reporting done elsewhere
            # with the command retrieval done here.  I believe tinderclient.pl is capable of doing that.
            iFactor = 1;
            if self._cReinitScratchErrors > 0:
                iFactor = 4;
            time.sleep(random.randint(self.kcSecMinDelay * iFactor, self.kcSecMaxDelay * iFactor));

    def _doSignOn(self):
        """
        Worker for _maybeSignOn that does the actual signing on.
        """
        assert not self._oCommand.isRunning();

        # Reset the siged-on state.
        testboxcommons.log('Signing-on...')
        self._fSignedOn = False
        self._idTestBox = None
        self._cSignOnAttempts += 1;

        # Assemble SIGN-ON request parameters and send the request.
        dParams = {};
        for sParam in self._ddSignOnParams:
            dParams[sParam] = self._ddSignOnParams[sParam][self.VALUE];
        oResponse = TestBoxConnection.sendSignOn(self._oOptions.sTestManagerUrl, dParams);

        # Check response.
        try:
            sResult = oResponse.getStringChecked(constants.tbresp.ALL_PARAM_RESULT);
            if sResult != constants.tbresp.STATUS_ACK:
                raise TestBoxException('Result is %s' % (sResult,));
            oResponse.checkParameterCount(3);
            idTestBox    = oResponse.getIntChecked(constants.tbresp.SIGNON_PARAM_ID, 1, 0x7ffffffe);
            sTestBoxName = oResponse.getStringChecked(constants.tbresp.SIGNON_PARAM_NAME);
        except TestBoxException as err:
            testboxcommons.log('Failed to sign-on: %s' % (str(err),))
            testboxcommons.log('Server response: %s' % (oResponse.toString(),));
            return False;

        # Successfully signed on, update the state.
        self._fSignedOn       = True;
        self._fNeedReSignOn   = False;
        self._cSignOnAttempts = 0;
        self._idTestBox       = idTestBox;
        self._sTestBoxName    = sTestBoxName;

        # Update the environment.
        os.environ['TESTBOX_ID']            = str(self._idTestBox);
        os.environ['TESTBOX_NAME']          = sTestBoxName;
        os.environ['TESTBOX_CPU_COUNT']     = self.getSignOnParam(constants.tbreq.SIGNON_PARAM_CPU_COUNT);
        os.environ['TESTBOX_MEM_SIZE']      = self.getSignOnParam(constants.tbreq.SIGNON_PARAM_MEM_SIZE);
        os.environ['TESTBOX_SCRATCH_SIZE']  = self.getSignOnParam(constants.tbreq.SIGNON_PARAM_SCRATCH_SIZE);

        testboxcommons.log('Successfully signed-on with Test Box ID #%s and given the name "%s"' \
                           % (self._idTestBox, self._sTestBoxName));

        # Set up the scratch area.
        self.reinitScratch(fUseTheForce = self._fFirstSignOn, cRetries = 2);

        self._fFirstSignOn = False;
        return True;

    def _doUpgrade(self, oResponse, oConnection, fReboot):
        """
        Common worker for _cmdUpgrade and _cmdUpgradeAndReboot.
        Will sys.exit on success!
        """

        #
        # The server specifies a ZIP archive with the new scripts. It's ASSUMED
        # that the zip is of selected files at g_ksValidationKitDir in SVN.  It's
        # further ASSUMED that we're executing from
        #
        sZipUrl = oResponse.getStringChecked(constants.tbresp.UPGRADE_PARAM_URL)
        oResponse.checkParameterCount(2);

        if utils.isRunningFromCheckout():
            raise TestBoxException('Cannot upgrade when running from the tree!');
        oConnection.sendAckAndClose(constants.tbresp.CMD_UPGRADE_AND_REBOOT if fReboot else constants.tbresp.CMD_UPGRADE);

        testboxcommons.log('Upgrading...');

        #
        # Download the file and install it.
        #
        sDstFile = os.path.join(g_ksTestScriptDir, 'VBoxTestBoxScript.zip');
        if os.path.exists(sDstFile):
            os.unlink(sDstFile);
        fRc = webutils.downloadFile(sZipUrl, sDstFile, self._oTestBoxScript.getPathBuilds(), testboxcommons.log);
        if fRc is not True:
            return False;

        if upgradeFromZip(sDstFile) is not True:
            return False;

        #
        # Restart the system or the script (we have a parent script which
        # respawns us when we quit).
        #
        if fReboot:
            self.doReboot();
        sys.exit(TBS_EXITCODE_NEED_UPGRADE);
        return False;                   # shuts up pylint (it will probably complain later when it learns DECL_NO_RETURN).

def _doUpgradeRemoveOldStuff(sUpgradeDir, asMembers):
    """
    Clean up all obsolete files and directories.
    Returns True (shouldn't fail or raise any exceptions).
    """

    try:
        shutil.rmtree(sUpgradeDir, ignore_errors = True);
    except:
        pass;

    asKnownFiles = [];
    asKnownDirs  = [];
    for sMember in asMembers:
        sMember = sMember[len('testboxscript/'):];
        if sMember == '':
            continue;
        if sMember[-1] == '/':
            asKnownDirs.append(os.path.normpath(os.path.join(g_ksValidationKitDir, sMember[:-1])));
        else:
            asKnownFiles.append(os.path.normpath(os.path.join(g_ksValidationKitDir, sMember)));

    for sDirPath, asDirs, asFiles in os.walk(g_ksValidationKitDir, topdown=False):
        for sDir in asDirs:
            sFull = os.path.normpath(os.path.join(sDirPath, sDir));
            if sFull not in asKnownDirs:
                testboxcommons.log2('Info: Removing obsolete directory "%s"' % (sFull,));
                try:
                    os.rmdir(sFull);
                except Exception as oXcpt:
                    testboxcommons.log('Warning: failed to rmdir obsolete dir "%s": %s' % (sFull, oXcpt));

        for sFile in asFiles:
            sFull = os.path.normpath(os.path.join(sDirPath, sFile));
            if sFull not in asKnownFiles:
                testboxcommons.log2('Info: Removing obsolete file "%s"' % (sFull,));
                try:
                    os.unlink(sFull);
                except Exception as oXcpt:
                    testboxcommons.log('Warning: failed to unlink obsolete file "%s": %s' % (sFull, oXcpt));
    return True;

    def handleCommand(self, oResponse, oConnection):
        """
        Handles a command from the test manager.

        Some commands will close the connection, others (generally the simple
        ones) wont, leaving the caller the option to use it for log flushing.

        Returns success indicator.
        Raises no exception.
        """
        try:
            sCmdName = oResponse.getStringChecked(constants.tbresp.ALL_PARAM_RESULT);
        except Exception as oXcpt:
            oConnection.close();
            return False;

        # Do we know the command?
        fRc = False;
        if sCmdName in self._dfnCommands:
            testboxcommons.log(sCmdName);
            try:
                # Execute the handler.
                fRc = self._dfnCommands[sCmdName](oResponse, oConnection)
            except Exception as oXcpt:
                # NACK the command if an exception is raised during parameter validation.
                testboxcommons.log1Xcpt('Exception executing "%s": %s' % (sCmdName, oXcpt));
                if oConnection.isConnected():
                    try:
                        oConnection.sendReplyAndClose(constants.tbreq.COMMAND_NACK, sCmdName);
                    except Exception as oXcpt2:
                        testboxcommons.log('Failed to NACK "%s": %s' % (sCmdName, oXcpt2));
        elif sCmdName in [constants.tbresp.STATUS_DEAD, constants.tbresp.STATUS_NACK]:
            testboxcommons.log('Received status instead of command: %s' % (sCmdName, ));
        else:
            # NOTSUP the unknown command.
            testboxcommons.log('Received unknown command: %s' % (sCmdName, ));
            try:
                oConnection.sendReplyAndClose(constants.tbreq.COMMAND_NOTSUP, sCmdName);
            except Exception as oXcpt:
                testboxcommons.log('Failed to NOTSUP "%s": %s' % (sCmdName, oXcpt));
        return fRc;

def _doUpgradeTestRun(sUpgradeDir):
    """
    Do a testrun of the new script, to make sure it doesn't fail with
    to run in any way because of old python, missing import or generally
    busted upgrade.
    Returns True/False.
    """
    asArgs = [os.path.join(sUpgradeDir, "testboxscript", "testboxscript", "testboxscript.py"), "--version"]
    testboxcommons.log("Testing the new testbox script (%s)..." % (asArgs[0],))
    if sys.executable is not None and len(sys.executable) > 0:
        asArgs.insert(0, sys.executable)
    oChild = subprocess.Popen(asArgs, shell=False, stdout=subprocess.PIPE, stderr=subprocess.STDOUT)

    asBuf = []
    oThread = threading.Thread(target=_doUpgradeThreadProc, args=(oChild.stdout, asBuf))
    oThread.daemon = True
    oThread.start()
    oThread.join(30)

    iStatus = oChild.poll()
    if iStatus is None:
        testboxcommons.log("Checking the new testboxscript timed out.")
        oChild.terminate()
        oThread.join(5)
        return False
    if iStatus is not TBS_EXITCODE_SYNTAX:
        testboxcommons.log(
            "The new testboxscript returned %d instead of %d during check." % (iStatus, TBS_EXITCODE_SYNTAX)
        )
        return False

    sOutput = "".join(asBuf)
    sOutput = sOutput.strip()
    try:
        iNewVersion = int(sOutput)
    except:
        testboxcommons.log('The new testboxscript returned an unparseable version string: "%s"!' % (sOutput,))
        return False
    testboxcommons.log("New script version: %s" % (iNewVersion,))
    return True

    def _doSignOn(self):
        """
        Worker for _maybeSignOn that does the actual signing on.
        """
        assert not self._oCommand.isRunning();

        # Reset the siged-on state.
        testboxcommons.log('Signing-on...')
        self._fSignedOn = False
        self._idTestBox = None
        self._cSignOnAttempts += 1;

        # Assemble SIGN-ON request parameters and send the request.
        dParams = {};
        for sParam in self._ddSignOnParams:
            dParams[sParam] = self._ddSignOnParams[sParam][self.VALUE];
        oResponse = TestBoxConnection.sendSignOn(self._oOptions.sTestManagerUrl, dParams);

        # Check response.
        try:
            sResult = oResponse.getStringChecked(constants.tbresp.ALL_PARAM_RESULT);
            if sResult != constants.tbresp.STATUS_ACK:
                raise TestBoxException('Result is %s' % (sResult,));
            oResponse.checkParameterCount(3);
            idTestBox    = oResponse.getIntChecked(constants.tbresp.SIGNON_PARAM_ID, 1, 0x7ffffffe);
            sTestBoxName = oResponse.getStringChecked(constants.tbresp.SIGNON_PARAM_NAME);
        except TestBoxException, err:
            testboxcommons.log('Failed to sign-on: %s' % (str(err),))
            testboxcommons.log('Server response: %s' % (oResponse.toString(),));
            return False;

def upgradeFromZip(sZipFile):
    """
    Upgrade the testboxscript install using the specified zip file.
    Returns True/False.
    """

    # A little precaution.
    if utils.isRunningFromCheckout():
        testboxcommons.log('Use "svn up" to "upgrade" your source tree!')
        return False

    #
    # Prepare.
    #
    # Note! Don't bother cleaning up files and dirs in the error paths,
    #       they'll be restricted to the one zip and the one upgrade dir.
    #       We'll remove them next time we upgrade.
    #
    oZip = zipfile.ZipFile(sZipFile, "r")
    asMembers = _doUpgradeCheckZip(oZip)
    if asMembers is None:
        return False

    sUpgradeDir = os.path.join(g_ksTestScriptDir, "upgrade")
    testboxcommons.log('Unzipping "%s" to "%s"...' % (sZipFile, sUpgradeDir))
    if _doUpgradeUnzipAndCheck(oZip, sUpgradeDir, asMembers) is not True:
        return False
    oZip.close()

    if _doUpgradeTestRun(sUpgradeDir) is not True:
        return False

    #
    # Execute.
    #
    if _doUpgradeApply(sUpgradeDir, asMembers) is not True:
        return False
    _doUpgradeRemoveOldStuff(sUpgradeDir, asMembers)
    return True

def _doUpgradeTestRun(sUpgradeDir):
    """
    Do a testrun of the new script, to make sure it doesn't fail with
    to run in any way because of old python, missing import or generally
    busted upgrade.
    Returns True/False.
    """
    asArgs = [os.path.join(sUpgradeDir, 'testboxscript', 'testboxscript', 'testboxscript.py'), '--version' ];
    testboxcommons.log('Testing the new testbox script (%s)...' % (asArgs[0],));
    if sys.executable:
        asArgs.insert(0, sys.executable);
    oChild = subprocess.Popen(asArgs, shell = False, stdout=subprocess.PIPE, stderr=subprocess.STDOUT);

    asBuf = []
    oThread = threading.Thread(target=_doUpgradeThreadProc, args=(oChild.stdout, asBuf));
    oThread.daemon = True;
    oThread.start();
    oThread.join(30);

    iStatus = oChild.poll();
    if iStatus is None:
        testboxcommons.log('Checking the new testboxscript timed out.');
        oChild.terminate();
        oThread.join(5);
        return False;
    if iStatus is not TBS_EXITCODE_SYNTAX:
        testboxcommons.log('The new testboxscript returned %d instead of %d during check.' \
                           % (iStatus, TBS_EXITCODE_SYNTAX));
        return False;

    sOutput = ''.join(asBuf);
    sOutput = sOutput.strip();
    try:
        iNewVersion = int(sOutput);
    except:
        testboxcommons.log('The new testboxscript returned an unparseable version string: "%s"!' % (sOutput,));
        return False;
    testboxcommons.log('New script version: %s' % (iNewVersion,));
    return True;