SharkORM fetch crashing on background fetch

[MeteC]

Hi Adrian et al.,

I've been trying for a long time to track down a crash I've only been seeing sporadically via Crashlytics, but I've managed to start replicating it myself, and I wonder if you've any knowledge on the matter.

Specifically, I'm seeing EXC_BAD_ACCESS during a call to sqlite3_step in the stack after calling SharkORM fetches during an iOS background fetch (my UIApplicationDelegate::performFetchWithCompletionHandler calls a SharkORM fetch to see what's in the DB). I'll paste in the thread stack below.

I couldn't replicate this without waiting some minutes - that is, running my app and then using Xcode's "Simulate Background Fetch" caused no problems at all the first few times I did it. Then 5-10 mins later I tried again (without having touched the phone at all meanwhile) and I could replicate the crash. So it seems the app and phone needs to be quite deeply backgrounded - I've never known sqlite to fail like this before..

Any help or clues would be much appreciated! It's a nasty bug because it can take so much time to replicate each time...

Stack trace:
(note line numbers for SharkORM.m will be a bit higher than they would be in the official version, as I hacked some extra calls into openDatabaseNamed for debugging.)

* thread #1, queue = 'com.apple.main-thread', stop reason = EXC_BAD_ACCESS (code=10, address=0x111f80000)
    frame #0: 0x00000001bf151a08 libsystem_platform.dylib`_platform_memmove + 280
  * frame #1: 0x0000000110b4d038 SharkORM`walIndexTryHdr(pWal=0x0000000111814860, pChanged=0x000000016d5079b0) at sqlite3.c:59300:3
    frame #2: 0x0000000110b4c960 SharkORM`walIndexReadHdr(pWal=0x0000000111814860, pChanged=0x000000016d5079b0) at sqlite3.c:59385:21
    frame #3: 0x0000000110b4c4a0 SharkORM`walTryBeginRead(pWal=0x0000000111814860, pChanged=0x000000016d5079b0, useWal=0, cnt=1) at sqlite3.c:59703:12
    frame #4: 0x0000000110b568c8 SharkORM`sqlite3WalBeginReadTransaction(pWal=0x0000000111814860, pChanged=0x000000016d5079b0) at sqlite3.c:59974:10
    frame #5: 0x0000000110b5672c SharkORM`pagerBeginReadTransaction(pPager=0x0000000112850000) at sqlite3.c:52822:8
    frame #6: 0x0000000110b561b8 SharkORM`sqlite3PagerSharedLock(pPager=0x0000000112850000) at sqlite3.c:54916:10
    frame #7: 0x0000000110b556d8 SharkORM`lockBtree(pBt=0x0000000280efe0a0) at sqlite3.c:65050:8
    frame #8: 0x0000000110b2ea1c SharkORM`sqlite3BtreeBeginTrans(p=0x0000000281fe6490, wrflag=0) at sqlite3.c:65418:47
    frame #9: 0x0000000110b6430c SharkORM`sqlite3VdbeExec(p=0x00000001118123f0) at sqlite3.c:85158:10
    frame #10: 0x0000000110b32344 SharkORM`sqlite3Step(p=0x00000001118123f0) at sqlite3.c:80320:10
    frame #11: 0x0000000110b32010 SharkORM`sqlite3_step(pStmt=0x00000001118123f0) at sqlite3.c:80383:16
    frame #12: 0x0000000110b1a66c SharkORM`-[SharkORM performQuery:rowBlock:](self=0x0000000283eb02e0, _cmd="performQuery:rowBlock:", query=0x0000000281295b80, rowBlock=0x0000000110b1b20c) at SharkORM.m:1391:22
    frame #13: 0x0000000110b1b1d4 SharkORM`-[SharkORM fetchEntitySetForQuery:](self=0x0000000283eb02e0, _cmd="fetchEntitySetForQuery:", query=0x0000000281295b80) at SharkORM.m:1487:12
    frame #14: 0x0000000110c1b294 SharkORM`-[SRKQuery fetch](self=0x0000000281295b80, _cmd="fetch") at SRKQuery.m:494:22
    frame #15: 0x0000000102a0b034 MyApp`+[Roi fetchUnsent](self=0x0000000103adf7d0, _cmd="fetchUnsent") at Roi.m:37:12
    frame #16: 0x0000000102dd8d6c MyApp`ROIBackgroundPollManager.start(self=0x00000002829b6180) at ROIBackgroundPollManager.swift:65:36
    frame #17: 0x0000000102c4c6cc MyApp`ACAppDelegate.doBackgroundROIPoll(date=Foundation.Date @ 0x000000016d5097d0, completionHandler=0x0000000102c5f674 UAV-ASIGN`partial apply forwarder for reabstraction thunk helper from @escaping @callee_unowned @convention(block) (@unowned __C.UIBackgroundFetchResult) -> () to @escaping @callee_guaranteed (@unowned __C.UIBackgroundFetchResult) -> () at <compiler-generated>, self=0x0000000280df4c80) at ACAppDelegate.swift:924:18
    frame #18: 0x0000000102c4c4ec MyApp`ACAppDelegate.application(application=0x0000000111906ca0, completionHandler=0x0000000102c5f674 MyApp`partial apply forwarder for reabstraction thunk helper from @escaping @callee_unowned @convention(block) (@unowned __C.UIBackgroundFetchResult) -> () to @escaping @callee_guaranteed (@unowned __C.UIBackgroundFetchResult) -> () at <compiler-generated>, self=0x0000000280df4c80) at ACAppDelegate.swift:229:14
    frame #19: 0x0000000102c4c790 MyApp`@objc ACAppDelegate.application(_:performFetchWithCompletionHandler:) at <compiler-generated>:0
    frame #20: 0x00000001c3510af0 UIKitCore`-[UIApplication _handleNonLaunchSpecificActions:forScene:withTransitionContext:completion:] + 2084

[editfmah]

Hi @MeteC, that is a spicy one. Thank you for the time you've taken to try and track this down. We also see that with one of our major projects. We had it cornered at one point where we felt it was to do with background encryption, but we were unable to work anything out beyond that. At one point we felt it could be a free'd SQlite3 pointer, but lots of the preceding calls check validity of the main handle and stmt structs.

As it crashes deeply within SQLite and not at the surface, I wonder if it's SharkORM doing something flaky and actually that might have been fixed by SQLite in the last 2 years since it was upgraded. We could try updating to a later maintenance release of SQLite and see if that solves the issue as a very quick attempt at a fix.

Casually looking at where is went wrong however, deep in the WAL, makes me feel like it's iOS locking that file for some reason and it having a valid handle to the log, but being unable to read from it.

[editfmah]

To test my last theory, you could set the log mode to none (or equivalent), and see if that stops the issue.

[MeteC]

Ah right! Well thanks Adrian, it's nice to know I'm not alone at least. 😆 Spicy indeed.

Ok will try the log mode change - to be specific do you mean I might change SharkORMs SRKSettings.sqliteJournalingMode?

(As seen in the line
sqlite3_exec(dbHandle, [NSString stringWithFormat:@"PRAGMA journal_mode=%@; PRAGMA default_cache_size = 200; PRAGMA cache_size = 200;", [[SRKGlobals sharedObject] settings].sqliteJournalingMode].UTF8String, 0, 0, 0);
in the openDatabaseNamed: method)

[editfmah]

So, i'd go for DELETE.

The DELETE journaling mode is the normal behavior. In the DELETE mode, the rollback journal is deleted at the conclusion of each transaction. Indeed, the delete operation is the action that causes the transaction to commit. (See the document titled Atomic Commit In SQLite for additional detail.)

As SQLite will open the file each time, so won't get unpicked by something holding onto the file.

[MeteC]

Thought that might be the way to go, thanks!

So after a cursory test with DELETE mode I'm not seeing any crashes - I'll install on all previously offending devices and monitor Crashlytics over the course of the week to see results. I'll report back!

[MeteC]

FYI No further issues all week, it's looking good for DELETE mode!
Presumably WAL is more optimised than delete mode? But a crash free app is obviously preferable... ;-)

[editfmah]

Yes it is, however. I was thinking of adding in a suspend call. Which could change the mode to delete and roll the log into the sqlite3 file. Then on app resume, it could switch back to WAL for performance. That way you gain stability and file security and keep performance as well.