I'd like to see the native Python logging mechanism used, since we
already use it for other debug output in Chandler; output that needs to
be found by Tinderbox could be logged by its own logger object, which
would make parsing it much less prone to false-positive errors (the
lines are in a well-defined format, so finding the lines produced by one
logger is easy); this would also make diagnosis of failures easier (the
big problem with the current output) because all the output (including
regular debug output) would be combined in correct chronological order
(so we wouldn't have to correlate multiple logs).
Of course, these logs would be more verbose, but that's a feature, not a
bug. If false positives are no longer a problem, the goal shouldn't be
to minimize output - it should be to provide enough output to simplify
diagnosing failures.
A couple more comments below...
Heikki Toivonen wrote:
The issue of Tinderbox log readability has been raised (once again). The
purpose of this email is to start a discussion to see if we can come to
a consensus on a suitable format. (We are talking about the full Tbox log.)
To start with, let me describe briefly how the current system works.
A Tinderbox clients pulls chandler source code, do build if code
changed, then run various tests. All of this activity is logged, and of
course Chandler itself and the test frameworks provide additional log
files. At the end of the run, the client sends an email to the Tinderbox
server with all of the logs concatenated to a single file.
In some cases we can miss entire logs from certain tests if we
encountered a Python crash. For example, functional tests will not
output anything until they finish, and if Python crashes before we
finish there will be no output. The only indication in the log file is
that there is a line that says something like 'starting functional
tests' and the next line says exit code=<some non-zero number).
This sounds like an easy thing to scan for (a line starting with "exit
code=" immediately after the 'starting functional tests' line).
Alternatively, the thing that concatenates everything could notice when
a log that's supposed to be non-empty is empty or nonexistant, and
substitute an easily found error message instead.
We can also experience a situation where test logs were output properly
and all tests passed, but then we experience a Python shutdown crash. We
catch that in some cases (but not all), and this will show up in the
Tbox log as something like 'all tests passed' followed by line that says
'tests failed' (the first one was output by the test framework, the
second one by the script that started the testsuite and monitored python
exit value).
This case also sounds readily identifiable, even though "all tests
passed" followed by "tests failed" looks confusing. If the tinderbox
doesn't panic when this case is identified, I won't either. :-)
The Tinderbox server creates an HTML page from the log. The page
contains the full log, among with some additional information. At the
top of the page is a section of links to errors. That is produced by
parsing the full log, and creating links for each line were certain
keywords appear, like 'error', 'warning' and 'failed'. This is of course
not foolproof, and can result in false positive links. The longer the
log, the more false positive error links there are the top.
Currently the logs are very long and verbose.
Thanks for thinking about this - improving this situation would help
productivity a lot.
...Bryan
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
Open Source Applications Foundation "chandler-dev" mailing list
http://lists.osafoundation.org/mailman/listinfo/chandler-dev
