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)
861
# Isolate global verbosity level, to make sure it's reproducible
862
# between tests. We should get rid of this altogether: bug 656694. --
864
self.overrideAttr(bzrlib.trace, '_verbosity_level', 0)
834
867
# debug a frame up.
836
869
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()
871
def discardDetail(self, name):
872
"""Extend the addDetail, getDetails api so we can remove a detail.
874
eg. bzr always adds the 'log' detail at startup, but we don't want to
875
include it for skipped, xfail, etc tests.
877
It is safe to call this for a detail that doesn't exist, in case this
878
gets called multiple times.
880
# We cheat. details is stored in __details which means we shouldn't
881
# touch it. but getDetails() returns the dict directly, so we can
883
details = self.getDetails()
853
887
def _clear_debug_flags(self):
854
888
"""Prevent externally set debug flags affecting tests.
1487
1519
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
1521
def overrideAttr(self, obj, attr_name, new=_unitialized_attr):
1498
1522
"""Overrides an object attribute restoring it after the test.
1612
1643
self._do_skip(result, reason)
1646
def _report_skip(self, result, err):
1647
"""Override the default _report_skip.
1649
We want to strip the 'log' detail. If we waint until _do_skip, it has
1650
already been formatted into the 'reason' string, and we can't pull it
1653
self._suppress_log()
1654
super(TestCase, self)._report_skip(self, result, err)
1657
def _report_expected_failure(self, result, err):
1660
See _report_skip for motivation.
1662
self._suppress_log()
1663
super(TestCase, self)._report_expected_failure(self, result, err)
1615
1666
def _do_unsupported_or_skip(self, result, e):
1616
1667
reason = e.args[0]
1668
self._suppress_log()
1617
1669
addNotSupported = getattr(result, 'addNotSupported', None)
1618
1670
if addNotSupported is not None:
1619
1671
result.addNotSupported(self, reason)
1666
1718
unicodestr = self._log_contents.decode('utf8', 'replace')
1667
1719
self._log_contents = unicodestr.encode('utf8')
1668
1720
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()
1721
if self._log_file is not None:
1722
log_contents = self._log_file.getvalue()
1680
1724
log_contents.decode('utf8')
1681
1725
except UnicodeDecodeError:
1682
1726
unicodestr = log_contents.decode('utf8', 'replace')
1683
1727
log_contents = unicodestr.encode('utf8')
1684
1728
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
1729
self._log_file = None
1713
1730
# Permit multiple calls to get_log until we clean it up in
1714
1731
# finishLogFile
1715
1732
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
1733
return log_contents
1727
return "No log file content and no log file name."
1735
return "No log file content."
1729
1737
def get_log(self):
1730
1738
"""Get a unicode string containing the log from bzrlib.trace.
1945
1953
variables. A value of None will unset the env variable.
1946
1954
The values must be strings. The change will only occur in the
1947
1955
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
1956
:param skip_if_plan_to_signal: raise TestSkipped when true and system
1957
doesn't support signalling subprocesses.
1950
1958
:param allow_plugins: If False (default) pass --no-plugins to bzr.
1952
1960
:returns: Popen object for the started process.
1954
1962
if skip_if_plan_to_signal:
1955
if not getattr(os, 'kill', None):
1956
raise TestSkipped("os.kill not available.")
1963
if os.name != "posix":
1964
raise TestSkipped("Sending signals not supported")
1958
1966
if env_changes is None:
1959
1967
env_changes = {}
2408
2418
made_control = self.make_bzrdir(relpath, format=format)
2409
2419
return made_control.create_repository(shared=shared)
2411
def make_smart_server(self, path):
2421
def make_smart_server(self, path, backing_server=None):
2422
if backing_server is None:
2423
backing_server = self.get_server()
2412
2424
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)
2425
self.start_server(smart_server, backing_server)
2426
remote_transport = _mod_transport.get_transport(smart_server.get_url()
2415
2428
return remote_transport
2417
2430
def make_branch_and_memory_tree(self, relpath, format=None):
2433
2446
def setUp(self):
2434
2447
super(TestCaseWithMemoryTransport, self).setUp()
2448
# Ensure that ConnectedTransport doesn't leak sockets
2449
def get_transport_with_cleanup(*args, **kwargs):
2450
t = orig_get_transport(*args, **kwargs)
2451
if isinstance(t, _mod_transport.ConnectedTransport):
2452
self.addCleanup(t.disconnect)
2455
orig_get_transport = self.overrideAttr(_mod_transport, 'get_transport',
2456
get_transport_with_cleanup)
2435
2457
self._make_test_root()
2436
2458
self.addCleanup(os.chdir, os.getcwdu())
2437
2459
self.makeAndChdirToTestDir()
3190
3219
def partition_tests(suite, count):
3191
3220
"""Partition suite into count lists of tests."""
3193
tests = list(iter_suite_tests(suite))
3194
tests_per_process = int(math.ceil(float(len(tests)) / count))
3195
for block in range(count):
3196
low_test = block * tests_per_process
3197
high_test = low_test + tests_per_process
3198
process_tests = tests[low_test:high_test]
3199
result.append(process_tests)
3221
# This just assigns tests in a round-robin fashion. On one hand this
3222
# splits up blocks of related tests that might run faster if they shared
3223
# resources, but on the other it avoids assigning blocks of slow tests to
3224
# just one partition. So the slowest partition shouldn't be much slower
3226
partitions = [list() for i in range(count)]
3227
tests = iter_suite_tests(suite)
3228
for partition, test in itertools.izip(itertools.cycle(partitions), tests):
3229
partition.append(test)
3203
3233
def workaround_zealous_crypto_random():
3310
3340
if '--no-plugins' in sys.argv:
3311
3341
argv.append('--no-plugins')
3312
# stderr=STDOUT would be ideal, but until we prevent noise on
3313
# stderr it can interrupt the subunit protocol.
3314
process = Popen(argv, stdin=PIPE, stdout=PIPE, stderr=PIPE,
3342
# stderr=subprocess.STDOUT would be ideal, but until we prevent
3343
# noise on stderr it can interrupt the subunit protocol.
3344
process = subprocess.Popen(argv, stdin=subprocess.PIPE,
3345
stdout=subprocess.PIPE,
3346
stderr=subprocess.PIPE,
3316
3348
test = TestInSubprocess(process, test_list_file_name)
3317
3349
result.append(test)
3632
3669
'bzrlib.tests.blackbox',
3633
3670
'bzrlib.tests.commands',
3671
'bzrlib.tests.doc_generate',
3634
3672
'bzrlib.tests.per_branch',
3635
3673
'bzrlib.tests.per_bzrdir',
3636
'bzrlib.tests.per_bzrdir_colo',
3674
'bzrlib.tests.per_controldir',
3675
'bzrlib.tests.per_controldir_colo',
3637
3676
'bzrlib.tests.per_foreign_vcs',
3638
3677
'bzrlib.tests.per_interrepository',
3639
3678
'bzrlib.tests.per_intertree',
4033
4080
:param new_id: The id to assign to it.
4034
4081
:return: The new test.
4036
new_test = copy(test)
4083
new_test = copy.copy(test)
4037
4084
new_test.id = lambda: new_id
4085
# XXX: Workaround <https://bugs.launchpad.net/testtools/+bug/637725>, which
4086
# causes cloned tests to share the 'details' dict. This makes it hard to
4087
# read the test output for parameterized tests, because tracebacks will be
4088
# associated with irrelevant tests.
4090
details = new_test._TestCase__details
4091
except AttributeError:
4092
# must be a different version of testtools than expected. Do nothing.
4095
# Reset the '__details' dict.
4096
new_test._TestCase__details = {}
4038
4097
return new_test
4100
4159
if test_id != None:
4101
4160
ui.ui_factory.clear_term()
4102
4161
sys.stderr.write('\nWhile running: %s\n' % (test_id,))
4162
# Ugly, but the last thing we want here is fail, so bear with it.
4163
printable_e = str(e).decode(osutils.get_user_encoding(), 'replace'
4164
).encode('ascii', 'replace')
4103
4165
sys.stderr.write('Unable to remove testing dir %s\n%s'
4104
% (os.path.basename(dirname), e))
4166
% (os.path.basename(dirname), printable_e))
4107
4169
class Feature(object):
4453
4526
from subunit import TestProtocolClient
4454
4527
from subunit.test_results import AutoTimingTestResultDecorator
4528
class SubUnitBzrProtocolClient(TestProtocolClient):
4530
def addSuccess(self, test, details=None):
4531
# The subunit client always includes the details in the subunit
4532
# stream, but we don't want to include it in ours.
4533
if details is not None and 'log' in details:
4535
return super(SubUnitBzrProtocolClient, self).addSuccess(
4455
4538
class SubUnitBzrRunner(TextTestRunner):
4456
4539
def run(self, test):
4457
4540
result = AutoTimingTestResultDecorator(
4458
TestProtocolClient(self.stream))
4541
SubUnitBzrProtocolClient(self.stream))
4459
4542
test.run(result)
4461
4544
except ImportError: