Two methods for TimeStamps

I have done two different ways of inserting timestamps into build logs. I need to figure out which one to use.

The first way I did this was by modifying BuildBot’s buildbot.status.builder.LogFile class to insert a timestamp when the addStdout() or addStderr() functions were called. This worked really well for non-parallel things like a checkout but became a horible mess on things like a build. This could be corrected by subclassing LogFile to make a special TimedLogFile, overriding the addStdout() and addStderr() and using this subclass only for non-parallel tasks. The advantage of this is that this change is very local to the Release Engineering team as well as being a single-location change. The disadvantage is that the timestamps would only be useful to those running their builds and tests in a BuildBot. Another problem is that this timestamp can’t be used to measure runtimes in parallel commands because you can’t guarantee the start of the next line is the finish of the current line. As well, this method doesn’t allow for me to insert special ‘flags’ when a multi-line test is done to aid in parsing. Originally I was going to modify twisted.python.log.msg() to add timestamps but I soon found out that this will not work. Within the confines of BuildBot (as I understand it), this function controls the actual BuildBot logs only, which do already have timestamps. This function controls the twistd.log file on master and slave machines. They come in the function results in logs similar to this example of a build step

2009-02-09 22:41:23-0500 [Broker,client]  make -f client.mk build2009-02-09 22:41:23-0500 [Broker,client]   in dir /Users/jhford/local-slave/moz-osx/build (timeout 1200 secs)2009-02-09 22:41:23-0500 [Broker,client]   watching logfiles {}2009-02-09 22:41:23-0500 [Broker,client]   argv: ['make', '-f', 'client.mk', 'build']2009-02-09 22:41:23-0500 [Broker,client]  environment: {'
'}2009-02-09 22:41:23-0500 [Broker,client]   closing stdin2009-02-09 22:41:23-0500 [Broker,client]   using PTY: True2009-02-09 22:50:06-0500 [-] sending app-level keepalive2009-02-09 22:55:42-0500 [-] command finished with signal None, exit code 0, elapsedTime: 858.9656762009-02-09 22:55:42-0500 [-] SlaveBuilder.commandComplete 

As you will notice, you have no output between invocation of make and the command completing. A possibility here is to log.msg() things which are given to addStdout() and addStderr(). This lack of command output happens because (as I understand it) BuildBot creates a file on the slave’s filesystem (something like SLAVEDIR/buildername/10-local-osx-stdout) for make to write to. As I understand, this would be akin to forking, dup2‘ing stdio to this file and execvpe‘ing make. In non-POSIX talk, that is creating a new process, changing the standard output and error file handles to the log file then executing the command with the given environmental variables. I believe that this solution is interesting but unlikely to work in a useful manner.

The second method I have tried seems to be more promising. This method is something that Dave Humphrey got me thinking about. Rather than modifying BuildBot, he suggested that I modify config/rules.mk. At first this method didn’t seem to work because the xpcshell tests were being timestamped on a folder by folder basis instead of test case by test case. I dug a little deeper into this and found a file called test_all.sh which is in charge of going through each folder and running individual xpcshell test cases. After a couple modifications I started getting timestamps in the format

Tue 10 Feb 2009 19:13:11 EST | TEST-PASS |
test_bug257155.js | all tests passed

After a while I noticed there was another type of test that is controled with the macro CPP_UNIT_TESTS, so I will refer to this style as that. These have output that looks like this:

Tue 10 Feb 2009 19:47:02 EST | CPP_UNIT_TESTSShould create one |TestObject|:  Creating TestObject 0x40bbc0.Should destroy one |TestObject|:  Destroying TestObject 0x40bbc0.Should create one |TestObject|:  Creating TestObject 0x40bbc0.Should create one |TestObject| and then destroy one:  Creating TestObject 0x40bc10.  Destroying TestObject 0x40bbc0.Should destroy one |TestObject|:.......

These have completely non-standard output and have no specific pass/fail message. I will not be looking for them in my parser. The next two types of test output I would need to hunt down their invocation. I will do once I have confirmation of my approach. One type, which wouldn’t run in parallel nicely:

*** Beginning parser tests...    for host "http://parser.test/": SET "test=parser; domain=.parser.test; ;; ;=; ,,, ===,abc,=; abracadabra! max-age=20;=;;"             "http://parser.test/": GOT "test=parser"    for host "http://parser.test/": SET "test=parser; domain=.parser.test; max-age=0"             "http://parser.test/": GOT nothing    for host "http://parser.test/": SET "test="fubar! = foo;bar\";" parser; domain=.parser.test; max-age=6five; max-age=2.63,"             "http://parser.test/": GOT "test="fubar! = foo;bar\";"; five"    for host "http://parser.test/": SET "test=kill; domain=.parser.test; max-age=0  five; max-age=0"             "http://parser.test/": GOT nothing    for host "http://parser.test/": SET "six"             "http://parser.test/": GOT "six"    for host "http://parser.test/": SET "seven"             "http://parser.test/": GOT "seven"    for host "http://parser.test/": SET " =eight"             "http://parser.test/": GOT "eight"    for host "http://parser.test/": SET "test=six"             "http://parser.test/": GOT "eight; test=six"*** tests passed.

This should be easy enough to find in a parser, potentially even with nesting. I will look into that as I write a parser. The other type of unexplained output I have found is:

PASS | xml/rfc4287/entry_contributor.xml | Test was: "atom author name works" | feed.items.queryElementAt(
).name=='John Doe Entry'; |

This solution has the advantage of being very granular in the output. It isn’t a one-size-fits-all solution so I can put special flags in the timestamp as needed/allowed. The output could also be of use to developers working outside of BuildBot. It would also be trivial to add command completion timestamps to allow timing of each item for most of the single line output. This solution has the disadvantage of requiring a larger number of changes in more places than the first solution. This might throw off other consumers of the logs. This could be mitigated by creating an option to control this behaviour in mozconfig, though, I don’t know how to do this right now.

I hope that I didn’t bore you! I would greatly appreciate any input you have