Changeset 65855 in vbox for trunk/src/VBox

Timestamp:

Feb 23, 2017 12:23:08 PM (8 years ago)

Author:

vboxsync

Message:

testdriver/reporter.py: Redid locking to account for garbage collection causing trouble when it calls del methods with log statements. Since those statements can be very useful, the reporter now disables GC while it's owning the lock, but allow recursion in case GC runs before we disables it or immediately after reenabling it.

File:

• trunk/src/VBox/ValidationKit/testdriver/reporter.py (modified) (3 diffs)

trunk/src/VBox/ValidationKit/testdriver/reporter.py

@@ -35 +35 @@
 import datetime
 import errno
+import gc
 import os
 import os.path
@@ -48 +49 @@
 g_oReporter = None;                     # type: ReporterBase
 g_sReporterName = None;
-g_oLock = threading.Lock();
-
-# Lock wrapper:
-class LockWrapper(object):
-    """ Temporary lock wrapper to debug deadlocks on the macs. """
-
-    kcMsTimeout = 15000;
+
+
+class ReporterLock(object):
+    """
+    Work around problem with garbage collection triggering __del__ method with
+    logging while inside the logger lock and causing a deadlock.
+    """
 
     def __init__(self, sName):
-        self.sName  = sName;
-        self.oLock  = threading.Lock();
-        self.oOwner = None;
-        self.oPrevOwner = None;
-        self.cAcquired = 0;
-        self.oReportingError = None;
-
-    def acquire(self, blocking = True):
+        self.sName          = sName;
+        self.oLock          = threading.RLock();
+        self.oOwner         = None;
+        self.cRecursion     = 0;
+        self.fRestoreGC     = False;
+
+    def acquire(self):
         """ Acquire the lock. """
         oSelf = threading.current_thread();
 
-        # Special case for avoiding recursive error reports via the error method.
-        if self.oReportingError == oSelf:
-            return True;
-
-        # Check ownership.
-        if oSelf == self.oOwner:
-            self.error('Recursive lock %s entry on thread %s' % (self.sName, oSelf,));
-
-        # Try acquire it (non-blocking).
-        if not self.oLock.acquire(False):
-            if not blocking:
-                return False;
-            msStart = utils.timestampMilli();
-            while True:
-                if self.oLock.acquire(False):
-                    break;
-                cMsElapsed = utils.timestampMilli() - msStart;
-                if cMsElapsed > 1:
-                    if cMsElapsed > self.kcMsTimeout:
-                        self.error('Thread %s has waited more than %u seconds on lock %s to be released by %s'
-                                   % (oSelf, self.kcMsTimeout / 1000, self.sName, self.oOwner,), fAllThreads = True);
-                    time.sleep(0.001);
-
-        # Got it. Update stats.
-        self.oOwner = oSelf;
-        self.cAcquired += 1;
+        # Take the lock.
+        if not self.oLock.acquire():
+            return False;
+
+        self.oOwner      = oSelf;
+        self.cRecursion += 1;
+
+        # Disable GC to avoid __del__ w/ log statement randomly reenter the logger.
+        self.fRestoreGC  = gc.isenabled();
+        if self.fRestoreGC:
+            gc.disable();
+
         return True;
 
@@ -99 +85 @@
         """ Release the lock. """
         oSelf = threading.current_thread();
-        # Skip if we're in the error method (see acquire).
-        if self.oReportingError == oSelf:
-            pass;
-        # Check ownership.
-        elif oSelf != self.oOwner:
-            self.error('Thread %s is trying to release %s without owning it' % (oSelf, self.sName,));
-        # Housekeeping first, then relase for real.
-        else:
-            self.oPrevOwner = oSelf;
+
+        # Check the ownership.
+        if oSelf != self.oOwner:
+            raise threading.ThreadError();
+
+        # Drop one recursion.
+        self.cRecursion -= 1;
+        if self.cRecursion <= 0:
+
+            # Final recursion. Clear owner and re-enable GC.
             self.oOwner = None;
-            self.oLock.release();
-
-    def error(self, sMessage, fAllThreads = False):
-        """ Reports a problem. Raises exception."""
-        #
-        # Get the ID of the current thread and the current and previous lock owners.
-        #
-        oSelf = threading.current_thread();
-        try:    idSelf = threading.current_thread().ident;
-        except: idSelf = -1;
-
-        try:    idOwner = self.oOwner.ident if self.oOwner is not None else -2;
-        except: idOwner = -1;
-        try:    sOwnerNm = self.oOwner.name if self.oOwner is not None else '<none>';
-        except: sOwnerNm = -1;
-
-        try:    idPrevOwner = self.oPrevOwner.ident if self.oPrevOwner is not None else -2;
-        except: idPrevOwner = -1;
-        try:    sPrevOwnerNm = self.oPrevOwner.name if self.oPrevOwner is not None else '<none>';
-        except: sPrevOwnerNm = -1;
-
-        # First to stdout.
-        print '!Lock trouble! %s idSelf=%s (%s)' % ( self.sName, idSelf, oSelf,);
-        print '!Lock trouble! %s' % (sMessage,);
-        print '!Lock trouble! %s idOwner=%s sOwnerNm=%s' % (self.sName, idOwner, sOwnerNm,);
-        print '!Lock trouble! %s idPrevOwner=%s sPrevOwnerNm=%s' % (self.sName, idPrevOwner, sPrevOwnerNm,);
-        print '!Lock trouble! %s cAcquired=%d' % (self.sName, self.cAcquired,);
-        sys.stdout.flush()
-
-        # Append to special log file (unbuffered).
-        try:
-            oFile = open('/tmp/reporter-lock-validation.log', 'a', 0)
-        except:
-            oFile = sys.stderr;
-        oFile.write('lock=%s tid=%s (%s) %s\n' % (self.sName, idSelf, oSelf, sMessage,));
-        oFile.write('lock=%s idOwner=%s sOwnerNm=%s idPrevOwner=%s sPrevOwnerNm=%s cAcquired=%s\n'
-                    % (self.sName, idOwner, sOwnerNm, idPrevOwner, sPrevOwnerNm, self.cAcquired));
-
-        #
-        # Get thread stack(s).
-        #
-        asStacks = [];
-        try:
-            for idThread, oStack in sys._current_frames().items(): # >=2.5, a bit ugly - pylint: disable=W0212
-                if not fAllThreads and idThread != idSelf and idSelf != -1:
-                    continue;
-                try:
-                    if asStacks:
-                        asStacks.append('');
-                    asStacks.append('Thread %s (%#x)' % (idThread, idThread));
-                    try:
-                        asInfo = traceback.format_stack(oStack, 20);
-                    except Exception as oXcpt:
-                        asStacks.append('  Stack formatting exception #2: %s' % (oXcpt,));
-                    else:
-                        for sInfo in asInfo:
-                            asStacks.extend(sInfo.splitlines());
-                except Exception as oXcpt:
-                    asStacks.append('  Stack formatting exception #1: %s' % (oXcpt,));
-        except Exception as oXcpt:
-            asStacks.append('  Stack formatting exception #0: %s' % (oXcpt,));
-
-        #
-        # Write the stacks to stdout then to the log file.
-        #
-        for sLine in asStacks:
-            print '!Lock trouble! %s' % (sLine,);
-        sys.stderr.flush()
-
-        for sLine in asStacks:
-            oFile.write('%s\n' % (sLine,));
-
-        if oFile != sys.stderr:
-            try:    oFile.close();
-            except: pass;
-
-        #
-        # Now for the risky part, try log it using the logger.
-        #
-        try:
-            self.oReportingError = oSelf;
-            g_oReporter.log(1, '!Lock %s trouble! %s' % (self.sName, sMessage,));
-            for sLine in asStacks:
-                g_oReporter.log(1, '!Lock %s trouble! %s' % (self.sName, sLine,));
-        except:
-            pass;
-        finally:
-            self.oReportingError = None;
-        raise Exception(sMessage);
-
-if utils.getHostOs() in ['darwin', 'solaris', 'linux']:
-    g_oLock = LockWrapper('reporter');
+            if self.fRestoreGC:
+                self.fRestoreGC = False;
+                gc.enable();
+
+        self.oLock.release();
+
+## Reporter lock.
+g_oLock = ReporterLock('reporter');