Monday, October 8, 2012

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:

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:

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.

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.