testtools-dev team mailing list archive

["Martin \[gz\]" <gzlist@xxxxxxxxxxxxxx>]

Martin [gz] has proposed merging lp:~gz/testtools/result_timings_forwarding_625594 into lp:testtools.

Requested reviews:
  testtools developers (testtools-dev)
Related bugs:
  #625594 selftest --parallel test case timings incorrect
  https://bugs.launchpad.net/bugs/625594


The testtools half of the fix for bug 625594, see <lp:~gz/bzr/use_testtools_timings_625594> for the bzr part.

ThreadsafeForwardingResult was simulating a test run from startTest to add<Result> to stopTest all in one go, so that concurrent tests don't interfere with each other in the reporting. This mostly doesn't matter as subunit doesn't flush its output stream so you get buffer-sized chunks from child processes, but does mean that the test result class doing the actual reporting thinks every test is nearly instant.

What we want to do is record and forward the relevant times subunit reports to the wrapped result, but I don't see a particularly pretty way of doing this. This change stashes the current stamp on the test case (which should be thread-local) when startTest is run, then retrieves it and reports it before startTest is forwarded, then forwards the now-current stamp before calling the add<Result> method.

Haven't really added sufficient test suite coverage here, and make the implementation tolerant of timestamps being given as the tests tend to call result methods out of sequence and expect sanity.

I welcome suggestions to make all this less horrid, and hope to dream some tonight.
-- 
https://code.launchpad.net/~gz/testtools/result_timings_forwarding_625594/+merge/36786
Your team testtools developers is requested to review the proposed merge of lp:~gz/testtools/result_timings_forwarding_625594 into lp:testtools.

=== modified file 'NEWS'
--- NEWS	2010-09-18 02:10:58 +0000
+++ NEWS	2010-09-27 20:41:03 +0000
@@ -16,6 +16,10 @@
 * In normal circumstances, a TestCase will no longer share details with clones
   of itself. (Andrew Bennetts, bug #637725)
 
+* Timestamps as produced by subunit protocol clients are now forwarded in the
+  ThreadsafeForwardingResult so correct test durations can be reported.
+  (Martin [gz], #625594)
+
 
 0.9.6
 ~~~~~

=== modified file 'testtools/testresult/real.py'
--- testtools/testresult/real.py	2010-08-04 14:59:59 +0000
+++ testtools/testresult/real.py	2010-09-27 20:41:03 +0000
@@ -299,60 +299,45 @@
         TestResult.__init__(self)
         self.result = ExtendedToOriginalDecorator(target)
         self.semaphore = semaphore
+        self._use_timings = False
+
+    def _add_result_with_semaphore(self, method, test, *args, **kwargs):
+        self.semaphore.acquire()
+        try:
+            if self._use_timings:
+                self.result.time(test._testtools_time_of_startTest)
+                self.result.startTest(test)
+                self.result.time(self._now())
+            else:
+                self.result.startTest(test)
+            method(test, *args, **kwargs)
+            self.result.stopTest(test)
+        finally:
+            self.semaphore.release()
 
     def addError(self, test, err=None, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addError(test, err, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addError,
+            test, err, details=details)
 
     def addExpectedFailure(self, test, err=None, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addExpectedFailure(test, err, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addExpectedFailure,
+            test, err, details=details)
 
     def addFailure(self, test, err=None, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addFailure(test, err, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addFailure,
+            test, err, details=details)
 
     def addSkip(self, test, reason=None, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addSkip(test, reason, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addSkip,
+            test, reason, details=details)
 
     def addSuccess(self, test, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addSuccess(test, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addSuccess,
+            test, details=details)
 
     def addUnexpectedSuccess(self, test, details=None):
-        self.semaphore.acquire()
-        try:
-            self.result.startTest(test)
-            self.result.addUnexpectedSuccess(test, details=details)
-            self.result.stopTest(test)
-        finally:
-            self.semaphore.release()
+        self._add_result_with_semaphore(self.result.addUnexpectedSuccess,
+            test, details=details)
 
     def startTestRun(self):
         self.semaphore.acquire()
@@ -375,6 +360,15 @@
         finally:
             self.semaphore.release()
 
+    def startTest(self, test):
+        test._testtools_time_of_startTest = self._now()
+        super(ThreadsafeForwardingResult, self).startTest(test)
+
+    def time(self, a_datetime):
+        self._use_timings = True
+        self.time = super(ThreadsafeForwardingResult, self).time
+        self.time(a_datetime)
+
 
 class ExtendedToOriginalDecorator(object):
     """Permit new TestResult API code to degrade gracefully with old results.

=== modified file 'testtools/tests/helpers.py'
--- testtools/tests/helpers.py	2009-12-31 03:15:19 +0000
+++ testtools/tests/helpers.py	2010-09-27 20:41:03 +0000
@@ -62,6 +62,10 @@
         self._events.append('done')
         super(LoggingResult, self).done()
 
+    def time(self, a_datetime):
+        self._events.append(('time', a_datetime))
+        super(LoggingResult, self).time(a_datetime)
+
 # Note, the following three classes are different to LoggingResult by
 # being fully defined exact matches rather than supersets.
 from testtools.testresult.doubles import *

=== modified file 'testtools/tests/test_testresult.py'
--- testtools/tests/test_testresult.py	2010-08-04 14:59:32 +0000
+++ testtools/tests/test_testresult.py	2010-09-27 20:41:03 +0000
@@ -419,7 +419,7 @@
 
 
 class TestThreadSafeForwardingResult(TestWithFakeExceptions):
-    """Tests for `MultiTestResult`."""
+    """Tests for `TestThreadSafeForwardingResult`."""
 
     def setUp(self):
         TestWithFakeExceptions.setUp(self)
@@ -472,6 +472,20 @@
             ('stopTest', self),
             ], self.target._events)
 
+    def test_times(self):
+        starttime = datetime.datetime.utcfromtimestamp(1.489)
+        endtime = datetime.datetime.utcfromtimestamp(51.476)
+        self.result1.time(starttime)
+        self.result1.startTest(self)
+        self.result1.time(endtime)
+        self.result1.addSuccess(self)
+        self.assertEqual([("time", starttime),
+            ("startTest", self),
+            ("time", endtime),
+            ("addSuccess", self),
+            ("stopTest", self),
+            ], self.target._events)
+
 
 class TestExtendedToOriginalResultDecoratorBase(TestCase):