Debugging the Firefox accessibility

Firefox 18 got a logging system that allows you to analyze accessibility related problems and bugs. It's used to debug the real life examples like web pages where thousands of things happen every second and you don't have any clue what's going wrong there. If you ever debugged a focus issue on the web then I think you agree the logging is something very helpful on this way. On the other hand logging is a great thing to understand the problem you can't reproduce (reliably).

I didn't tried the system in case when the bug reporter is unique person who can see a problem but it works quite well for analysis of automated tests intermittent failures. The difference is the test suite has own logging capabilities and it writes down every step so that you can find out where the test was stumbled. Having these logs enabled both you can see what action was performed and what happened after.

Here's couple examples how to use logging to understand the intermittent failure.

 

Test suite logging

Almost every accessibility related test is based on events watching, i.e. we wait for certain event before starting the next test. It's all caused by async nature of accessibility implementation in Gecko.

You can start logging by setting gA11yEventDumpToConsole variable to true. A log looks like:

registered: event type: document load complete,
  target: tabDocumentAt, arg: 0
registered: event type: document load complete,
  target: tabDocumentAt, arg: 1

Event queue:
  invoke: relations of tabs

Event type: document load complete.
  Target: ['document node', address: 0x1e3b4850, role: document,
           name: 'The Book of Mozilla, 11:9', address: 0x112ddd90].
Event type: document load complete.
  Target: ['document node', address: 0x1e3b4448, role: document,
           name: 'About:', address: 0xe253250].

*****
EQ matched: document load complete
*****

7233 ERROR TEST-UNEXPECTED-FAIL |
  accessible/relations/test_tabbrowser.xul |
  Test timed out.

It is a real world example. We wait for two document load events and as you see we receive them but only one is recognized as expected one. The problem here is we wait events in specific order but sometimes we receive them in reverse order. It happens because documents are loaded asynchronously and thus events order varies. The test was fixed.

This was a case when the test suite log gives you enough information to fix a problem. But often you know there's no expected event and that's all you have. Extra info is wanted. In this case the system logging can be helpful.

 

System logging

The system logging is used to log implementation internals, i.e. it serves to understand what happens under the hood. There's a bunch of modules you can track, for example, 'focus' module logs everything related with accessible focus event processing. Depending on your needs you can enable one or several modules to log. You can do that by setting up the environment variable A11YLOG, for example:

export A11YLOG=focus,tree,DOMEvents;

Alternatively you can manage the logging from java script via nsIAccessibleRetrieval interface:

var accRetrieval =
  Components.classes["@mozilla.org/accessibleRetrieval;1"].
  getService(nsIAccessibleRetrieval);
accRetrieval.setLogging("focus,tree");

Note, you need to have enhanced privileges for that. If you debug a11y automated tests then you can use enableLogging()/disableLogging() helper functions from common.js.

The system logging can be enabled on any debug or nightly build.

 

An example

Bug 782991 is a good example how to debug intermittent failures. The problem was the following: when link is open in a new window then document load event was missed occasionally. That's all you know. And that means you don't even know whether the window was open or not.

Since it's document loading issue then it's reasonable to enable 'docload' module. A log when test fails:

A11Y DOCLOAD: document loaded; 47:41.689
  {
    DOM id: 17D86000, acc id: 1A9545C0
    uri: chrome://browser/content/browser.xul
  }

A11Y DOCLOAD: document loaded; 47:42.014
  {
    DOM id: 0E337000, acc id: 16C60B80
    uri: http://www.example.com/
  }

A11Y DOCLOAD: document loaded *completely*; 47:42.036
  {
    DOM id: 0E337000, acc id: 16C60B80
    uri: http://www.example.com/
    document acc state: completely loaded
    document is load event target: false
  }

A11Y DOCLOAD: document loaded *completely*; 47:42.048
  {
    DOM id: 17D86000, acc id: 1A9545C0
    uri: chrome://browser/content/browser.xul
    document acc state: completely loaded
    document is load event target: false
  }

As you can see 'example.com' document gets loaded (what means the window was open) but document load event wasn't fired. In practice a log when the test doesn't fail is also helpful to find a problem:

A11Y DOCLOAD: document loaded; 02:50.695
  {
    DOM id: 0x91e97a0, acc id: 0xebaf308
    uri: chrome://browser/content/browser.xul
  }

A11Y DOCLOAD: document loaded *completely*; 02:51.043
  {
    DOM id: 0x91e97a0, acc id: 0xebaf308
    uri: chrome://browser/content/browser.xul
    document acc state: completely loaded
    document is load event target: false
  }

A11Y DOCLOAD: document loaded; 02:51.235
  {
    DOM id: 0xd9732b0, acc id: 0xd11ed40
    uri: http://www.example.com/
  }

A11Y DOCLOAD: document loaded *completely*; 02:51.302
  {
    DOM id: 0xd9732b0, acc id: 0xd11ed40
    uri: http://www.example.com/
    document acc state: completely loaded
    document is load event target: true
  }

A11Y DOCEVENT: handled 'load complete' event; 02:51.302
  {
    DOM id: 0xd9732b0, acc id: 0xd11ed40
    uri: http://www.example.com/
  }

The difference between logs is in order of the document load processing. If the 'example.com' document is processed before a document of the main Firefox window then 'example.com' document isn't considered as a target of document loading events and the test fails. It's enough to understand where the bug is and fix it.

If you look for more examples then check out bugs: bug 745788, bug 708927 and bug 691580.