1291304 - [iOS 10] Springboard termination crash in 0xdead10cc

Status: RESOLVED FIXED

(Firefox for iOS :: General, defect, P1)

Description

[Aaron Train [:aaronmt]]

Current high volume crash signature for Firefox (v5.0) affecting iOS 10.

Exception Type:  EXC_CRASH (SIGKILL)
Exception Codes: 0x0000000000000000, 0x0000000000000000
Exception Note:  EXC_CORPSE_NOTIFY
Termination Reason: Namespace SPRINGBOARD, Code 0xdead10cc
Triggered by Thread:  0

Thread 0 name:
Thread 0 Crashed:
0   libsystem_kernel.dylib        	0x0000000193d80194 mach_msg_trap + 8
1   libsystem_kernel.dylib        	0x0000000193d80004 mach_msg + 72 (mach_msg.c:103)
2   CoreFoundation                	0x00000001941bde8c __CFRunLoopServiceMachPort + 192 (CFRunLoop.c:2527)
3   CoreFoundation                	0x00000001941bbaa8 __CFRunLoopRun + 1132 (CFRunLoop.c:2870)
4   CoreFoundation                	0x00000001940eb8d8 CFRunLoopRunSpecific + 444 (CFRunLoop.c:3113)
5   GraphicsServices              	0x0000000195af2198 GSEventRunModal + 180 (GSEvent.c:2245)
6   UIKit                         	0x000000019a0957c8 -[UIApplication _run] + 664 (UIApplication.m:2651)
7   UIKit                         	0x000000019a090534 UIApplicationMain + 208 (UIApplication.m:4088)
8   Client                        	0x00000001000cd714 0x1000bc000 + 71444
9   libdyld.dylib                 	0x0000000193c8c5b8 start + 4

~ 2600 devices, top signature

Comment 1

[Aaron Train [:aaronmt]]

This dead lock (0xdead10cc) should be 'easy' to reproduce as it's possible that we're holding onto a system resource when backgrounded?

Comment 2

[Aaron Train [:aaronmt]]

Installed iOS 10 Beta 4 on my iPad Pro. I hit this crash when Firefox was in the background while device was idle. Springboard restarted.

Comment 3

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

At https://developer.apple.com/library/ios/technotes/tn2151/_index.html it says

"The exception code 0xdead10cc indicates that an application has been terminated by iOS because it held on to a system resource (like the address book database) while running in the background."

Does that give us a hint?

Comment 4

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Aaron, can you pull a crash report from your iPad Pro? The report that is written to the device may include more info than what we see in Xcode. Settings -> Privacy -> Diagnostics -> Diagnostic & Usage Data. We need the full .ips file on this bug if you have it.

Comment 5

[Aaron Train [:aaronmt]]

I can only get the same non-symbolic stack traces on the device. This crash is so frequent that any device with iOS 10 (developers) should be able to see this now.

Comment 6

[Stephan Leroux [:sleroux]]

Were you logged into Sync by chance? I got the app running on my iPod Touch on iOS 10b5 but haven't gotten it to crash.

Comment 7

[Aaron Train [:aaronmt]]

Nope. Take a look at the *.IPS files, it might not be apparent that it's a crash, but they started collecting up when Firefox was in the background.

Firefox kept refreshing the pages when restored in the foreground.

Comment 8

[Stephan Leroux [:sleroux]]

From 'ortwin' on the dev forums here: https://forums.developer.apple.com/thread/54266

> No, I haven't found out yet. I suspect it's related to CoreSpotlight indexing but it's hard to analyze because the OS part of the backtrace isn't symbolicated.

CoreSpotlight could be one reason why we're deadlocking on a shared resources with Springboard. We use the CoreSpotlight framework to index open tabs so they show up in spotlight. 

Aaron, I've created a branch with the CoreSpotlight use commented out on a branch named sleroux/SpringboardCrashTest. Mind giving that a test? I was able to reproduce the crash once on my iPod but it seems you're able to reproduce it easier.

Comment 9

[Aaron Train [:aaronmt]]

This is a top-crash on 5.1

Comment 10

[Aaron Train [:aaronmt]]

Updated my iPhone 5 to iOS 10 Public Beta 6. Running Nightly off TestFlight for several hours, I have yet to hit a crash.

Comment 11

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

30e46eba14d917c4dcd7293b5b04360daaf94986 is the first bad commit
commit 30e46eba14d917c4dcd7293b5b04360daaf94986
Author: jhugman <[e-mail]>
Date:   Mon Jun 13 13:33:34 2016 +0100

    Bug 1277572 – Change new tab behaviour based on user setting (#1916)

    * Bug 1277572 – Don't show the home panels if new tab is either a blank or homepage.

    This would otherwise mean that there is zero difference between a blank page and the defaults.

    * Bug 1277572 – Detect that this is a new tab and load the correct URL into the tab.

    * Bug 1277572 – Remove concept of default homepage for opening new tabs.

    This replaces the notion of a single unified new tab page set at start up..

    * Bug 1277572 – Added defaults for China.

    Using literals, because I don't like copying PrefsDefaults and PrefsKeys around, and we can't have a dependency from Profile to Client.

    * Bug 1277572 – Update feature flags now there is real functionality available.

    * Bug 1277572 – Construct localhostURL from rawValue and remove other calculations of the URL.

    * Bug 1277572 – Moved string literals into existing PrefsKeys and PrefsDefaults.

:040000 040000 30ce148a13911a0416cd7fcb2ac834655a879759 0a9565f08b286472c759b66c712ce54c90333616 M	Client
:040000 040000 a7e4e027a1005d4533e6322d7144f59fc51f85ac b3023dc37f3a021fec56abeb9c3f3e0c057f0b7b M	ClientTests
:040000 040000 2745a3e85f51bbd686476d9045733fa6d804cb4f 1ad9279144f2751f65e7ad9fe28b0cd143fb1f62 M	Providers
:040000 040000 857e75a803531f141df24715f847fe9aab33442b 8b173f6ba2e8133538d82d98c21e32eff70f332d M	Utils

Comment 12

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

(In reply to Aaron Train [:aaronmt] from comment #10)
> Updated my iPhone 5 to iOS 10 Public Beta 6. Running Nightly off TestFlight
> for several hours, I have yet to hit a crash.

I can trigger a crash pretty easily:

* iPad Pro 9.7"
* iOS 10.0b7
* Running Fennec, master

Open the following tabs:

* New tab, search for "news"
* Facebook login screen
* What's New in Firefox for iOS
* http://abcnews.go.com/Politics/wireStory/gov-lepage-drug-dealers-arrested-black-hispanic-41644330
* http://www.cbsnews.com/news/ocearch-great-white-sharks-birthing-site-montauk-long-island-discovered-chris-fischer/

Open Firefox. Flip through all the tabs.

End on the last one about the white sharks.

Hit the home button to background the app.

When run in the Debugger, the app exists with: Message from debugger: Terminated due to signal 9

Comment 13

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Link to what git bisect thinks is the first bad commit:

https://github.com/mozilla/firefox-ios/commit/30e46eba14d917c4dcd7293b5b04360daaf94986

May or not be the case, but this is probably the best starting point we have now.

Comment 14

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Not convinced that git bisect is telling the truth :-(

Comment 15

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

I have narrowed this down to the LoginsHelper!

The crash consistently happens on https://m.facebook.com - Open that page (without logging in) as your only tab, hit the home button and boom. Terminated due to signal 9.

Commenting out the following code:

        // only add the logins helper if the tab is not a private browsing tab
        if !tab.isPrivate {
            let logins = LoginsHelper(tab: tab, profile: profile)
            tab.addHelper(logins, name: LoginsHelper.name())
        }

In BrowserViewController.tab(:didCreateWebView) makes the crash go away.

I did not setup sync, so I do not have any logins, as this confirms:

2016-08-25 23:33:57.625 [Debug] [LoginsHelper.swift:214] requestLogins(_:requestId:) > Found 0 logins.

Is it possible that on iOS 10 things are more strict, and we cannot leave any databases open?

Comment 16

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

This is what happens when I start the app with a clean profile and then go to https://m.facebook.com

2016-08-25 23:38:04.875 [Debug] [BrowserDB.swift:50] init(filename:secretKey:files:) > Initializing BrowserDB: logins.db.
2016-08-25 23:38:04.876 [Debug] [BrowserDB.swift:60] init(filename:secretKey:files:) > Creating db: /private/var/mobile/Containers/Shared/AppGroup/A03623BA-3FA4-45E7-A073-35BA75714C15/profile.profile/logins.db with secret = Optional("LkuHAsY2RwY5DoeNkhOJm3lgkaIzZ/5LgoK1sF9YB6jaR9vptY8aj4BDTDOXIx/uxYCz6nyFSkt1BE/rA36ch32KJnzNmIMYc4EgryxDi01EfprnYIUIiRYzeCw3bPFuhiRMYwKh1iCpNaQC2i2TqIhd0+QGc8VoWDuH4XzFQLkGopK8Wv+htZijH+6euf+EHYWex8o8zk/uvwkbknJpdnGSL68TyyYz5ThlV/pkqnONbv+cxrohXLbBBasBxjQEraHAyIoXY7fYrWyYy+1Q8MMGDOVIlcTOo3GDjsA/BvItRfq8kStD1iwcx8LYtnb9e2zJgyo0tzRXO19PgwomKg==")
2016-08-25 23:38:04.877 [Debug] [SwiftData.swift:83] getSharedConnection() > >>> Creating shared SQLiteDBConnection for /private/var/mobile/Containers/Shared/AppGroup/A03623BA-3FA4-45E7-A073-35BA75714C15/profile.profile/logins.db on thread <NSThread: 0x17406a380>{number = 1, name = main}.
2016-08-25 23:38:04.877 [Debug] [SwiftData.swift:480] init(filename:flags:key:prevKey:) > Opening connection to /private/var/mobile/Containers/Shared/AppGroup/A03623BA-3FA4-45E7-A073-35BA75714C15/profile.profile/logins.db.
2016-08-25 23:38:04.928 [Info] [SwiftData.swift:406] prepareEncrypted(_:key:prevKey:) > Enabling WAL mode.
2016-08-25 23:38:04.929 [Debug] [BrowserDB.swift:139] createOrUpdate > Create or update tableList version 1 on <NSThread: 0x17406a380>{number = 1, name = main}.
2016-08-25 23:38:04.929 [Debug] [BrowserDB.swift:83] updateTable(_:table:) > Trying update tableList version 1
2016-08-25 23:38:04.929 [Debug] [BrowserDB.swift:151] createOrUpdate > Table tableList already exists.
2016-08-25 23:38:04.930 [Debug] [BrowserDB.swift:139] createOrUpdate > Create or update LOGINS version 3 on <NSThread: 0x17406a380>{number = 1, name = main}.
2016-08-25 23:38:04.930 [Debug] [BrowserDB.swift:449] tablesExist > 2 tables exist. Expected 2
2016-08-25 23:38:04.930 [Debug] [BrowserDB.swift:83] updateTable(_:table:) > Trying update LOGINS version 3
2016-08-25 23:38:04.931 [Debug] [BrowserDB.swift:151] createOrUpdate > Table LOGINS already exists.
2016-08-25 23:38:04.934 [Debug] [LoginsHelper.swift:214] requestLogins(_:requestId:) > Found 0 logins.

Comment 17

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Reproducible on other login forms too. Like Google or Amazon. (If you test, be sure to reset the browser and not let the browser load any tabs with login forms from previous tests)

Comment 18

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

Fixed with the following patch:

diff --git a/Client/Application/AppDelegate.swift b/Client/Application/AppDelegate.swift
index 9f4d9a2..9bf6e68 100644
--- a/Client/Application/AppDelegate.swift
+++ b/Client/Application/AppDelegate.swift
@@ -359,6 +359,7 @@ class AppDelegate: UIResponder, UIApplicationDelegate {
     private func syncOnDidEnterBackground(application application: UIApplication) {
         // Short circuit and don't sync if we don't have a syncable account.
         guard self.profile?.hasSyncableAccount() ?? false else {
+            self.profile?.shutdown()
             return
         }

This is probably not complete or fully correct. But I think the problem is that we only call self.profile().shutdown() if sync is setup. If it is not setup then we do not shut down the profile, aka close the databases on suspend.

I did not follow the flow of applicationDidEnterBackground() very well. The shutdown() call may have to go in another place to make sure it always runs.

But this is probably a good hint!

Comment 19

[Stephan Leroux [:sleroux]]

Looks like this definitely could be problematic considering that shutdown is only called after the guard and in the applicationWillTerminate method. I think what we have is to remove the guard check altogether and allow the profile to be shutdown below in the beginBackgroundTaskWithExpirationHandler method since it could potentially take a while to shut down the database. I'll rewrite this method to make sure the profile gets shutdown all the time and does sync-y stuff if needed.

Comment 20

[Richard Newman [:rnewman]]

Happy to review if you want extra eyes.

Comment 21

[Stephan Leroux [:sleroux]]

Attachment: Link to Github pull-request: https://github.com/mozilla/firefox-ios/pull/2065#attch-to-bugzilla

Found another related issue in this code path! I've attached :st3fan's fix and another fix in the PR.

Comment 22

[Stephan Leroux [:sleroux]]

master: 2e126ad8285e3e5fbe1af1e1b3a1c94cbf8e9450

Comment 23

[Stephan Leroux [:sleroux]]

v5.x f5b3137

Comment 24

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

I'm seeing this crash when I am not logged in to Sync.

This is the crash log:

MOOMOO syncOnDidEnterBackground()
MOOMOO Shutting down profile
2016-09-21 16:15:25.384 [Debug] [Profile.swift:268] shutdown() > Shutting down profile.
2016-09-21 16:15:25.384 [Debug] [SwiftData.swift:504] deinit > deinit: closing connection on thread <NSThread: 0x17407ee40>{number = 1, name = main}.
2016-09-21 16:15:25.385 [Debug] [SwiftData.swift:571] closeCustomConnection(immediately:) > Closing custom connection for /private/var/mobile/Containers/Shared/AppGroup/0FA91D99-5271-47A8-9CFF-8BC2B0D05B69/profile.profile/browser.db on <NSThread: 0x17407ee40>{number = 1, name = main}.
2016-09-21 16:15:25.389 [Debug] [SwiftData.swift:591] closeCustomConnection(immediately:) > Closed /private/var/mobile/Containers/Shared/AppGroup/0FA91D99-5271-47A8-9CFF-8BC2B0D05B69/profile.profile/browser.db.
MOOMOO 555 Returning
MOOMOO 666 Returning
[INFO] GCDWebServer stopped
2016-09-21 16:15:25.416 [Debug] [Telemetry.swift:55] sendPing > Ping URL: Optional(https://incoming.telemetry.mozilla.org/submit/telemetry/5FDAD92A-01D7-445B-A6B4-CA26C38336A2/core/Fennec/6.0/default/1)
2016-09-21 16:15:25.446 [Debug] [Telemetry.swift:56] sendPing > Ping payload: {"locale":"en","osversion":"10.0.1","tz":-240,"durations":7,"device":"Apple-iPhone8,2","v":7,"profileDate":17065,"defaultSearch":"yahoo","seq":8,"os":"iOS","clientId":"06D37AF3-F611-4CAD-9EB4-84273E67FEAC","sessions":1,"created":"2016-09-21","arch":"arm"}
2016-09-21 16:15:25.477 [Debug] [Telemetry.swift:65] sendPing > Non-release build; not sending ping
2016-09-21 16:15:25.602 [Debug] [SwiftData.swift:83] getSharedConnection() > >>> Creating shared SQLiteDBConnection for /private/var/mobile/Containers/Shared/AppGroup/0FA91D99-5271-47A8-9CFF-8BC2B0D05B69/profile.profile/logins.db on thread <NSThread: 0x174471e80>{number = 9, name = (null)}.
2016-09-21 16:15:25.607 [Debug] [SwiftData.swift:480] init(filename:flags:key:prevKey:) > Opening connection to /private/var/mobile/Containers/Shared/AppGroup/0FA91D99-5271-47A8-9CFF-8BC2B0D05B69/profile.profile/logins.db.
Message from debugger: Terminated due to signal 9


And this is how I annotated my code:

    private func syncOnDidEnterBackground(application application: UIApplication) {
        print("MOOMOO syncOnDidEnterBackground()")
        guard let profile = self.profile else {
            print("MOOMOO 111 Returning")
            return
        }

        profile.syncManager.applicationDidEnterBackground()

        var taskId: UIBackgroundTaskIdentifier = 0
        taskId = application.beginBackgroundTaskWithExpirationHandler { _ in
            log.warning("Running out of background time, but we have a profile shutdown pending.")
            profile.shutdown()
            application.endBackgroundTask(taskId)
            print("MOOMOO 222 Returning")
        }

        if profile.hasSyncableAccount() {
            let backgroundQueue = dispatch_get_global_queue(DISPATCH_QUEUE_PRIORITY_BACKGROUND, 0)
            profile.syncManager.syncEverything().uponQueue(backgroundQueue) { _ in
                profile.shutdown()
                application.endBackgroundTask(taskId)
                print("MOOMOO 333 Returning")
            }
            print("MOOMOO 444 Returning")
        } else {
            print("MOOMOO Shutting down profile")
            profile.shutdown()
            application.endBackgroundTask(taskId)
            print("MOOMOO 555 Returning")
        }
        print("MOOMOO 666 Returning")
    }

(print statements because I dont think i can step through this in the debugger)

What this looks like is that we correctly go through the code path. But then *after* syncOnDidEnterBackground() finishes, something happens that causes the profile to be opened again.

Could this be Telemetry the code? Should the Telemetry code check if the app state is in shutdown state (does that exist on iOS) and then not open the profile?

Comment 25

[Stefan Arentz | :st3fan | ⏰ EST | he/him]

16:27:38 <st3fan> STR is the same, go to a login page, tap on one of the fields, background the app
16:28:08 <st3fan> the ping code does not always run, but when it does, it seems to crash

Comment 26

[Aaron Train [:aaronmt]]

Have we tried a build with telemetry disabled using the STR?

Comment 27

[Brian Nicholson (:bnicholson)]

Attachment: Link to Github pull-request: https://github.com/mozilla/firefox-ios/pull/2114

Fix part 2!

Comment 28

[Brian Nicholson (:bnicholson)]

master: https://github.com/mozilla/firefox-ios/commit/c3d742b80fe6af361cf9543271b9978c2d66730f
v5.x: db0236a3985c5dc8ed1f368cf567550a1a5e22d8