Worst Case Scenario

Well, that was no fun. Yesterday morning, I ran my iPad app, MealPlan, and it crashed. It wouldn't launch - it just exited. I wasn't at home, where I could debug it, and I wanted to show the app to someone, and I figured the problem was something to do with the fact that I had two copies of the app installed (one by Xcode and one by the App Store) so I just deleted and reinstalled it.

Later yesterday, I got an email from a user, telling me that the app was crashing on launch.

Uh oh.

I apologized to the user, said that they were "the first report person to report this" (when I hear that from a company I always assume they're just saying that to make me feel better, but in this case it really was true), and asked if they wouldn't mind sending me a crash log.

I had checked iTunes Connect, and there were no crash reports. Even now, it still says "Too few reports have been submitted for a report to be shown". But without a crash log, I had no idea what was going on. The instructions I sent to the user were:

One thing that would help would be if you could send me a crash log. It's a bit of work to go and get it, but it would help give me some idea what's going wrong in the application. To get a crash log, sync the iPad with your computer, and then look in these directories on your computer:

Mac: /Library/Logs/CrashReporter/MobileDevice/<iPad name>
Windows: Application Data/Apple Computer/Logs/CrashReporter/MobileDevice/<iPad name>

Fortunately the user was willing to go to some trouble to get the app working again, so they sent me a crash log. The crash log showed MealPlan on the call stack:

Thread 0 name: Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0 libsystem_kernel.dylib 0x3691e32c 0x3690d000 + 70444
1 libsystem_c.dylib 0x36b77208 0x36b2a000 + 315912
2 libsystem_c.dylib 0x36b70298 0x36b2a000 + 287384
3 libsystem_c.dylib 0x36b90cba 0x36b2a000 + 421050
4 MealPlan 0x00043f84 0x3a000 + 40836
5 MealPlan 0x000401b2 0x3a000 + 25010
6 MealPlan 0x0003cf6c 0x3a000 + 12140
7 UIKit 0x30f88a7e 0x30f5c000 + 182910
8 UIKit 0x310868fc 0x30f5c000 + 1222908

So this was a real clue. The crash log from the device doesn't show symbols, and to know what's going on I needed to turn the locations in the crash log into symbols that I could look up in my source. Xcode makes this easy: Drop the .crash file onto the Device Logs section of the Organizer window.

201203190650-1

If everything is working, the bottom of the Organizer window will briefly say that it's Symbolicating your crash log:

201203190652

And then it will show you the crash log with the locations in the crash log converted into symbols that point right to where the problem is happening in your source.

Thread 0 name: Dispatch queue: com.apple.main-thread
Thread 0 Crashed:
0 libsystem_kernel.dylib 0x3691e32c __pthread_kill + 8
1 libsystem_c.dylib 0x36b77208 pthread_kill + 48
2 libsystem_c.dylib 0x36b70298 abort + 88
3 libsystem_c.dylib 0x36b90cba __assert_rtn + 174
4 MealPlan 0x00043f84 -[MPDocument day:] (MPDocument.m:76)
5 MealPlan 0x000401b2 -[MPViewController populate] (MPViewController.m:197)
6 MealPlan 0x0003cf6c -[MPMainView scrollViewDidScroll:] (MPMainView.m:78)
7 UIKit 0x30f88a7e -[UIScrollView setContentOffset:] + 682
8 UIKit 0x310868fc -[UIScrollView(Static) _smoothScroll:] + 3604

Note that for this process to work, Xcode must have access to the symbols for the binary you submitted to the App Store. When you choose Archive for your project, Xcode builds an archive file and adds it to the organizer. You must keep this archive file for any binary you submit to the App Store, so that you can symbolicate your crash logs.

Anyway, once symbolicated, the problem became a bit more clear. I had an assertion at line 76 of MPDocument.m that would fire if there were duplicate entries in my Core Data database. Basically if the app went to get a record for a particular day, and found more than one, it would assert. I leave these asserts on in the release version so that if something does go wrong, even at runtime, the app will crash, rather than continuing on with bad data. The assert pointed right to the problem, where if I didn't have the assert, the app may have continued but would have been updating the wrong record - so sometimes the data from one of the duplicate rows would show up, and sometimes the other would. No good.

After a bit of sleuthing, I managed to figure out what was going on. MealPlan uses UIManagedDocument, and opening a UIManagedDocument is asynchronous. MealPlan would ask the document to open, and then when the document opened, would populate the main view.

Problem is, the main view was active during the brief window while this was happening, and if the user tapped on a row during this interval, the app would create a record in the database before the document was completely open. This led to the inconsistency. The solution for me was to set userInteractionEnabled to NO on my main view while the document was opening, and then set it back to YES when the UIManagedDocument's open completion handler was called. And to clean up the mess that the previous version had made.

The update to 1.0.1 is waiting in Apple's submission queue, and due to the nature of the problem, I've submitted a request for an expedited review (there's a form for that here). So hopefully the fix will go live today.

It's really disappointing when users run into a problem like this "in the wild". For some reason, a lot of people ran into this problem yesterday - I had five reports by the end of the day - even though there's nothing special about yesterday that should have triggered this. But in every case, users weren't angry or looking for a refund, they just wanted to get back to using the app. That makes me happy. :)