196
194
self._overall_start_time = time.time()
197
195
self._strict = strict
196
self._first_thread_leaker_id = None
197
self._tests_leaking_threads_count = 0
198
self._traceback_from_test = None
199
200
def stopTestRun(self):
200
201
run = self.testsRun
201
202
actionTaken = "Ran"
202
203
stopTime = time.time()
203
204
timeTaken = stopTime - self.startTime
205
self.stream.writeln(self.separator2)
206
self.stream.writeln("%s %d test%s in %.3fs" % (actionTaken,
205
# GZ 2010-07-19: Seems testtools has no printErrors method, and though
206
# the parent class method is similar have to duplicate
207
self._show_list('ERROR', self.errors)
208
self._show_list('FAIL', self.failures)
209
self.stream.write(self.sep2)
210
self.stream.write("%s %d test%s in %.3fs\n\n" % (actionTaken,
207
211
run, run != 1 and "s" or "", timeTaken))
208
self.stream.writeln()
209
212
if not self.wasSuccessful():
210
213
self.stream.write("FAILED (")
211
214
failed, errored = map(len, (self.failures, self.errors))
218
221
if failed or errored: self.stream.write(", ")
219
222
self.stream.write("known_failure_count=%d" %
220
223
self.known_failure_count)
221
self.stream.writeln(")")
224
self.stream.write(")\n")
223
226
if self.known_failure_count:
224
self.stream.writeln("OK (known_failures=%d)" %
227
self.stream.write("OK (known_failures=%d)\n" %
225
228
self.known_failure_count)
227
self.stream.writeln("OK")
230
self.stream.write("OK\n")
228
231
if self.skip_count > 0:
229
232
skipped = self.skip_count
230
self.stream.writeln('%d test%s skipped' %
233
self.stream.write('%d test%s skipped\n' %
231
234
(skipped, skipped != 1 and "s" or ""))
232
235
if self.unsupported:
233
236
for feature, count in sorted(self.unsupported.items()):
234
self.stream.writeln("Missing feature '%s' skipped %d tests." %
237
self.stream.write("Missing feature '%s' skipped %d tests.\n" %
235
238
(feature, count))
237
240
ok = self.wasStrictlySuccessful()
239
242
ok = self.wasSuccessful()
240
if TestCase._first_thread_leaker_id:
243
if self._first_thread_leaker_id:
241
244
self.stream.write(
242
245
'%s is leaking threads among %d leaking tests.\n' % (
243
TestCase._first_thread_leaker_id,
244
TestCase._leaking_threads_tests))
246
self._first_thread_leaker_id,
247
self._tests_leaking_threads_count))
245
248
# We don't report the main thread as an active one.
246
249
self.stream.write(
247
250
'%d non-main threads were left active in the end.\n'
248
% (TestCase._active_threads - 1))
251
% (len(self._active_threads) - 1))
250
253
def getDescription(self, test):
276
280
def _shortened_test_description(self, test):
278
what = re.sub(r'^bzrlib\.(tests|benchmarks)\.', '', what)
282
what = re.sub(r'^bzrlib\.tests\.', '', what)
285
# GZ 2010-10-04: Cloned tests may end up harmlessly calling this method
286
# multiple times in a row, because the handler is added for
287
# each test but the container list is shared between cases.
288
# See lp:498869 lp:625574 and lp:637725 for background.
289
def _record_traceback_from_test(self, exc_info):
290
"""Store the traceback from passed exc_info tuple till"""
291
self._traceback_from_test = exc_info[2]
281
293
def startTest(self, test):
282
unittest.TestResult.startTest(self, test)
294
super(ExtendedTestResult, self).startTest(test)
283
295
if self.count == 0:
284
296
self.startTests()
285
298
self.report_test_start(test)
286
299
test.number = self.count
287
300
self._recordTestStartTime()
301
# Make testtools cases give us the real traceback on failure
302
addOnException = getattr(test, "addOnException", None)
303
if addOnException is not None:
304
addOnException(self._record_traceback_from_test)
305
# Only check for thread leaks if the test case supports cleanups
306
addCleanup = getattr(test, "addCleanup", None)
307
if addCleanup is not None:
308
addCleanup(self._check_leaked_threads, test)
289
310
def startTests(self):
291
if getattr(sys, 'frozen', None) is None:
292
bzr_path = osutils.realpath(sys.argv[0])
294
bzr_path = sys.executable
296
'bzr selftest: %s\n' % (bzr_path,))
299
bzrlib.__path__[0],))
301
' bzr-%s python-%s %s\n' % (
302
bzrlib.version_string,
303
bzrlib._format_version_tuple(sys.version_info),
304
platform.platform(aliased=1),
306
self.stream.write('\n')
311
self.report_tests_starting()
312
self._active_threads = threading.enumerate()
314
def stopTest(self, test):
315
self._traceback_from_test = None
317
def _check_leaked_threads(self, test):
318
"""See if any threads have leaked since last call
320
A sample of live threads is stored in the _active_threads attribute,
321
when this method runs it compares the current live threads and any not
322
in the previous sample are treated as having leaked.
324
now_active_threads = set(threading.enumerate())
325
threads_leaked = now_active_threads.difference(self._active_threads)
327
self._report_thread_leak(test, threads_leaked, now_active_threads)
328
self._tests_leaking_threads_count += 1
329
if self._first_thread_leaker_id is None:
330
self._first_thread_leaker_id = test.id()
331
self._active_threads = now_active_threads
308
333
def _recordTestStartTime(self):
309
334
"""Record that a test has started."""
310
self._start_time = time.time()
312
def _cleanupLogFile(self, test):
313
# We can only do this if we have one of our TestCases, not if
315
setKeepLogfile = getattr(test, 'setKeepLogfile', None)
316
if setKeepLogfile is not None:
335
self._start_datetime = self._now()
319
337
def addError(self, test, err):
320
338
"""Tell result that test finished with an error.
322
340
Called from the TestCase run() method when the test
323
341
fails with an unexpected error.
326
unittest.TestResult.addError(self, test, err)
343
self._post_mortem(self._traceback_from_test)
344
super(ExtendedTestResult, self).addError(test, err)
327
345
self.error_count += 1
328
346
self.report_error(test, err)
329
347
if self.stop_early:
331
self._cleanupLogFile(test)
333
350
def addFailure(self, test, err):
334
351
"""Tell result that test failed.
336
353
Called from the TestCase run() method when the test
337
354
fails because e.g. an assert() method failed.
340
unittest.TestResult.addFailure(self, test, err)
356
self._post_mortem(self._traceback_from_test)
357
super(ExtendedTestResult, self).addFailure(test, err)
341
358
self.failure_count += 1
342
359
self.report_failure(test, err)
343
360
if self.stop_early:
345
self._cleanupLogFile(test)
347
363
def addSuccess(self, test, details=None):
348
364
"""Tell result that test completed successfully.
401
417
raise errors.BzrError("Unknown whence %r" % whence)
403
def report_cleaning_up(self):
419
def report_tests_starting(self):
420
"""Display information before the test run begins"""
421
if getattr(sys, 'frozen', None) is None:
422
bzr_path = osutils.realpath(sys.argv[0])
424
bzr_path = sys.executable
426
'bzr selftest: %s\n' % (bzr_path,))
429
bzrlib.__path__[0],))
431
' bzr-%s python-%s %s\n' % (
432
bzrlib.version_string,
433
bzrlib._format_version_tuple(sys.version_info),
434
platform.platform(aliased=1),
436
self.stream.write('\n')
438
def report_test_start(self, test):
439
"""Display information on the test just about to be run"""
441
def _report_thread_leak(self, test, leaked_threads, active_threads):
442
"""Display information on a test that leaked one or more threads"""
443
# GZ 2010-09-09: A leak summary reported separately from the general
444
# thread debugging would be nice. Tests under subunit
445
# need something not using stream, perhaps adding a
446
# testtools details object would be fitting.
447
if 'threads' in selftest_debug_flags:
448
self.stream.write('%s is leaking, active is now %d\n' %
449
(test.id(), len(active_threads)))
406
451
def startTestRun(self):
407
452
self.startTime = time.time()
444
489
self.pb.finished()
445
490
super(TextTestResult, self).stopTestRun()
447
def startTestRun(self):
448
super(TextTestResult, self).startTestRun()
492
def report_tests_starting(self):
493
super(TextTestResult, self).report_tests_starting()
449
494
self.pb.update('[test 0/%d] Starting' % (self.num_tests))
451
def printErrors(self):
452
# clear the pb to make room for the error listing
454
super(TextTestResult, self).printErrors()
456
496
def _progress_prefix_text(self):
457
497
# the longer this text, the less space we have to show the test
551
586
return '%s%s' % (indent, err[1])
553
588
def report_error(self, test, err):
554
self.stream.writeln('ERROR %s\n%s'
589
self.stream.write('ERROR %s\n%s\n'
555
590
% (self._testTimeString(test),
556
591
self._error_summary(err)))
558
593
def report_failure(self, test, err):
559
self.stream.writeln(' FAIL %s\n%s'
594
self.stream.write(' FAIL %s\n%s\n'
560
595
% (self._testTimeString(test),
561
596
self._error_summary(err)))
563
598
def report_known_failure(self, test, err):
564
self.stream.writeln('XFAIL %s\n%s'
599
self.stream.write('XFAIL %s\n%s\n'
565
600
% (self._testTimeString(test),
566
601
self._error_summary(err)))
568
603
def report_success(self, test):
569
self.stream.writeln(' OK %s' % self._testTimeString(test))
604
self.stream.write(' OK %s\n' % self._testTimeString(test))
570
605
for bench_called, stats in getattr(test, '_benchcalls', []):
571
self.stream.writeln('LSProf output for %s(%s, %s)' % bench_called)
606
self.stream.write('LSProf output for %s(%s, %s)\n' % bench_called)
572
607
stats.pprint(file=self.stream)
573
608
# flush the stream so that we get smooth output. This verbose mode is
574
609
# used to show the output in PQM.
575
610
self.stream.flush()
577
612
def report_skip(self, test, reason):
578
self.stream.writeln(' SKIP %s\n%s'
613
self.stream.write(' SKIP %s\n%s\n'
579
614
% (self._testTimeString(test), reason))
581
616
def report_not_applicable(self, test, reason):
582
self.stream.writeln(' N/A %s\n %s'
617
self.stream.write(' N/A %s\n %s\n'
583
618
% (self._testTimeString(test), reason))
585
620
def report_unsupported(self, test, feature):
586
621
"""test cannot be run because feature is missing."""
587
self.stream.writeln("NODEP %s\n The feature '%s' is not available."
622
self.stream.write("NODEP %s\n The feature '%s' is not available.\n"
588
623
%(self._testTimeString(test), feature))
789
824
routine, and to build and check bzr trees.
791
826
In addition to the usual method of overriding tearDown(), this class also
792
allows subclasses to register functions into the _cleanups list, which is
827
allows subclasses to register cleanup functions via addCleanup, which are
793
828
run in order as the object is torn down. It's less likely this will be
794
829
accidentally overlooked.
797
_active_threads = None
798
_leaking_threads_tests = 0
799
_first_thread_leaker_id = None
800
_log_file_name = None
801
833
# record lsprof data when performing benchmark calls.
802
834
_gather_lsprof_in_benchmarks = False
804
836
def __init__(self, methodName='testMethod'):
805
837
super(TestCase, self).__init__(methodName)
807
838
self._directory_isolation = True
808
839
self.exception_handlers.insert(0,
809
840
(UnavailableFeature, self._do_unsupported_or_skip))
827
858
self._track_transports()
828
859
self._track_locks()
829
860
self._clear_debug_flags()
830
TestCase._active_threads = threading.activeCount()
831
self.addCleanup(self._check_leaked_threads)
834
863
# debug a frame up.
836
865
pdb.Pdb().set_trace(sys._getframe().f_back)
838
def _check_leaked_threads(self):
839
active = threading.activeCount()
840
leaked_threads = active - TestCase._active_threads
841
TestCase._active_threads = active
842
# If some tests make the number of threads *decrease*, we'll consider
843
# that they are just observing old threads dieing, not agressively kill
844
# random threads. So we don't report these tests as leaking. The risk
845
# is that we have false positives that way (the test see 2 threads
846
# going away but leak one) but it seems less likely than the actual
847
# false positives (the test see threads going away and does not leak).
848
if leaked_threads > 0:
849
TestCase._leaking_threads_tests += 1
850
if TestCase._first_thread_leaker_id is None:
851
TestCase._first_thread_leaker_id = self.id()
867
def discardDetail(self, name):
868
"""Extend the addDetail, getDetails api so we can remove a detail.
870
eg. bzr always adds the 'log' detail at startup, but we don't want to
871
include it for skipped, xfail, etc tests.
873
It is safe to call this for a detail that doesn't exist, in case this
874
gets called multiple times.
876
# We cheat. details is stored in __details which means we shouldn't
877
# touch it. but getDetails() returns the dict directly, so we can
879
details = self.getDetails()
853
883
def _clear_debug_flags(self):
854
884
"""Prevent externally set debug flags affecting tests.
1487
1515
debug.debug_flags.discard('strict_locks')
1489
def addCleanup(self, callable, *args, **kwargs):
1490
"""Arrange to run a callable when this case is torn down.
1492
Callables are run in the reverse of the order they are registered,
1493
ie last-in first-out.
1495
self._cleanups.append((callable, args, kwargs))
1497
1517
def overrideAttr(self, obj, attr_name, new=_unitialized_attr):
1498
1518
"""Overrides an object attribute restoring it after the test.
1612
1639
self._do_skip(result, reason)
1642
def _report_skip(self, result, err):
1643
"""Override the default _report_skip.
1645
We want to strip the 'log' detail. If we waint until _do_skip, it has
1646
already been formatted into the 'reason' string, and we can't pull it
1649
self._suppress_log()
1650
super(TestCase, self)._report_skip(self, result, err)
1653
def _report_expected_failure(self, result, err):
1656
See _report_skip for motivation.
1658
self._suppress_log()
1659
super(TestCase, self)._report_expected_failure(self, result, err)
1615
1662
def _do_unsupported_or_skip(self, result, e):
1616
1663
reason = e.args[0]
1664
self._suppress_log()
1617
1665
addNotSupported = getattr(result, 'addNotSupported', None)
1618
1666
if addNotSupported is not None:
1619
1667
result.addNotSupported(self, reason)
1666
1714
unicodestr = self._log_contents.decode('utf8', 'replace')
1667
1715
self._log_contents = unicodestr.encode('utf8')
1668
1716
return self._log_contents
1670
if bzrlib.trace._trace_file:
1671
# flush the log file, to get all content
1672
bzrlib.trace._trace_file.flush()
1673
if self._log_file_name is not None:
1674
logfile = open(self._log_file_name)
1676
log_contents = logfile.read()
1717
if self._log_file is not None:
1718
log_contents = self._log_file.getvalue()
1680
1720
log_contents.decode('utf8')
1681
1721
except UnicodeDecodeError:
1682
1722
unicodestr = log_contents.decode('utf8', 'replace')
1683
1723
log_contents = unicodestr.encode('utf8')
1684
1724
if not keep_log_file:
1686
max_close_attempts = 100
1687
first_close_error = None
1688
while close_attempts < max_close_attempts:
1691
self._log_file.close()
1692
except IOError, ioe:
1693
if ioe.errno is None:
1694
# No errno implies 'close() called during
1695
# concurrent operation on the same file object', so
1696
# retry. Probably a thread is trying to write to
1698
if first_close_error is None:
1699
first_close_error = ioe
1704
if close_attempts > 1:
1706
'Unable to close log file on first attempt, '
1707
'will retry: %s\n' % (first_close_error,))
1708
if close_attempts == max_close_attempts:
1710
'Unable to close log file after %d attempts.\n'
1711
% (max_close_attempts,))
1712
1725
self._log_file = None
1713
1726
# Permit multiple calls to get_log until we clean it up in
1714
1727
# finishLogFile
1715
1728
self._log_contents = log_contents
1717
os.remove(self._log_file_name)
1719
if sys.platform == 'win32' and e.errno == errno.EACCES:
1720
sys.stderr.write(('Unable to delete log file '
1721
' %r\n' % self._log_file_name))
1724
self._log_file_name = None
1725
1729
return log_contents
1727
return "No log file content and no log file name."
1731
return "No log file content."
1729
1733
def get_log(self):
1730
1734
"""Get a unicode string containing the log from bzrlib.trace.
1945
1949
variables. A value of None will unset the env variable.
1946
1950
The values must be strings. The change will only occur in the
1947
1951
child, so you don't need to fix the environment after running.
1948
:param skip_if_plan_to_signal: raise TestSkipped when true and os.kill
1952
:param skip_if_plan_to_signal: raise TestSkipped when true and system
1953
doesn't support signalling subprocesses.
1950
1954
:param allow_plugins: If False (default) pass --no-plugins to bzr.
1952
1956
:returns: Popen object for the started process.
1954
1958
if skip_if_plan_to_signal:
1955
if not getattr(os, 'kill', None):
1956
raise TestSkipped("os.kill not available.")
1959
if os.name != "posix":
1960
raise TestSkipped("Sending signals not supported")
1958
1962
if env_changes is None:
1959
1963
env_changes = {}
2408
2414
made_control = self.make_bzrdir(relpath, format=format)
2409
2415
return made_control.create_repository(shared=shared)
2411
def make_smart_server(self, path):
2417
def make_smart_server(self, path, backing_server=None):
2418
if backing_server is None:
2419
backing_server = self.get_server()
2412
2420
smart_server = test_server.SmartTCPServer_for_testing()
2413
self.start_server(smart_server, self.get_server())
2414
remote_transport = get_transport(smart_server.get_url()).clone(path)
2421
self.start_server(smart_server, backing_server)
2422
remote_transport = _mod_transport.get_transport(smart_server.get_url()
2415
2424
return remote_transport
2417
2426
def make_branch_and_memory_tree(self, relpath, format=None):
2433
2442
def setUp(self):
2434
2443
super(TestCaseWithMemoryTransport, self).setUp()
2444
# Ensure that ConnectedTransport doesn't leak sockets
2445
def get_transport_with_cleanup(*args, **kwargs):
2446
t = orig_get_transport(*args, **kwargs)
2447
if isinstance(t, _mod_transport.ConnectedTransport):
2448
self.addCleanup(t.disconnect)
2451
orig_get_transport = self.overrideAttr(_mod_transport, 'get_transport',
2452
get_transport_with_cleanup)
2435
2453
self._make_test_root()
2436
2454
self.addCleanup(os.chdir, os.getcwdu())
2437
2455
self.makeAndChdirToTestDir()
3191
3215
def partition_tests(suite, count):
3192
3216
"""Partition suite into count lists of tests."""
3194
tests = list(iter_suite_tests(suite))
3195
tests_per_process = int(math.ceil(float(len(tests)) / count))
3196
for block in range(count):
3197
low_test = block * tests_per_process
3198
high_test = low_test + tests_per_process
3199
process_tests = tests[low_test:high_test]
3200
result.append(process_tests)
3217
# This just assigns tests in a round-robin fashion. On one hand this
3218
# splits up blocks of related tests that might run faster if they shared
3219
# resources, but on the other it avoids assigning blocks of slow tests to
3220
# just one partition. So the slowest partition shouldn't be much slower
3222
partitions = [list() for i in range(count)]
3223
tests = iter_suite_tests(suite)
3224
for partition, test in itertools.izip(itertools.cycle(partitions), tests):
3225
partition.append(test)
3204
3229
def workaround_zealous_crypto_random():
3311
3336
if '--no-plugins' in sys.argv:
3312
3337
argv.append('--no-plugins')
3313
# stderr=STDOUT would be ideal, but until we prevent noise on
3314
# stderr it can interrupt the subunit protocol.
3315
process = Popen(argv, stdin=PIPE, stdout=PIPE, stderr=PIPE,
3338
# stderr=subprocess.STDOUT would be ideal, but until we prevent
3339
# noise on stderr it can interrupt the subunit protocol.
3340
process = subprocess.Popen(argv, stdin=subprocess.PIPE,
3341
stdout=subprocess.PIPE,
3342
stderr=subprocess.PIPE,
3317
3344
test = TestInSubprocess(process, test_list_file_name)
3318
3345
result.append(test)
3633
3665
'bzrlib.tests.blackbox',
3634
3666
'bzrlib.tests.commands',
3667
'bzrlib.tests.doc_generate',
3635
3668
'bzrlib.tests.per_branch',
3636
3669
'bzrlib.tests.per_bzrdir',
3637
'bzrlib.tests.per_bzrdir_colo',
3670
'bzrlib.tests.per_controldir',
3671
'bzrlib.tests.per_controldir_colo',
3638
3672
'bzrlib.tests.per_foreign_vcs',
3639
3673
'bzrlib.tests.per_interrepository',
3640
3674
'bzrlib.tests.per_intertree',
4035
4076
:param new_id: The id to assign to it.
4036
4077
:return: The new test.
4038
new_test = copy(test)
4079
new_test = copy.copy(test)
4039
4080
new_test.id = lambda: new_id
4081
# XXX: Workaround <https://bugs.launchpad.net/testtools/+bug/637725>, which
4082
# causes cloned tests to share the 'details' dict. This makes it hard to
4083
# read the test output for parameterized tests, because tracebacks will be
4084
# associated with irrelevant tests.
4086
details = new_test._TestCase__details
4087
except AttributeError:
4088
# must be a different version of testtools than expected. Do nothing.
4091
# Reset the '__details' dict.
4092
new_test._TestCase__details = {}
4040
4093
return new_test
4102
4155
if test_id != None:
4103
4156
ui.ui_factory.clear_term()
4104
4157
sys.stderr.write('\nWhile running: %s\n' % (test_id,))
4158
# Ugly, but the last thing we want here is fail, so bear with it.
4159
printable_e = str(e).decode(osutils.get_user_encoding(), 'replace'
4160
).encode('ascii', 'replace')
4105
4161
sys.stderr.write('Unable to remove testing dir %s\n%s'
4106
% (os.path.basename(dirname), e))
4162
% (os.path.basename(dirname), printable_e))
4109
4165
class Feature(object):
4455
4522
from subunit import TestProtocolClient
4456
4523
from subunit.test_results import AutoTimingTestResultDecorator
4524
class SubUnitBzrProtocolClient(TestProtocolClient):
4526
def addSuccess(self, test, details=None):
4527
# The subunit client always includes the details in the subunit
4528
# stream, but we don't want to include it in ours.
4529
if details is not None and 'log' in details:
4531
return super(SubUnitBzrProtocolClient, self).addSuccess(
4457
4534
class SubUnitBzrRunner(TextTestRunner):
4458
4535
def run(self, test):
4459
4536
result = AutoTimingTestResultDecorator(
4460
TestProtocolClient(self.stream))
4537
SubUnitBzrProtocolClient(self.stream))
4461
4538
test.run(result)
4463
4540
except ImportError: