rich context logging for mozmill failures has landed in comm-central

[Andrew Sutherland]

Short version: As promised in a teaser blog post I recently made ( 
http://www.visophyte.org/blog/?p=722 ), Thunderbird mozmill failures 
will now dump a rich JSON representation on stdout.  This is intended 
for processing and exposure via a web app.

The current server can be found here:
http://arbpl.visophyte.org/?tree=Thunderbird

An example failure can be seen here:
http://arbpl.visophyte.org/?tree=Thunderbird&pushid=5603&log=19178%3A1299790976.1299791885.27652.gz 
<http://arbpl.visophyte.org/?tree=Thunderbird&pushid=5603&log=19178%3A1299790976.1299791885.27652.gz>

It is running this code:
https://github.com/asutherland/arbitrarypushlog

The bug for this was here, but any further discussion should happen on 
the tb-planning list or newly filed bugs:
https://bugzilla.mozilla.org/show_bug.cgi?id=633498

Long version:

# How The Logging Works:

The asyncTestUtils testing framework ( 
https://developer.mozilla.org/en/MailNews/AsyncTestUtils_Extended_Framework 
) includes a file, logHelper.js ( 
http://mxr.mozilla.org/comm-central/source/mailnews/test/resources/logHelper.js 
).  logHelper provides a means of hooking up log4moz for network and 
disk output, as well as convenience methods (mark_action, mark_failure) 
to easily log rich information to those log4moz endpoints and less rich 
output to stdout.

The original consumer of logHelper was logsploder, you can find info on 
logsploder at these links:
http://www.visophyte.org/blog/?p=681
http://groups.google.com/group/mozilla.dev.apps.thunderbird/msg/be2c39e523210c02

There are other files available that can provide additional context 
information via logHelper's mark_action mechanism.  Specifically, gloda 
created folderEventLogHelper.js to listen to nsIMsgMailSession and 
nsIMsgFolderNotificationService events that seemed useful:
http://groups.google.com/group/mozilla.dev.apps.thunderbird/msg/be2c39e523210c02

I have made changes to our mozmill shared-library 
test-folder-display-helpers.js to activate this functionality and hook 
it up to mozmill's jsbridge.  Specifically, we put the log events for 
each test in in-memory buckets and keep around the buckets for the 
current test and the last test.  In the event that a failure is reported 
via the mozmill event system, we annotate the failure with the last 10 
seconds of logs from the previous test and all of the logs for the 
current test.

I have also modified test-window-helpers so that on failure we walk the 
list of currently open windows, and capture for each:
- whether that window is the "active"/focused window
- a synthetic screenshot
- info on the currently focused DOM element
- info on all currently open popups.  The popups currently do not get 
composited into the screenshot or screenshotted themselves!  (This is 
something it would be nice to rectify, since popups that are not closed 
can easily break subsequent tests.)

You can find those files here:
http://mxr.mozilla.org/comm-central/source/mail/test/mozmill/shared-modules/test-folder-display-helpers.js
http://mxr.mozilla.org/comm-central/source/mail/test/mozmill/shared-modules/test-window-helpers.js

Please note that tests which do not cause test-folder-display-helpers.js 
to be loaded *will not benefit from this fanciness*.  Ideally we would 
refactor things so that it's not effectively a pre-requisite for all 
tests to loads test-folder-display-helpers, especially since a lot of 
the specific test names are not sufficiently namespaced and not 
particularly intended to be extensible.  ex: assert_visible is a rather 
generic name that will has a marked bias towards assuming you are 
talking about messages in the thread pane.


# What of the server?

arbpl.visophyte.org is a development server and not the permanent home 
of the web interface.  I will pursue having IT (gozer/jhopkins) stand up 
a production server.  We will post here and in various places when that 
happens.  Even after the production server is stood up, 
arbpl.visophyte.org should stick around as a development server for a bit.


# What if I am running mozmill tests locally?

Currently, you will see the JSON blob on failures.  Because it has the 
screenshot in there as a data:url, it can be ugly and take up a few 
lines in your scrollback buffer.  It may be worth adding a flag and/or 
different make-target so that the dumping is opt-in or opt-out or the like.

However, you can also do something with the log locally, with the caveat 
that you currently need to be running hbase and the base-thrift server.  
That's a pretty ridiculous requirement, and our hbase usage is rather 
limited, so I hope to be able to provide an alternate SQLite-based 
backend as a more reasonable requirement.  If/when that happens, I will 
be sure to post here about it.  In the meantime, please avail yourself 
of our try server, as the ThunderbirdTry tinderbox tree is processed.


# I want to add more fancy logging.

Use mark_action, it has some documentation:
http://mxr.mozilla.org/comm-central/source/mailnews/test/resources/logHelper.js#487

If you have some rich object you want transported better, modify 
_normalize_for_json:
http://mxr.mozilla.org/comm-central/source/mailnews/test/resources/logHelper.js#330

It's also easily cargo-cult-able!


Andrew