
Photo by Clio20
I've just spent several days tracking down a serious but hard to reproduce bug, so I wanted to leave a trail of Googleable breadcrumbs for anyone else who's hitting similar symptoms.
As some background, Jetpac's iPad app uses a UIWebView to host a complex single-page web application. There are a lot of independent scripts that we normally minify down into a handful of compressed files in production. Over the last few weeks, a significant percentage of our new users have had the app hang on them the first time they loaded it. We couldn't reproduce their problems in-house, which made debugging what was going wrong tough.
From logging, it seemed like our app setup Javascript code was failing, so the interface never appeared. The strange thing was that it was rarely the same error, and often the error locations and line numbers wouldn't match with the known file contents, even after we switched to non-minified files. Eventually we narrowed it down to the text content of some of our <script> tags being pulled from a different <script> tag elsewhere in the file, seemingly at random!
That's going to be hard to swallow, so here's the evidence to back up what we were seeing:
We had client-side logging statements within each script's content, describing what code was being executed at what time, combined with <script> onload handlers that logged what src had just been processed. Normal operation would look like this:
…
Executing module storage.js
Loaded script with src 'https://www.jetpac.com/js/modules/storage.js'
Executing module profile.js
Loaded script with src 'https://www.jetpac.com/js/modules/profile.js'
Executing module nudges.js
Loaded script with src 'https://www.jetpac.com/js/modules/nudges.js'
…
In the error case, we'd see something like this:
…
Executing module storage.js
Loaded script with src 'https://www.jetpac.com/js/modules/storage.js'
Executing module profile.js
Loaded script with src 'https://www.jetpac.com/js/modules/profile.js'
Executing module storage.js
Loaded script with src 'https://www.jetpac.com/js/modules/nudges.js'
…
Notice that the third script thinks it's loading nudges.js, but the content comes from storage.js!
Ok, so maybe the Jetpac server is sending the wrong content? We were able to confirm through the access log the file with the bogus content (nudges.js in the example above) was never requested from the server. We saw the same pattern every time we managed to reproduce this, and could never reproduce it with the same code in a browser.
As a clincher, we were able to confirm that the content of the bogus files was incorrect using the iOS 6 web inspector.
The downside is that we can't trigger the problem often enough to create reliable reproduction steps or a test app, so we can't chase down the underlying cause much further. It has prompted us to change our cache control headers since it seems like something going wrong with the iOS caching, and the logging has also given us a fairly reliable method of spotting when this error has happened after the fact. Since it is so intermittent, we're triggering a page reload if we do know we've lost our marbles. This generally fixes the problem, since it it does seem so timing dependent, though the hackiness of the workaround doesn't leave me with a happy feeling!
If you think you're hitting the same issue, my bet is you aren't! It's pretty rare even for us, but if you want to confirm try adding logging like this in your script tags, and log inside each js file to keep track of which you think is loading:
<script src="foo.js" onload="console.log('loaded foo.js');"/>
In foo.js
console.log('executing foo.js');
…
Comparing the stream of log statement will tell you if things are going wrong. You'd expect every 'executing foo.js' to be followed by a 'loaded foo.js' in the logs, unless you're using defer or async attributes.