things that I remembered to write about

Posts in category School

0.6 – The end of ridiculousness

Feb22
2009 Leave a Comment Written by John Ford

I give up on my 1/7th release numbers. I will be following the standard numbers from now on.

0.6

This release involved getting a patch submitted to Bugzilla, doing a ton of thinking and starting writing my parser.

Initial Patch Submitted and Thinking

I have submitted a patch to Bugzilla on my bug. This patch:

  • Creates a mozconfig enable timing, timing program and timestamp format option
  • Puts timestamps using the above options into some tests. Right now, it is doing them for XPCShell test which use test_all.sh and the check:: make target (minus the feeds test suite)

Working on this patch has showed me how varied the testing frameworks are. I am a little nervous about continuing along this path without confirmation of my approach. Originally I was hoping to customize the time stamp formatting but I now realise that there is very little pay off for a ton of effort. From now on, I am going to be using exclusively epoch based times. This makes it easy because if I continue with this approach, I’d need to get a make option visible in JavaScript, which I don’t know how to do.

My other option would be to modify BuildBot. This option would involve overriding the existing LogFile class to have one which did timing. This new type of LogFile would only be used on Mozilla testing buildsteps. This would make it a lot easier to add the timestamps but would be harder to parse and would be useless outside of BuildBot.

If you are at all familiar with Mozilla’s testing framework I’d love your opinion.

Parser

I have started writing my log file parser. I have most standard output being parsed fine. Right now, everything but Mochitest based tests and some obscure tests are able to be parsed. I will be making a screen capture this week to highlight my parser for my second Demo.

It works by reading all the lines in the specified file into an array. It then goes through each line and decides if it is part of a unit test. If it is, it is narrowed down to the type of test it is (reftest, xpcshell test, etc). Once that is done, the line is sent to the initialiser for that type of test’s output. These classes understand each type of test output and parse accordingly. Once this is done, the parser spits out a list of output as specified my bug.

Some things this parser doesn’t do

  • There are obscurely formatted tests early on in the “make -k check” output. They aren’t looked at
  • Mochitest output is not parsed because there are no timestamps.
  • The Log class doesn’t have information about itself and won’t until it is injected into the log somehow
  • Some test failures generate multi-line output bounded by “<<<<<<" and ">>>>>>” lines. This is not being handled right now, but I have an idea that will take care of it
  • Parse all non-epoch date/time information into Unix time

Sample output

1/1 | 20090213-014025 | ../../_tests/xpcshell-simple/test_necko/unit/test_bug321706.js | local-osx | TEST-PASS | all tests passed | http://www.example.com/waterfall
1/1 | 20090213-014025 | ../../_tests/xpcshell-simple/test_necko/unit/test_bug331825.js | local-osx | TEST-PASS | all tests passed | http://www.example.com/waterfall
1/1 | 20090213-014025 | ../../_tests/xpcshell-simple/test_necko/unit/test_bug336501.js | local-osx | TEST-PASS | all tests passed | http://www.example.com/waterfall
1/1 | 20090213-014025 | ../../_tests/xpcshell-simple/test_necko/unit/test_bug337744.js | local-osx | TEST-PASS | all tests passed | http://www.example.com/waterfall

The 1/1, local-osx and url are placeholder values.

I would like to investigate using a parser generator at some point in the coming week.

Project Update

Feb13
2009 Leave a Comment Written by John Ford

I have put my first patch on Mozilla’s Bugzilla for timestamps. This is the option for changing the code to do timing information. Again, the other option is to modify buildbot. This patch would still require a change to insert machine information into the log file, so we can figure out which machines are failing. I am at a crossroads and I need to decide if I am going to do this with a buildbot specific approach or modify the actual testing infrastructure.

My options include:

1) In BuildBot Subclass LogFile to TimedLogFile:
This option involves subclassing LogFile to a specialized LogFile which will implement the timing steps. Rather than adding this in the initial LogFile implementation, the subclassing removes the breakage of parallel, multi-line build task output. This subclass would only be used by specialized build steps.

2) In BuildBot Subclass LogFile to DatabaseLogFile:
This option involves intercepting LogFile addStdout() calls and sending them straight to a database. This has the disadvantage of requiring DB libraries on the client machines. I don’t know if it would be possible to route the database connection through the slaveport or not, so it might even require a second socket connection. This option has the [advantage|disadvantage] of not changing the actual build output. This could also lead to simpler parser writing because the parser would only need to know where the database is, no files

3) Modify test harnesses:
This is what I have started doing with my patch. It requires a lot of changes all over the place so it might be hard to get landed. This also changes the build output for everyone. It also requires that one timestamp format/option is used, so one format must be used in C, JS and Py.

4) Investigate pymake. This is not really an option until pymake is more mainstream.

I need to pick one of these methods very soon but I would like to get someone else’s opinion on this first.

Two methods for TimeStamps

Feb10
2009 1 Comment Written by John Ford

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 :)

0.285 Release

Feb07
2009 Leave a Comment Written by John Ford

My goal for this release was to modify BuildBot in a way that didn’t horibly break the system. I believe I have done this and have done some work on my next step: Adding timestamps to build logs. You can see my patches here. My first patch inserts a lot of information into the build logs which isn’t needed for each line. I modified this patch to only put the repeated information in the log once at the start of the log. I have also modified Mozilla’s mozbuild.py to work with my local BuildBot setup in running unit tests, reftests and crash tests. These are the things that I am mainly going to deal with for this project.

My next tasks include figuring out how to deal with the command output interleaving, making this patch become something which could possibly be accepted upstream, writing a parser, designing a database for test results and designing a UI for the information

You can download my 0.285 release in a working form at this address

I love IRC

Feb05
2009 Leave a Comment Written by John Ford

I was on IRC this morning and asked a simple question in IRC and was overwhelmed by the response! I asked about interleaving of build command output to which I got my answer. Apparently, all parallel builds write to the same file descriptor which means that even within a single line of text different jobs can write. What I mean is this, assuming you have two commands to run which each will generate the following output:

Job A
gcc -o file.o otherfile.c
-DHAS_A_TON_OF_MACROS

Job B
gcc -o otherfile.o otherfile.c
-DHAS_EVEN___MORE___MACROS

could be output in the form:
gcc -o file.o otherfile.c
gcc -o otherfile.o otherfile.c
-DHAS_EVEN___MORE___MACROS
-DHAS_A_TON_OF_MACROS

or even worse
gcc -o
gcc -o otherfile.o otherfile.c
file.o -DHAS_EVEN___MORE___MACROS
otherfile.c
-DHAS_A_TON_OF_MACROS

This clearly represents an issue with the way my first patch deals with this situation as the timestamp values are generated at the end of writing to the log file. BSmedberg pointed me to a blog post in which he parsed out compiler errors/warnings from each task of make. I will likely use this code in the log file parser that I need to write. Also thanks BZ for the help with interleaving :)

← Older Entries Newer Entries →