miscoded

I'll try to recount what turned into the most longwinded debugging of a single problem I can remember. A word of warning: we're going deep into the internals of one of the web's most important siteapps - Google Maps - and it gets both extremely technical, extremely long-winded and extremely tedious. It really took more than one calendar week to figure out this problem. Consider yourself warned..

Our very own browser.js manager/blogger, Ola, reported the bug on March 7th:

1. load site
2. zoom in somewhere
3. click the "report a problem" in lower right corner
4. select element on dropdown
-> dialog disappears

Indeed, we have a problem. My work on it started inconspicuously enough one day later with a bug tracker comment from a colleague:

I'm struggling to figure this one out

The dialog only goes away for me when selecting any option in the "Select an element" drop down. But the dialog disappearing (being removed from the DOM) doesn't appear to happen through the change event. I used Fiddler to replace all instances of "change" with "dblclick" and it still disappeared on change. The dialog is added through a JS file with "mod_suck" in the URL (search for "reportmapissuehtml" to locate the code in question).

Hallvord, any ideas or knowledge?

This comment, coming from a colleague who has often enough beaten me to the goal post in analysis if we happened to look at the same issue, did of course indicate a challenge. Starting my investigation on March 9, I seemed to start with a lucky strike though..

The full Maps application has megabytes of JavaScript, much of it loading on demand in response to various actions. Debugging a huge app like that means your first challenge is to find the code you want to look at. The second challenge will of course be to understand it..

My first step was just guessing that some Maps code removed the dialog from the document, and might be using element.removeChild() to do so. A fast way to find the code that would call removeChild() would be to simply make removeChild() throw an exception and study the error. Between steps 3 and 4 in the instructions, I pasted this into the address bar:

javascript:void(Element.prototype.removeChild=function(){undefined()})

..and voila, I did get a stack trace:

c.firstChild!=i&&c.removeChild(c.firstChild);
 called from line 1, column 58883 in <anonymous function: r.O$>():
 F1a(this,o0(this))
 called as bound function from line 1696, column 65 in <anonymous function: Wh.prototype.lH>(a, b) in http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/399b/maps2/%7Bmain,mod_util,mod_rst%7D.js:
 return c?(b&&a.tick("re"),c(a),!0):!1
 called from line 1695, column 108 in <anonymous function>(c) in http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/399b/maps2/%7Bmain,mod_util,mod_rst%7D.js:
 d&&(vm(c),d.node().tagName=="A"&&b==D&&wm(c),a.lH(d)?d.done():a.xH?(a.xH.Gd(d),Ina(a,d)):d.done())

(Notice how Maps includes some sort of build number in the URL - that day I was apparently using build 399b).

Having found the code that might be responsible, I loaded the JS file's URL directly, used "View source" and ran my own JS-formatting PHP script to beautify and wrap the source code right there in Opera's cache. (There are several online alternatives here, but not all of them are bug-free. Mine hasn't broken a script I've thrown at it in years, and it's been in daily use, so I feel pretty confident while using it.)

Knowing that Tools > Advanced > Reload from cache would now run Maps with the formatted script, I was ready to open Opera Dragonfly and have a good look at the code while it's running.

Rigging things some more, I also added an auto-response entry in Fiddler so that all browsers on my computer, if they happened to request this .js file, would get the formatted one from Opera's cache folder. This way, I might add debug code and reload from cache in Opera, but simultaneously compare with some other browser by refreshing the page to run the same debug code there. It's often very, very useful to compare with another browser at an early stage. (This case turned out to be a counter-example, sort of, and I might have completed the analysis faster if I had delayed comparisons until I was more confident I had found the problematic code..)

The function from the stack I decided to stop in contained only this:

var c=this.lH[a.N];
return c?(b&&a.tick("re"),c(a),!0):!1

I stopped here because it does some conditional execution of other functions. Since I believed I had found the "guilty" code, much of the remaining debugging would be to try to pin down where the script would do one thing in Opera but something else in another browser. That usually involves dissecting control structures - basically anywhere the script does if .. then .. else is suspect.

Setting a breakpoint on the

return c?(b&&a.tick("re"),c(a),!0):!1

line, Dragonfly stopped nicely - and it was time to inspect the state of the script. Things took a very confusing turn. b was false, that was easy. The somewhat unusual syntax b&&a.tick("re"),c(a) means a.tick() will only be called if b evaluates to true - in other words, it's a compressed way of writing

if(b)a.tick("re");

Maps uses this syntax a lot.

The c() function would, however, run - the && operator only works before the comma. Before stepping into it, I wanted to get a quick glance of what it would do - and Maps gave me the first small surprise. Typing c into the Dragonfly console would output

function () { [native code] }

What?! The variable referred to some function defined by Opera, not Maps!? But why did it not have a name? Stringifying a native function will usually include the name, for example

function alert(){ [native code] }

Why was this one different? What native function was it? And how could a native function possibly wind up calling removeChild() inside the Maps page??

This was getting really, really interesting..but I still expected to find the problem just "around the corner"..

At least I could easily figure out what a.N was. It was a string, and its value was 'rmi.updateUI'.

Pressing [F11] to step into c() brought another surprise. Opera's scripting engine jumped into code that looked completely different. I summarized my confusion in the bug tracker:

Opera suddenly is inside an eval'ed GAddMessages() call and claims to have r.O$ on the stack. The stack makes no sense at all..neither r.O$ nor eval() is called anywhere.

Approximately at this point, I was distracted because my son's school day was over, and my wife was at work so I had to go and meet him. His school is less than 10 minutes from the Opera Software HQ, easily within walking distance. When I met him, he and his best friend wanted to come to the Opera office, and eager to get back to the interesting problem I took them there.

I helped my son and his friend start playing some random edutainment game, preferably in complete silence since I share office with Ola. Being seven-year-olds, they were naturally not quite silent. Worrying about Ola's concentration was somewhat distracting, so eventually I walked the boys down to the playroom office. Yes, Opera has a playroom office which, along with the canteen's free hot chocolate, might be the main reasons why the kids want to come to the building . I promised to be back soon, and optimistically returned to my laptop screen.

I launched Chrome and opened the debugger to check the value of the mysterious c variable. Wow! The output was exactly the same - the odd "native code", name-less function.

In another lucky strike, I searched for "rmi." and looked at how some apparently related functions were set. Looking at one of the functions involved, I found this:

return a.call.apply(a.bind,arguments)

Hm.. What might

Function.prototype.call.apply(Function.prototype.bind, [function(){}])

output? Voila! A "native" function without a name.

What this trick does - and I haven't seen this anywhere else yet - is to call the native Function.prototype.bind function with some page-defined function as the this object, and return a new function created by bind().

Now, with the current debuggers there is no obvious way to see the source code of these functions - in other words, inspect the function that was passed in as the this object of the native bind() function in the apply call. One needs to find the code that calls bind() to in look at the function before bind() runs.

Sounds easy?

The above (and variations of it) is among Maps' basic utilities, and it is used a lot. Setting breakpoints and even logging will given you an instant information overload..

Actually, I want to set a breakpoint or get a stack trace from the point where a property named rmi.updateUI is set on any object in the page. As far as I know, no JavaScript debugger has such capabilities yet, although I may be wrong here given the speed they evolve with these days.

Hm.. User JavaScript and ES5 to the rescue:

Object.defineProperty(Object.prototype, 'rmi.updateUI', {
	get : function () {
		opera.postError('rmi.updateUI read');
		return this.___desc;
	},
	set : function (val) {
		opera.postError('rmi.updateUi set to '+val); 
		try{undefined();}catch(e){opera.postError(e.stack);}
		this.___desc = val;
	}
});

An initial attempt used Object.prototype.__defineSetter__(), but this created a property that Maps would run into when enumerating objects with for..in (and predictably, Maps did just that). Hence the ES5 syntax, Object.defineProperty(), which lets you create non-enumerable properties. Success! I got a stack trace! Assuming that something in the execution of rmi.updateUI would go wrong in Opera and remove the box, I set a suitable breakpoint on the same line in Opera and Chrome and intended to do a step-by-step comparison.

..and approximately at this point I realised I would most definitely NOT get to the bottom of this within a reasonable time, paused the debugging and took the somewhat bored boys home.

Looking back, I started stepping through code somewhat prematurely. Stepping takes a lot of time, so ideally one should get as close as possible to the relevant code before breaking and stepping.

Running the two debuggers - Dragonfly and Chrome's developer tools - side by side, would sometimes slow both browsers down. Badly. I guess it sort of makes sense - a debugger needs to keep track of a lot of state, so in some ways I guess debugging is simply an orchestrated memory leak.. It turned into a real problem when using Chrome's dev tools' built-in script formatting. After a number of Maps reloads, I was counting minutes instead of seconds between tests..

Maps' code was - as always - really hard to read. A random and representative sample:

Be.prototype.getName=function(){var a=this.F.name;return a!=i?a:""};
Be.prototype.ke=function(){var a=this.F.description;return a!=i?a:""};
Be.prototype.Se=t(180);var af=function(a){a=a.F.b_s;return a!=i?a:0},
gea=new xd,bf=function(a){return(a=a.F.latlng)?new xd(a):gea},
hea=new ye,iea=function(a){return(a=a.F.sprite)?new ye(a):hea},
jea=new we,cf=function(a){return(a=a.F.ext)?new we(a):jea},
kea=new ve,df=function(a){return a.F.infoWindow!=i},
ef=function(a){return(a=a.F.infoWindow)?new ve(a):kea},
lea=new Td,mea=new Ce,nea=new qd,oea=new Ae;Ce.prototype.Aa=m("F");Ce.prototype.Vb=function(){var a=this.F.type;return a!=i?a:0};

Apart from the obfuscation, several other issues made it hard to get an overview - even while stepping through it. Here's a Dragonfly screenshot and some explanations:

1. As already explained, several functions would stringify as native ones, with no obvious way to inspect what they would actually do when called. Sometimes such bound functions would live inside other bound functions, creating several layers of confusion.
2. Dragonfly or Opera itself has a bug that shows the wrong source code for several stack entries. I have not yet managed to figure out why.
3. While the Object.defineProperty() method from ES5 was really useful, I was considerably less amused by discovering that Maps runs in ES5 strict mode. Typing arguments.callee into the console can be a quick way of looking at the function you're inside - it's often useful to get an idea of its size and control flow. This would have been particularly useful when stepping inside those "bound" functions. Unfortunately, ES5 deprecates the arguments.callee property. I know there are some sound technical reasons for that but it sucks for debugging..

Additionally, Maps is very modular - which is probably a good thing - and loads its modules by passing long strings of source to window.eval() which is extremely inconvenient for my purposes. The strings won't be formatted and line wrapped (to the formatting script, they are just strings), and adding debug code to them is very fiddly because one must remember to escape quotes.

Maps combines and obfuscates its JavaScript modules. The module names will be in the JS file's URL, for example {main,mod_util,mod_rst}.js. Adding to my debugging challenges, was that it would sometimes serve different combinations (or builds?) to different browsers. The module I was investigating is called mod_suck (and I admit that I eventually found the name quite appropriate.. This tweet is also merely vented Maps debug frustration).

If mod_suck was sent to Opera in a file with modules A, B and C, but to Chrome in a file with modules X, Y and Z, mod_suck's obfuscation would be different and variables and functions have completely different names.. (However, within the file the separate modules might use the same names. For example if this.initialize was obfuscated as this.dF each file would contain several this.dF definitions. Juggling which ones to debug across two different files was very confusing..)

Finally, I already mentioned the URL build numbers. Maps seems to iterate quickly. In 10 days I've seen four versions. When Maps decides to send a new set of scripts, a lot of debugger state gets lost: breakpoints in the debuggers, debug code I added in locally cached files and so on. Even my mental knowledge of variable and method names and the notes I jotted down on paper while debugging the previous version are suddenly obsoleted by the new obfuscation.

At this point in the debugging I spent the best hours of a day trying to figure out what triggered the Dragonfly bug. I didn't really succeed at that. Yet.

The holy grail of this type of QA work is a minimized test case - a small file, as short and sweet as possible - that contains only the code that triggers the problem. The ultimate aim of my analysis is to reduce the megabytes of complexity that is Maps to a small file that clearly shows where Opera is wrong (if it is Opera's fault in the first place, of course).

There are mainly two ways to do that - either take your understanding of what's happening in some of the relevant code and write a small file that does something similar from scratch, or take the whole application and remove piece by piece until you reach a minimal version that shows the issue. The latter would obviously be extremely time consuming for Maps, but several attempts at creating a test case for Dragonfly from scratch failed. I spent a bit of time refining a Fiddler script that tries to dump a local, functional copy of a website I load. Thanks to the powers of Fiddler, it is quite close to being able to automatically create a snapshot of the Google Maps front end, with many of the references rewritten and much of the functionality working. Will probably be handy some day later

Trying to get back to the original problem, I happened to try to removeChild() exception trick in Chrome. Wow - the exception also fired in Chrome, even though the dialog wasn't removed. Maps used removeChild() to change the contents of the dialog - perhaps I had been going down the wrong paths for several days..?

Another user script for debugging helped me get back on track - given that the dialog removal probably happened as a consequence of event listeners on the SELECT element, I wanted to figure out what event listeners ran, and whether preventing some of them would help:

opera.addEventListener('BeforeEventListener.change', function(e){if(top.opera._x)opera.postError(e.preventDefault()||'stopped event '+e.listener)}, false);
opera.addEventListener('BeforeEventListener.click', function(e){if(top.opera._x)opera.postError(e.preventDefault()||'stopped event '+e.listener)}, false);
opera.addEventListener('BeforeEventListener.mouseup', function(e){if(top.opera._x)opera.postError(e.preventDefault()||'stopped event '+e.listener)}, false);

I could log listeners from User JS - but preventing for example click events outright would prevent me from opening the dialog itself. Hence the if(top.opera._x) check - I open the dialog, run a bookmarklet to set opera._x to true, and use the SELECT element. User JS blocks the relevant events and outputs some information in the console.

And here was another surprise: several listeners were problematic. Either click, change or mouseup would apparently trigger the removal. Maps seems very thorough in its event handling indeed..

Trying to log removeChild() actions happening during event execution brought up nothing of interest, however:

var realremovechild=Element.prototype.removeChild;
Element.prototype.removeChild=function(child){
    try{if(window.event.type=='change')opera.postError(child);}catch(e){}
    return realremovechild.apply(this, arguments);
}

The only way ahead was logging all removeChild() usage and compare logs from Opera and Chrome.

Some information overload later, I noticed that a removeChild() call removed elements from a

<div class="gmnoprint">

parent in Opera but not in Chrome. Maybe I was on the right track now? If I was, the track looked more or less like this:

Timeout thread: delay 250 ms
<anonymous function: r.hide>([arguments not available])@
<anonymous function: pL.prototype.qb>([arguments not available])@
<anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:15430
<anonymous function: ut.prototype.qb>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:15423
<anonymous function: r.qb>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:8496
<anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:8506
<anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:0

..and there was of course the reason why no interesting removeChild() calls happened during event processing: it happened from a timeout. That's where the apparently correct track ended - the stack won't tell us where the timeout was set, much less where Chrome went down a different route and didn't set it.

Maps uses setTimeout() and setInterval() a lot. Again, normal approaches to breakpoints and logging are pretty much useless - Maps logs timeouts much faster than I can guess whether they are interesting. (It doesn't help that Opera describes both intervals and timeouts as "Timeout thread" in its error console - we don't even know if setTimeout or setInterval was used.).

User JS comes to the rescue again (though this time with a generic snippet that could also be pasted directly into Dragonfly's console or the cached .js file):

(function(sto){
	window.setTimeout=function(func, time){
		if( time==250  ){
			try{undefined();}catch(e){console.log('250ms timeout stack:\n'+e.stack);}
		}
		return sto.apply(this, arguments);
	}
})(setTimeout);

and FINALLY.. this is a smoking gun, sort of. At least a hint of smoke:

<anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:5362
 <anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:5356
 wm([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:5662
 <anonymous function: r.bea>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:8505
 <anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:0
 <anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:5023
 F([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:2223
 C([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:5020
 <anonymous function>([arguments not available])@http://maps.gstatic.com/cat_js/intl/no_ALL/mapfiles/401c/maps2/%7Bmain,mod_util,mod_rst%7D.js:7379

This sets a timeout that eventually causes the unexpected removal.

At this point I tried logging the C and F functions. I often use a quite neat "log by conditional breakpoints" trick. Set a breakpoint in the JavaScript debugger where you want to log something, right-click it and add a condition, then type for example

console.log( 'the this.dF function ran in this browser!', window.event.type )

When you no longer need this logging, the developer tool's list of breakpoints is a convenient place to quickly silence each logger by disabling the breakpoint. Since console.log() and opera.postError() don't return anything, the script will never actually stop at the breakpoints, but that's intentional.

C and F turned out to be extremely busy. What was worse, they often were dealing with bound functions or functions with some closure data that C and F did not have access to - in other words, while logging C and F I had no way to tell what log entries were related to the function stack I was interested in. (I had sort of given up on Dragonfly because of the broken stack problems earlier.)

Eventually, I tried looking at the stack of an exception provoked in the r.bea function from the stack above (which had meanwhile turned into s.gea since Maps had kindly bestowed upon me yet another new build). And d'oh - I had forgotten that the stack property of an exception object includes only ten lines or so. The real stack was of course much longer, as Dragonfly would have told me..

Through logging breakpoints I could quickly figure out that most of this stack trace wasn't called in Chrome at all. Was I finally approaching the if..else where the browsers parted ways? Stepping up the stack, if(a.Pm)return a.yf.apply(a.Pm,b) piqued my interest, but trying to log code that set either yf of Pm returned so much noise that I moved on. Inside a method named s.oQ, this line looked extremely promising:

(this.O==0||c-this.zc<=Tia&&mg(this.C.x-a.clientX)<=2&&mg(this.C.y-a.clientY)<=2)&&D(this,E,a)

- all of a sudden we have conditional execution and some dependency on values from the DOM - event.clientX and clientY which might well be entirely different between browsers.

Alas, not even this method ran in Chrome..but s.oQ was called from Qia, and Qia was called from only a few places in the code. One of them here:

Fh.prototype.lF=function(a){
		rn(this,a);
		D(this,bb,a);
		if(!a.cancelDrag&&Oia(this,a)){
			sn(this);
			Pia(this,a.clientX,a.clientY);
			if(this.lm)var b=new Ff(this.lm);
			Qia(this,a,b);

Another place for breakpoint logging - and now we're coming up with a real difference: a.cancelDrag is always true in Chrome, but in Opera it's sometimes undefined. It's undefined in Opera if a is the event object of a mousedown event whose target is an OPTION element inside the SELECT. If it's undefined, the above code will go on to call Qia, which eventually causes the timeout to be set and the dialog to disappear.

That leaves us just a little bit of detective work: cancelDrag is not a built-in property (I checked the HTML5 drag-and-drop spec just to be sure I wasn't missing anything..). Where is it set? Elementary, dear Watson - we simply reuse the Object.defineProperty() trick to break if it is. It works in Chrome too. What do we find? If the function a gets called in this method, it is set:

iL.prototype.K=function(a,b){if(P.type==1)a(b);else{var c=Gm(b,this.j.window);(isNaN(c.y)||c.y<=this.H.height+36)&&a(b)}}

P.type is browser sniffing. Opera is not included in type=1 (it's type 0). So, a mix of browser sniffing and position-of-something detection determines whether cancelDrag is set.

So Opera fires a mousedown event on OPTION. Not all browsers do - it's us and Firefox versus IE and Chrome. (And yes, we're extremely thorough about this and fire these mouse events even if you use the keyboard to change the SELECT's value!).

This mousedown event appears to trigger some DnD-related logic, which I haven't studied in detail. I think the script starts reading event.clientX and event.clientY and such to determine whether you might later intend to drag the OPTION, then fire some custom "we'll start dragging the map, initialize" event and get really confused when a change/mouseup/click event comes along and says it's time to update the dialog while a drag appears to be in progress.

Given that Firefox fires mousedown on OPTION like Opera, why doesn't Firefox have the same bug? To understand this, we need to investigate the positioning code.

return tk(P)?new H(a.pageX-window.pageXOffset,a.pageY-window.pageYOffset):new H(a.clientX,a.clientY)

Opera runs the part after the colon, and it turns out that event.clientY returns a significantly higher value in Opera than in Firefox when one clicks an OPTION element that has some absolutely positioned ancestor, even when the browser windows are aligned so that the vertical position on the screen is similar.

This extremely small and subtle incompatibility just met Maps' browser sniffing and turned their "Report a problem" dialog into a problem. My problem. But the best thing about QA work is that when you've looked at a problem for long enough, it automatically becomes somebody else's problem . I sincerely hope that "long enough" will remain significantly shorter than ten days for most problems out there..