Rev 2826: notes on logging from tests in http://sourcefrog.net/bzr/test-cleanup

[Martin Pool]

At http://sourcefrog.net/bzr/test-cleanup

------------------------------------------------------------
revno: 2826
revision-id: mbp at sourcefrog.net-20070917033300-7jwnccl3tro1e0j6
parent: pqm at pqm.ubuntu.com-20070917005035-cshdkpzbj63id1uw
committer: Martin Pool <mbp at sourcefrog.net>
branch nick: test-cleanup
timestamp: Mon 2007-09-17 13:33:00 +1000
message:
  notes on logging from tests
modified:
  doc/developers/HACKING.txt     HACKING-20050805200004-2a5dc975d870f78c
=== modified file 'doc/developers/HACKING.txt'
--- a/doc/developers/HACKING.txt	2007-09-10 10:05:51 +0000
+++ b/doc/developers/HACKING.txt	2007-09-17 03:33:00 +0000
@@ -522,6 +522,84 @@
 module's ``test_suite`` function.
 
 
+Logging from tests
+------------------
+
+Each test object has a log kept in memory.  If the test fails, the log is 
+displayed and may give some useful information on what went wrong.
+
+The log content can be retrieved through ``TestCase.get_log()``.
+
+Content can get into the test log in several ways:
+
+ * The test itself can record information through ``TestCase.log()`` to
+   give context.  This is used in only a few places, but can give useful
+   context by for example recording the arguments given to run_bzr().
+
+ * bzrlib trace calls are redirected into the test log for the duration
+   of the tests.
+
+ * apply_redirected has the special case that if you don't give stdout and
+   stderr files, the content will go into the test log.  Is this used, or
+   useful?
+
+Logging from tests serves multiple purposes:
+
+ * If the test fails, the log may give useful information to the
+   developer.
+
+ * We sometimes look at the log to check what happened within Bazaar.
+
+ * In particular we look in the log when checking that expected trace
+   messages are emitted, for example in the tests for ``-Dlock``.
+
+ * Some tests look at the log to make assertions about the output of
+   blackbox tests.  This is not a good idea, because they're always
+   looking for expected data in a larger pool.  Since ``TestCase.run_bzr``
+   now always returns the stdout and stderr strings these tests should
+   just match on that.
+
+Improving test logging
+''''''''''''''''''''''
+ 
+[mbp]: It's not so good that the test log serves these multiple purposes.
+I think it would be good to make the sole purpose of the log be aiding in
+diagnosing test failures, and not examine it programmatically except when
+testing that it works.
+
+At the moment we have the problem that when an exception occurs it's
+typically both displayed by the test framework and also written into the
+log.  So the overall failure message is unnecessarily long.
+
+The log is written to disk, and also kept in memory but sometimes removed.
+This is also somewhat complicated.  If we rarely look at the log we can
+probably just keep it on disk and load it every time it's requested.
+
+At present, within tests, warnings from inside blackbox tests seem to go
+only to the test log, but they should be returned in stderr instead.  See
+e.g. TestDeprecationWarning.
+
+_get_log has side effects (deleting the log file, etc) but it shouldn't.
+
+test_ignore_zero_merge_inner is an example of a problematic case, where we
+want to test an api, not a command line, but want to look at what it would
+write through the logging system to the console.  This indicates a
+slightly misfactored api: if it's programmatic, it should indicate its
+results in a programmatic way, such as by returning a Result object.
+
+One approach to cleaning this up would be to at least separate out the
+different types of message into different separate logs.
+
+When should the log be deleted?  After the test object reports its result?
+When it's gcd?  At the moment successful logs delete their logs earlier,
+it seems.
+
+All the get_log calls seem to be using it to look at things sent through
+bzrlib.trace by the code under test.  And almost all are passing
+keep_log=True.  For these users, we can have a separate routine that
+returns just the trace output.
+
+
 Essential Domain Classes
 ########################