Overview
A long, rambly and very geeky post without a proper ending about some of the challenges I recently had getting WebSockets to work with mobile Safari on the iPhone/iPad.
Background
I wrote last week about a recent project of mine – a proof-of-concept using a custom WebSockets server implementation to push messages to web apps.
A target platform for one of the demos that I wrote to go with this was the iPhone. But it wasn’t as straightforward as I’d hoped. And I’ve ranted enough about it to friends and colleagues and on twitter. About time that I did a bit of moaning here ??
Starting with a poor excuse…
I made the dumb, obvious school-boy mistake for any development – I left testing on all target platforms way too late. For most of my development time, I developed against Safari and Chrome on Windows and Linux.
In my defence, I don’t have an iPhone or Mac. When doing iPhone web app development I set the user agent in Safari to an iPhone string, and use bookmarklets that resize the browser window to emulate the right resolution. And this has never caused a problem before. On rare occasions, when it came to testing on real devices, there are some minor rendering differences, but even then these have been easily fixable.
But this is a lame defence. I should’ve borrowed an iPhone from work and been trying this on a real device from day 1 instead of leaving it until a few weeks before the deadline.
I’m a muppet.
What was happening
With that out of the way…
I had written a web app which makes a WebSockets connection to our custom server implementation, then started sending and receiving JSON messages.
On Chrome, Safari, and Firefox, this worked beautifully. No errors reported at all. On the mobile browser on a BlackBerry, it worked brilliantly.
Then I tried it on an iPhone, where it worked for a bit. Then crashed mobile Safari.
With no warning, Safari just closed.
I tried it again. Again, mobile Safari just crashed, although this time at a different point in the app’s sequence. Third attempt, and a third crash, again in a third different point.
Sometimes it would crash almost immediately, other times it would be okay for a minute or two before crashing.
How I investigated
First step – the console on Safari.
Most times – say nine out of ten times – no errors got written out to the console before it crashed. Or at least, none that I had a chance to see – once Safari crashes, all the console logs are lost, so there might have been something reported immediately before the crash that I never saw.
Occassionally, I saw “WebSocket frame (at X bytes) is too long” in the console – where X was an implausibly large number (I saw it go as high as 8.3GB).
But when I saw that error, it was accompanied by a report that the connection was lost, which my web app handled by closing the WebSocket cleanly and updating the UI accordingly.
There is no way that it could have received an 8GB frame, given how quickly it was receiving messages. This looked like a gibberish number. An error in how Safari was reporting the error? A buffer overrun?
So I didn’t know if this was related to the crashes or not, but it was the only bit of diagnostics I had to go on so far.
Next step – adding trace.
I added a mountain of trace (console.debug, console.log, etc.) to my JavaScript code to try and get an idea of what happened in the run up to a crash.
That didn’t help. With the exception of the occasional error mentioned above, everything always looked absolutely fine, right up until the point where it would go bang and kill Safari.
Then – using weinre to follow the trace
I hadn’t used this before, but it’s pretty awesome.
You know the Firebug-style web developer tools you get in desktop WebKit browsers like Chrome and Safari? weinre gives you that on your desktop for web apps running on a mobile web browser such as on iPhone or Android.
The point is, the console log in mobile Safari is primitive to the point of being only barely usable. You can’t use console.dir to look at objects, there is no interactive console, you can’t inspect the DOM and so on.
weinre gives you all the Firebug-style goodness that we’re used to in desktop browsers while you’re running mobile web apps.
(As an aside, I didn’t realise until after I’d started using it that it was actually made by a colleague of mine – Patrick Mueller in the US bit of my team, IBM Emerging Technologies. Small world!)
This let me get a much better understanding of what was going on – I could trace out every WebSockets packet my JavaScript was sending and receiving and what my code was doing about it.
No joy.
There is a small delay in collecting the console and DOM changes and sending it to the weinre server – it is not as instantaneous as Firebug on your local machine. The problem was that this is done by JavaScript that you embed in the page you are debugging. So when Safari crashes, it stopped sending stuff.
Add in the delay, and I’m still not sure I saw everything in the last instant before a crash.
It was very useful, though – it gave me a better understanding of what was going on, and seemed to indicate that the crash was happening at seemingly random points in the sequence of messages.
Next – fun with wireshark.
I ran all the WebSockets traffic through a redir TCP/IP forwarder on my Ubuntu desktop, and used Wireshark to study it.
I spent a couple of days examining every packet that went between the iPhone and the server, both when it was working okay, and when it led to a crash.
It looked fine. I couldn’t see anything wrong with any of the WebSockets messages.
And it confirmed what weinre’s log had suggested, that the crashes were happening at seemingly random points in the flow.
More confusingly, it showed that messages sent and received while it was working fine were almost indistinguishable from messages that were followed by a crash.
Argh
Getting crash logs
When an app on iPhone crashes, it does generate a crash report. And you can get these off the phone when it syncs with a desktop.
What was the exception that was causing iOS to kill Safari?
There were a lot of them, but a lot of them looked like this:
Exception Type: EXC_BAD_ACCESS (SIGBUS) Exception Codes: KERN_PROTECTION_FAILURE at 0x0000008a Crashed Thread: 2 Thread 2 Crashed: 0 ??? 0x0000008a 0 + 138 1 WebCore 0x3311c880 0x33070000 + 706688 2 WebCore 0x332f4380 0x33070000 + 2638720 3 WebCore 0x332f3af0 0x33070000 + 2636528 4 WebCore 0x332f3a24 0x33070000 + 2636324 Thread 2 crashed with ARM Thread State: r0: 0x0408c588 r1: 0x0000008b r2: 0x00000000 r3: 0x00000000 r4: 0x0408c010 r5: 0x00000000 r6: 0x00000000 r7: 0x004f7398 r8: 0x040c2b60 r9: 0x00000060 r10: 0x042bfc90 r11: 0x00000000 ip: 0x00000000 sp: 0x004f7394 lr: 0x3311d980 pc: 0x0000008a cpsr: 0x200f0030
The EXC_BAD_ACCESS bit was kinda interesting, but ultimately the raw logs aren’t that useful.
But where it got interesting was when I got Rob to help. He’s got the iOS SDK – which includes the SYM files for the iPhone apps, and the tools that can combine the raw crash logs with the symbol files to create more readable stack-traces.
0 JavaScriptCore 0x00020c92 JSC::Lexer::setCode(JSC::SourceCode const&, JSC::ParserArena&) + 138 1 JavaScriptCore 0x00020b5c JSC::Parser::parse(JSC::JSGlobalData*, int*, JSC::UString*) + 104 2 JavaScriptCore 0x0003a028 WTF::PassRefPtr<JSC::FunctionBodyNode> JSC::Parser::parse<JSC::FunctionBodyNode>(JSC::JSGlobalData*, JSC::Debugger*, JSC::ExecState*, JSC::SourceCode const&, int*, JSC::UString*) + 44 3 JavaScriptCore 0x00039e3e JSC::FunctionExecutable::compile(JSC::ExecState*, JSC::ScopeChainNode*) + 38 4 JavaScriptCore 0x000574ac JSC::Interpreter::execute(JSC::FunctionExecutable*, JSC::ExecState*, JSC::JSFunction*, JSC::JSObject*, JSC::ArgList const&, JSC::ScopeChainNode*, JSC::JSValue*) + 232 5 JavaScriptCore 0x000573b0 JSC::JSFunction::call(JSC::ExecState*, JSC::JSValue, JSC::ArgList const&) + 112 6 JavaScriptCore 0x00055f16 JSC::call(JSC::ExecState*, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&) + 54 7 WebCore 0x00138242 WebCore::JSEventListener::handleEvent(WebCore::ScriptExecutionContext*, WebCore::Event*) + 638 8 WebCore 0x00137f8c WebCore::EventTarget::fireEventListeners(WebCore::Event*, WebCore::EventTargetData*, WTF::Vector<WebCore::RegisteredEventListener, 1ul>&) + 292 9 WebCore 0x0004996c WebCore::EventTarget::fireEventListeners(WebCore::Event*) + 148 10 WebCore 0x0011f5b6 WebCore::EventTarget::dispatchEvent(WTF::PassRefPtr<WebCore::Event>) + 54 11 WebCore 0x00582542 WebCore::WebSocket::didConnect() + 94 12 WebCore 0x005824dc non-virtual thunk to WebCore::WebSocket::didConnect() + 4 13 WebCore 0x00583192 WebCore::WebSocketChannel::processBuffer() + 178 14 WebCore 0x0058351a WebCore::WebSocketChannel::didReceiveData(WebCore::SocketStreamHandle*, char const*, int) + 70 15 WebCore 0x00513a7c WebCore::SocketStreamHandle::readStreamCallback(unsigned long) + 204 16 WebCore 0x00513ad0 WebCore::SocketStreamHandle::readStreamCallback(__CFReadStream*, unsigned long, void*) + 4 17 CoreFoundation 0x0001da1a _signalEventSync + 70 18 CoreFoundation 0x0001d9b6 _cfstream_solo_signalEventSync + 58 19 CoreFoundation 0x0001d8aa _CFStreamSignalEvent + 326 20 CoreFoundation 0x0001d75c CFReadStreamSignalEvent + 4 21 CFNetwork 0x00084c14 SocketStream::dispatchSignalFromSocketCallbackUnlocked(SocketStreamSignalHolder*) + 20 22 CFNetwork 0x000123f4 SocketStream::socketCallback(__CFSocket*, unsigned long, __CFData const*, void const*) + 104 23 CFNetwork 0x00012376 SocketStream::_SocketCallBack_stream(__CFSocket*, unsigned long, __CFData const*, void const*, void*) + 42 24 CoreFoundation 0x0007a48a __CFSocketDoCallback + 334 25 CoreFoundation 0x0007b4a2 __CFSocketPerformV0 + 78 26 CoreFoundation 0x00075a72 __CFRUNLOOP_IS_CALLING_OUT_TO_A_SOURCE0_PERFORM_FUNCTION__ + 6 27 CoreFoundation 0x0007769c __CFRunLoopDoSources0 + 188 28 CoreFoundation 0x000784e4 __CFRunLoopRun + 224 29 CoreFoundation 0x00008ebc CFRunLoopRunSpecific + 224 30 CoreFoundation 0x00008dc4 CFRunLoopRunInMode + 52 31 GraphicsServices 0x00004418 GSEventRunModal + 108 32 GraphicsServices 0x000044c4 GSEventRun + 56 33 UIKit 0x0002ed62 -[UIApplication _run] + 398 34 UIKit 0x0002c800 UIApplicationMain + 664 35 MobileSafari 0x000231d6 0x21000 + 8662 36 MobileSafari 0x00022c1c 0x21000 + 7196
As I mentioned above, I was using the WebSocket to send a chunk of JSON, so the first thing I did with anything I received down the socket was call JSON.parse on it.
This was blowing up – the stack trace shows the attempt to parse near the top, with the WebSockets stuff below.
Could it be a weird state error – where the JSON parser caused a conflict while in the WebSocket callback?
I tried using setTimeout in the WebSocket’s onmessage callback, letting the callback return immediately, and passing off the JSON parsing until later.
It still crashed, and still during parsing – so all this changed was removing the WebSockets stuff from the stack trace:
0 JavaScriptCore 0x000038ae JSC::JSString::~JSString() + 34 1 JavaScriptCore 0x00003882 JSC::JSString::~JSString() + 2 2 JavaScriptCore 0x00018b84 JSC::Heap::allocate(unsigned long) + 136 3 JavaScriptCore 0x00033544 JSC::jsOwnedString(JSC::JSGlobalData*, JSC::UString const&) + 84 4 JavaScriptCore 0x00046d3c JSC::JSPropertyNameIterator::create(JSC::ExecState*, JSC::JSObject*) + 332 5 JavaScriptCore 0x00096ab2 JITStubThunked_op_get_pnames + 82 6 JavaScriptCore 0x00094862 cti_op_get_pnames + 2 7 JavaScriptCore 0x000573b0 JSC::JSFunction::call(JSC::ExecState*, JSC::JSValue, JSC::ArgList const&) + 112 8 JavaScriptCore 0x00055f16 JSC::call(JSC::ExecState*, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&) + 54 9 WebCore 0x000ea3b4 WebCore::ScheduledAction::executeFunctionInContext(JSC::JSGlobalObject*, JSC::JSValue) + 332 10 WebCore 0x000ea1d0 WebCore::ScheduledAction::execute(WebCore::Document*) + 108 11 WebCore 0x000ea15c WebCore::ScheduledAction::execute(WebCore::ScriptExecutionContext*) + 32 12 WebCore 0x000e9bc8 WebCore::DOMTimer::fired() + 240 13 WebCore 0x000a6608 WebCore::ThreadTimers::sharedTimerFiredInternal() + 92 14 WebCore 0x000a659a WebCore::ThreadTimers::sharedTimerFired() + 34 15 WebCore 0x000a654e WebCore::timerFired(__CFRunLoopTimer*, void*) + 34
When I tried and parse what I got into JSON, it still blew up.
I made a bunch of desperate attempts to detect and protect against this, such as:
substring() to make a copy caused a crash.split("").join("") as another way to try and make a “clean” copy – this also caused a crash.length caused a crashalert() to display ittypeof what came out of the WebSocket onmessage callback, and not touching it if it’s not a stringand so on.
In each case, Safari crashed with a similar stack, such as:
0 JavaScriptCore 0x00003574 JSC::JSArray::~JSArray() + 20 1 JavaScriptCore 0x00003556 JSC::JSArray::~JSArray() + 2 2 JavaScriptCore 0x00018b84 JSC::Heap::allocate(unsigned long) + 136 3 WebCore 0x000e6eec JSC::JSValue WebCore::getDOMObjectWrapper<WebCore::JSCSSStyleDeclaration, WebCore::CSSStyleDeclaration>(JSC::ExecState*, WebCore::JSDOMGlobalObject*, WebCore::CSSStyleDeclaration*) + 68 4 WebCore 0x000e6e9e WebCore::toJS(JSC::ExecState*, WebCore::JSDOMGlobalObject*, WebCore::CSSStyleDeclaration*) + 2 5 WebCore 0x000f88b4 WebCore::jsDOMWindowPrototypeFunctionGetComputedStyle(JSC::ExecState*, JSC::JSObject*, JSC::JSValue, JSC::ArgList const&) + 252 6 JavaScriptCore 0x0009a4ce JITStubThunked_op_call_NotJSFunction + 194 7 JavaScriptCore 0x00094562 cti_op_call_NotJSFunction + 2 8 JavaScriptCore 0x000573b0 JSC::JSFunction::call(JSC::ExecState*, JSC::JSValue, JSC::ArgList const&) + 112 9 JavaScriptCore 0x00055f16 JSC::call(JSC::ExecState*, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&) + 54 10 WebCore 0x00138242 WebCore::JSEventListener::handleEvent(WebCore::ScriptExecutionContext*, WebCore::Event*) + 638 11 WebCore 0x00137f8c WebCore::EventTarget::fireEventListeners(WebCore::Event*, WebCore::EventTargetData*, WTF::Vector<WebCore::RegisteredEventListener, 1ul>&) + 292 12 WebCore 0x0004996c WebCore::EventTarget::fireEventListeners(WebCore::Event*) + 148 13 WebCore 0x00049b40 WebCore::Node::handleLocalEvents(WebCore::Event*) + 116
or
0 JavaScriptCore 0x000494b8 WTF::tryFastRealloc(void*, unsigned long) + 2112 1 JavaScriptCore 0x00048bf4 JSC::JSArray::increaseVectorLength(unsigned int) + 52 2 JavaScriptCore 0x00049f06 JSC::JSArray::putSlowCase(JSC::ExecState*, unsigned int, JSC::JSValue) + 438 3 JavaScriptCore 0x00049d44 JSC::JSArray::put(JSC::ExecState*, unsigned int, JSC::JSValue) + 84 4 JavaScriptCore 0x0005c43a JSC::arrayProtoFuncSplice(JSC::ExecState*, JSC::JSObject*, JSC::JSValue, JSC::ArgList const&) + 722 5 JavaScriptCore 0x0009a4ce JITStubThunked_op_call_NotJSFunction + 194 6 JavaScriptCore 0x00094562 cti_op_call_NotJSFunction + 2 7 JavaScriptCore 0x000573b0 JSC::JSFunction::call(JSC::ExecState*, JSC::JSValue, JSC::ArgList const&) + 112 8 JavaScriptCore 0x00055f16 JSC::call(JSC::ExecState*, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&) + 54 9 WebCore 0x00138242 WebCore::JSEventListener::handleEvent(WebCore::ScriptExecutionContext*, WebCore::Event*) + 638 10 WebCore 0x00137f8c WebCore::EventTarget::fireEventListeners(WebCore::Event*, WebCore::EventTargetData*, WTF::Vector<WebCore::RegisteredEventListener, 1ul>&) + 292 11 WebCore 0x0004996c WebCore::EventTarget::fireEventListeners(WebCore::Event*) + 148
or
0 JavaScriptCore 0x00041b8e WTF::tryFastMalloc(unsigned long) + 874 1 JavaScriptCore 0x0004154e JSC::JSString::resolveRope(JSC::ExecState*) const + 70 2 JavaScriptCore 0x0004d8be JSC::stringProtoFuncReplace(JSC::ExecState*, JSC::JSObject*, JSC::JSValue, JSC::ArgList const&) + 322 3 JavaScriptCore 0x0009a4ce JITStubThunked_op_call_NotJSFunction + 194 4 JavaScriptCore 0x00094562 cti_op_call_NotJSFunction + 2 5 JavaScriptCore 0x000573b0 JSC::JSFunction::call(JSC::ExecState*, JSC::JSValue, JSC::ArgList const&) + 112 6 JavaScriptCore 0x00055f16 JSC::call(JSC::ExecState*, JSC::JSValue, JSC::CallType, JSC::CallData const&, JSC::JSValue, JSC::ArgList const&) + 54 7 WebCore 0x00138242 WebCore::JSEventListener::handleEvent(WebCore::ScriptExecutionContext*, WebCore::Event*) + 638 8 WebCore 0x00137f8c WebCore::EventTarget::fireEventListeners(WebCore::Event*, WebCore::EventTargetData*, WTF::Vector<WebCore::RegisteredEventListener, 1ul>&) + 292 9 WebCore 0x0004996c WebCore::EventTarget::fireEventListeners(WebCore::Event*) + 148 10 WebCore 0x00049b40 WebCore::Node::handleLocalEvents(WebCore::Event*) + 116 11 WebCore 0x0004970c WebCore::Node::dispatchGenericEvent(WTF::PassRefPtr<WebCore::Event>) + 964 12 WebCore 0x000492b6 WebCore::Node::dispatchEvent(WTF::PassRefPtr<WebCore::Event>) + 166 13 WebCore 0x0014a2a4 WebCore::EventTarget::dispatchEvent(WTF::PassRefPtr<WebCore::Event>, int&) + 48
I couldn’t protect against a crash from the client side. As soon as I tried to touch the evil data that the iPhone was creating from the WebSocket, I got an invalid memory access exception, iOS killed Safari and it was game over.
But in every case, the Wireshark and server-side trace failed to show why. The trace from the server showed that it thought it was sending something valid. The Wireshark trace showed that the packets flowed to the iPhone looked fine.
But the iPhone blew up anyway.
What else could it be?
It’s worth pointing out that several demo apps were made to show off our WebSockets implementation. Only this one web app caused mobile Safari to crash. All the other web apps worked fine on the iPhone.
I wondered if it might be a weird interplay between WebSockets and my use of local storage. But removing my use of local storage made no difference.
I wondered if it might be some weird interaction with the JavaScript framework I used to do stuff like page transitions. But writing the app in jQuery Mobile or dojo mobile made no difference – both flavours of the app crashed.
Rob pointed me at someone’s experience developing with WebSockets for iOS.
It mentions:
What Ia€?ve learned
Floods!? You have to take care of how data is sent through the socket, there are no automatic checks nor buffers. If you send too much data the connection just drops or even worse the browser crashes.
This got me thinking.
What if the problem isn’t what I was sending, but how fast I was sending it?
This would explain why we couldn’t see anything wrong in the server trace, and why I couldn’t see any problems with the packets in the wireshark trace.
It would explain why the crashes were so inconsistent (in terms of where they come in the sequence of messages sent – sometimes during connect, sometimes during the first subscription, other times during the second or third, etc.)
As a quick sniff test, I tried using my redir forwarder to throttle it, altering the max bandwidth limit in the redir options.
It still crashed.
When memory problems get really weird
With the dojo mobile version of the app, the weirdest symptom wasn’t even when it crashed. Sometimes, as data was received down the WebSocket, it caused Japanese (I think?) characters to be appended to the label on the buttons on the page.
The stack traces from the crashes seem to point to some sort of memory write error or overrun. This was just bizarre.
So I said there was no proper ending…
This has to be a bug in mobile Safari, right?
No other browser had any problems running the web app. And as I said, I’ve studied the trace extensively – I’m convinced that the custom WebSockets server implementation is behaving properly.
And I don’t know… those stack traces look like the result of a bug in the browser engine. Even if there was an error in what was being sent to the browser, at worst Safari should close the connection. I don’t think those stack-traces can be an appropriate response for a browser on receiving text (Note that WebSockets sends UTF-8 text at the moment, not binary data) no matter how erroneous the text might be.
We’ll see if raising the issue with Apple helps resolves the problem. In the meantime, it’s been an interesting issue to explore.
Tags: apple, iphone, javascript, safari, websockets
This entry was posted on Monday, April 18th, 2011 at 3:35 pm and is filed under code. You can follow any responses to this entry through the RSS 2.0 feed. Both comments and pings are currently closed.
联系客服
