Changeset 80128 in vbox for trunk/src/VBox/ValidationKit/testmanager

Timestamp:

Aug 5, 2019 11:06:37 AM (6 years ago)

Author:

vboxsync

svn:sync-xref-src-repo-rev:

132569

Message:

vsheriff: Better detect VM process SIGSEGVs. [3rd try]

Location:

trunk/src/VBox/ValidationKit/testmanager

Files:

• batch/virtual_test_sheriff.py (modified) (15 diffs)
• core/testresults.py (modified) (4 diffs)

trunk/src/VBox/ValidationKit/testmanager/batch/virtual_test_sheriff.py

@@ -40 +40 @@
 
 # Standard python imports
+import hashlib;
+import os;
+import re;
+import smtplib;
+import subprocess;
 import sys;
-import os;
-import hashlib;
-import subprocess;
-import smtplib
-from email.mime.multipart import MIMEMultipart
-from email.mime.text import MIMEText
-from email.utils import COMMASPACE
+from email.mime.multipart   import MIMEMultipart;
+from email.mime.text        import MIMEText;
+from email.utils            import COMMASPACE;
 
 if sys.version_info[0] >= 3:
@@ -61 +62 @@
 
 # Test Manager imports
+from common                                 import utils;
 from testmanager.core.db                    import TMDatabaseConnection;
 from testmanager.core.build                 import BuildDataEx;
@@ -98 +100 @@
         self.oTestCase      = oTestCase;    # TestCaseDataEx
         self.sMainLog       = '';           # The main log file.  Empty string if not accessible.
+        self.sSvcLog        = '';           # The VBoxSVC log file.  Empty string if not accessible.
 
         # Generate a case file name.
@@ -238 +241 @@
             self.oSheriff.vprint(u'Error opening the "%s" log file: %s' % (oFile.sFile, oSizeOrError,));
         return sContent;
+
+    def getSvcLog(self):
+        """
+        Tries to read the VBoxSVC log file as it typically not associated with a failing test result.
+        Note! Returns the first VBoxSVC log file we find.
+        """
+        if not self.sSvcLog:
+            asSvcLogFiles = self.oTree.getListOfLogFilesByKind(TestResultFileData.ksKind_LogReleaseSvc);
+            if asSvcLogFiles:
+                self.sSvcLog = self.getLogFile(asSvcLogFiles[0]);
+        return self.sSvcLog;
 
     def getScreenshotSha256(self, oFile):
@@ -1018 +1032 @@
         ( True,  ktReason_OSInstall_Sata_no_BM,                     'PCHS=14128/14134/8224' ),
         ( True,  ktReason_Host_DoubleFreeHeap,                      'double free or corruption' ),
-        ( False, ktReason_Unknown_VM_Start_Error,                   'VMSetError: ' ),
+        #( False, ktReason_Unknown_VM_Start_Error,                   'VMSetError: ' ), - false positives for stuff like:
+        #           "VMSetError: VD: Backend 'VBoxIsoMaker' does not support async I/O"
         ( False, ktReason_Unknown_VM_Start_Error,                   'error: failed to open session for' ),
         ( False, ktReason_Unknown_VM_Runtime_Error,                 'Console: VM runtime error: fatal=true' ),
@@ -1096 +1111 @@
     ];
 
-    ## Things we search a VBoxSVC log for to figure out why something went bust.
-    katSimpleSvcLogReasons = [
-        # ( Whether to stop on hit, reason tuple, needle text. )
-        ( False, ktReason_Unknown_VM_Crash,                         ') exited normally: -1073741819 (0xc0000005)' ),
-        ( False, ktReason_Unknown_VM_Crash,                         ') was signalled: 11 (0xb)' ),
-    ];
+
+    def scanLog(self, asLogs, atNeedles, oCaseFile, idTestResult):
+        """
+        Scans for atNeedles in sLog.
+
+        Returns True if a stop-on-hit neelde was found.
+        Returns None if a no-stop reason was found.
+        Returns False if no hit.
+        """
+        fRet = False;
+        for fStopOnHit, tReason, oNeedle in atNeedles:
+            fMatch = False;
+            if utils.isString(oNeedle):
+                for sLog in asLogs:
+                    if sLog:
+                        fMatch |= sLog.find(oNeedle) > 0;
+            else:
+                for sLog in asLogs:
+                    if sLog:
+                        fMatch |= oNeedle.search(sLog) is not None;
+            if fMatch:
+                oCaseFile.noteReasonForId(tReason, idTestResult);
+                if fStopOnHit:
+                    return True;
+                fRet = None;
+        return fRet;
 
 
@@ -1113 +1148 @@
             Investigates the current set of VM related logs.
             """
-            self.dprint('investigateLogSet: log lengths: result %u, VM %u, kernel %u, vga text %u, info text %u, hard %u, SVC %u'
+            self.dprint('investigateLogSet: log lengths: result %u, VM %u, kernel %u, vga text %u, info text %u, hard %u'
                         % ( len(sResultLog if sResultLog else ''),
                             len(sVMLog     if sVMLog else ''),
@@ -1119 +1154 @@
                             len(sVgaText   if sVgaText else ''),
                             len(sInfoText  if sInfoText else ''),
-                            len(sNtHardLog if sNtHardLog else ''),
-                            len(sSvcLog    if sSvcLog else ''), ));
+                            len(sNtHardLog if sNtHardLog else ''),));
 
             #self.dprint(u'main.log<<<\n%s\n<<<\n' % (sResultLog,));
@@ -1150 +1184 @@
                 return oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult, sComment = sDetails.strip());
 
+            fFoundSomething = False;
+
             #
             # Look for linux panic.
             #
             if sKrnlLog is not None:
-                for fStopOnHit, tReason, sNeedle in self.katSimpleKernelLogReasons:
-                    if sKrnlLog.find(sNeedle) > 0:
-                        oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
-                        if fStopOnHit:
-                            return True;
-                        fFoundSomething = True;
+                fRet = self.scanLog([sKrnlLog,], self.katSimpleKernelLogReasons, oCaseFile, oFailedResult.idTestResult);
+                if fRet is True:
+                    return fRet;
+                fFoundSomething |= fRet is None;
 
             #
             # Loop thru the simple stuff.
             #
-            fFoundSomething = False;
-            for fStopOnHit, tReason, sNeedle in self.katSimpleMainAndVmLogReasons:
-                if sResultLog.find(sNeedle) > 0 or (sVMLog is not None and sVMLog.find(sNeedle) > 0):
-                    oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
-                    if fStopOnHit:
-                        return True;
-                    fFoundSomething = True;
+            fRet = self.scanLog([sResultLog, sVMLog], self.katSimpleMainAndVmLogReasons, oCaseFile, oFailedResult.idTestResult);
+            if fRet is True:
+                return fRet;
+            fFoundSomething |= fRet is None;
 
             # Continue with vga text.
             if sVgaText:
-                for fStopOnHit, tReason, sNeedle in self.katSimpleVgaTextReasons:
-                    if sVgaText.find(sNeedle) > 0:
-                        oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
-                        if fStopOnHit:
-                            return True;
-                        fFoundSomething = True;
-            _ = sInfoText;
+                fRet = self.scanLog([sVgaText,], self.katSimpleVgaTextReasons, oCaseFile, oFailedResult.idTestResult);
+                if fRet is True:
+                    return fRet;
+                fFoundSomething |= fRet is None;
 
             # Continue with screen hashes.
@@ -1193 +1221 @@
             # Check VBoxHardening.log.
             if sNtHardLog is not None:
-                for fStopOnHit, tReason, sNeedle in self.katSimpleVBoxHardeningLogReasons:
-                    if sNtHardLog.find(sNeedle) > 0:
-                        oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
-                        if fStopOnHit:
-                            return True;
-                        fFoundSomething = True;
-
-            # Check VBoxSVC.log.
-            if sSvcLog is not None:
-                for fStopOnHit, tReason, sNeedle in self.katSimpleSvcLogReasons:
-                    if sSvcLog.find(sNeedle) > 0:
-                        oCaseFile.noteReasonForId(tReason, oFailedResult.idTestResult);
-                        if fStopOnHit:
-                            return True;
-                        fFoundSomething = True;
+                fRet = self.scanLog([sNtHardLog,], self.katSimpleVBoxHardeningLogReasons, oCaseFile, oFailedResult.idTestResult);
+                if fRet is True:
+                    return fRet;
+                fFoundSomething |= fRet is None;
 
             #
@@ -1255 +1272 @@
         sVgaText    = None;
         sInfoText   = None;
-        sSvcLog     = None;
         for oFile in oFailedResult.aoFiles:
             if oFile.sKind == TestResultFileData.ksKind_LogReleaseVm:
@@ -1268 +1284 @@
                     sScreenHash = None;
                     sNtHardLog  = None;
-                    sSvcLog     = None;
                     sVMLog      = oCaseFile.getLogFile(oFile);
                 else:
@@ -1278 +1293 @@
             elif oFile.sKind == TestResultFileData.ksKind_InfoCollection:
                 sInfoText = oCaseFile.getLogFile(oFile);
-            elif oFile.sKind == TestResultFileData.ksKind_LogReleaseSvc:
-                sSvcLog   = oCaseFile.getLogFile(oFile);
             elif oFile.sKind == TestResultFileData.ksKind_ScreenshotFailure:
                 sScreenHash = oCaseFile.getScreenshotSha256(oFile);
@@ -1293 +1306 @@
 
         return None;
+
+    ## Things we search a VBoxSVC log for to figure out why something went bust.
+    katSimpleSvcLogReasons = [
+        # ( Whether to stop on hit, reason tuple, needle text. )
+        ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* exited normally: -1073741819 \(0xc0000005\)') ),
+        ( False, ktReason_Unknown_VM_Crash, re.compile(r'Reaper.* was signalled: 11 \(0xb\)') ),
+    ];
+
+    def investigateSvcLogForVMRun(self, oCaseFile, sSvcLog):
+        """
+        Check the VBoxSVC log for a single VM run.
+        """
+        if sSvcLog:
+            fRet = self.scanLog([sSvcLog,], self.katSimpleSvcLogReasons, oCaseFile, oCaseFile.oTree.idTestResult);
+            if fRet is True or fRet is None:
+                return True;
+        return False;
 
 
@@ -1401 +1431 @@
                 self.vprint(u'TODO: Cannot place idTestResult=%u - %s' % (oFailedResult.idTestResult, oFailedResult.sName,));
                 self.dprint(u'%s + %s <<\n%s\n<<' % (oFailedResult.tsCreated, oFailedResult.tsElapsed, sResultLog,));
+
+        #
+        # Check VBoxSVC.log for VM crashes if inconclusive on single VM runs.
+        #
+        if fSingleVM and len(oCaseFile.dReasonForResultId) < len(aoFailedResults):
+            self.dprint(u'Got %u out of %u - checking VBoxSVC.log...'
+                        % (len(oCaseFile.dReasonForResultId), len(aoFailedResults)));
+            if self.investigateSvcLogForVMRun(oCaseFile, oCaseFile.getSvcLog()):
+                return self.caseClosed(oCaseFile);
 
         #

trunk/src/VBox/ValidationKit/testmanager/core/testresults.py

@@ -220 +220 @@
         Get a list of test results instances actually contributing to cErrors.
 
-        Returns a list of TestResultDataEx instance from this tree. (shared!)
+        Returns a list of TestResultDataEx instances from this tree. (shared!)
         """
         # Check each child (if any).
@@ -233 +233 @@
         if self.cErrors > cChildErrors:
             aoRet.append(self);
+
+        return aoRet;
+
+    def getListOfLogFilesByKind(self, asKinds):
+        """
+        Get a list of test results instances actually contributing to cErrors.
+
+        Returns a list of TestResultFileDataEx instances from this tree. (shared!)
+        """
+        aoRet = [];
+
+        # Check the children first.
+        for oChild in self.aoChildren:
+            aoRet.extend(oChild.getListOfLogFilesByKind(asKinds));
+
+        # Check our own files next.
+        for oFile in self.aoFiles:
+            if oFile.sKind in asKinds:
+                aoRet.append(oFile);
 
         return aoRet;
@@ -402 +421 @@
     ksKind_LogDebugVm           = 'log/debug/vm';
     ksKind_LogReleaseSvc        = 'log/release/svc';
-    ksKind_LogRebugSvc          = 'log/debug/svc';
+    ksKind_LogDebugSvc          = 'log/debug/svc';
     ksKind_LogReleaseClient     = 'log/release/client';
     ksKind_LogDebugClient       = 'log/debug/client';
@@ -427 +446 @@
         ksKind_LogDebugVm,
         ksKind_LogReleaseSvc,
-        ksKind_LogRebugSvc,
+        ksKind_LogDebugSvc,
         ksKind_LogReleaseClient,
         ksKind_LogDebugClient,