Debugging event driven applications has always been notoriously difficult. With user-generated messages coming at the application at seemingly random intervals, reproducing errors can be a daunting challenge. JavaScript makes it even worse, with users running a wide variety of slightly incompatible software and asynchronous server requests thrown into the mix.
The Footsteps project seeks to address the problems of reproducibility using a logging and replay framework. The client-side part of Footsteps is a JavaScript library that records non-deterministic events such as mouse clicks and random number generation. No plugins or special browsers are needed, this done entirely with JavaScript.
Footsteps is enabled by referencing a JavaScript library at the top of each page and iframe. Based on AOP and dynamic programming principals. Methods like Date and setTimeout are replaced with new versions that wrap the original, as are mouse, keyboard, and server events. The way each method is wrapped varies. Some like Date were quite simple, while others like setTimeout had some serious problems. It turns out that on all popular browsers the variable he was using to refer to the original setTimeout was being garbage collected. Thus when the wrapper tried calling the real version it results in an undefined function exception. The workaround was to save a reference to the setTimeout function in a invisible iframe.
Mouse events were even worse. In Firefox the DOM 0 handlers are called before the DOM 2 handlers and there can only be a single DOM 0 handler for a given function. Using a DOM 0 handler wouldn’t work for logging because the logging event handler may be overwritten. Nor could the DOM 2 handler work because by then the event may have already been cancelled. In IE there was a different set of problems. There are no capture-level handlers in IE so that isn’t an option. Bubbling events would work either because not all events bubble and the ones that do can be cancelled before it hits the logger. Details on how he handled the problems in his research paper. Here are a couple of interesting excerpts from it:
Firefox
Ideally, Mugshot would define a DOM 2 logging handler for each event type e, and create setter code for the window.e property which wrapped the user-specified handler with a Mugshot-provided logging function. If the application provided no DOM 0 handler, Mugshot’s DOM 2 callback would log the event; otherwise, the wrapped DOM 0 handler would log the event and set a special flag on the event object indicating that Mugshot’s DOM 2 handler should not duplicate the log entry. Unfortunately, this scheme will not work because Firefox’s getter/setter implementation is buggy. Mugshot can create a getter/setter pair for a DOMnode event property, and application writes to the property will properly invoke the setter. However, when an actual event of type e is generated, the browser will not invoke the associated function. In other words, the setter code, which works perfectly at the application level, hides the event handler from the internal browser code.
Internet Explorer
To log non-bubbling events, Mugshot exploits IE’s facility for extending the object prototypes for DOM nodes. For DOM types like Images and Inputs which support non-bubbling events, Mugshot modifies their class definitions to define custom setters for DOM 0 event properties. Mugshot also redefines attachEvent() and detachEvent(), the mechanisms by which applications register DOM 2 handlers for these nodes. The DOM 0 setters and the wrapped DOM 2 registration methods collaborate to ensure that if an application defines at least one handler for a DOM node/event pair, Mugshot will log relevant events precisely once, and before any application-specified handler can cancel the event.
Ideally, Mugshot could use the same techniques to capture bubbling events at the target phase. Unfortunately, IE’s DOM extension facility is fragile: redefining certain combinations of DOM 0 properties can cause un- predictable behavior. Therefore Mugshot uses window- level handlers to log bubbling events; this is the problematic technique described above that may lead to temporal violations in the log. Fortunately, Mugshot can mitigate this problem in IE, because IE stores the current DOM event in a global variable window.event. Whenever Mugshot needs to log a source of non-determinism, it first checks whether window.event is defined and refers to a not-yet-logged event. If so, Mugshot logs the event before examining the causally dependent event.
An application may cancel a bubbling event before it reaches Mugshot’s window-level handler by setting its Event.cancelBubble property to true. The event still must be logged, so Mugshot extends the class prototype for the Event object, overriding its cancelBubble setter to log the event before its cancellation.
When logging is turned on performance is roughly 90% of the application’s baseline. According to James most users don’t even notice this. Memory usage varies depending on the style of log used. Logging can be verbose, i.e. human readable, or it can just have enough to support replaying the log.
When an error occurs the log is shipped to the developer. The developer can then replay the events to see what the user saw when the application failed. Logs can also be shipped when the user presses a “panic” button and confirms that they want to send the log.
Once the developer has the log he can replay it to see exactly what happened to the running application. Events can be played back in real time or via stepping, with either mode sending simulated events to the application. Real time playback actually runs at about 40% of the speed of the baseline application.
Footsteps is based on an earlier research project called Mugshot. The co-authors of the research paper were James Mickens, Jeremy Elson, and Jon Howell. You can learn more about Silo on Channel 9.