Grdb.swift: [logging] misuse at line 147939 of [2b0954060f] when opening a database on iOS 11

[gereons]

What did you do?

var config = Configuration()
config.readonly = true
let db = try DatabaseQueue(path: dbFile, configuration: config)

What did you expect to happen?

No log output

What happened instead?

Each time I run this on iOS 11, I get a log line like
2017-12-06 10:35:24.210182+0100 MyApp[33044:6574873] [logging] misuse at line 147939 of [2b0954060f]

Running the same code, using the exact same database file (it's generated offline and installed as part of the app bundle) on iOS 10 is silent, as expected.

This happens both on the Simulator and on real devices.

Environment

GRDB flavor(s): GRDB
GRDB version: 2.4.0
Installation method: CocoaPods
Xcode version: 9.1
Swift version: 4.0
Platform(s) running GRDB: iOS
macOS version running Xcode: 10.13

[groue]

Hello @gereons. I don't know who is logging this line, and what it means. Did you find any evidence that this line is the sign of an actual problem that needs fixing inside GRDB?

[gereons]

It's definitely from within SQLite or GRDB, in Database.setupGlobalErrorLog() where the Impl object is initialized.

So far I have found no indication that anything else is broken. Other mentions of this error (e.g. https://stackoverflow.com/questions/33239845/sqlite-error-sqlite-misuse-error-ios-add-table) indicate that it could be improper API usage that is now detected by the iOS 11 version of SQLite.

It may well be harmless and unavoidable, and that may warrant a mention in the README.

[groue]

It's definitely from within SQLite or GRDB, in Database.setupGlobalErrorLog() where the Impl object is initialized.

You say so. Were you able to use the debugger and trace the GRDB line that triggers the log? Which line is it? Share full information, please.

Other mentions of this error

I don't see how this stack overflow question is related to the[logging] misuse at line 147939 of [2b0954060f] line we're talking about : this SO question is about an SQLITE_MISUSE error that the user is getting. Since GRDB isn't supposed to swallow any SQLITE_MISUSE error, but instead throws all of them back to the host application, this question would be relevant to this issue if and only if your application were indeed catching a SQLITE_MISUSE error. This is not at all the situation described in this issue.

[groue]

It may well be harmless and unavoidable, and that may warrant a mention in the README.

I don't know. You tell me. Until further evidence, the problem could well lie in the app you're developing or in the embedded database.

[gereons]

Yes, I used the debugger to trace this to the assignment of static let setupErrorLog in Database.swift, line 190. Steps to repro: set a breakpoint on line 199 Impl.setupErrorLog. Click "Step into" two times to get the log output.

The SO answer I linked to has a comment that talks about needing to balance certain C API calls, which sounded reasonable to me re: what SQLite can check internally. I that's a red herring, I apologise.

[groue]

Yes, I used the debugger to trace this to the assignment of static let setupErrorLog in Database.swift, line 190. Steps to repro: set a breakpoint on line 199 Impl.setupErrorLog. Click "Step into" two times to get the log output.

I wasn't clear enough. Let my try again.

This line 199 is invoked because SQLite wants to log an error. But we don't care about this. What we care is the reason why SQLite wants to log an error. When your application stops on this breakpoint, somewhere above in the stack trace is that information. Would you mind sharing this stacktrace, please? Type bt in the debugger.

The SO answer I linked to has a comment that talks about needing to balance certain C API calls, which sounded reasonable to me re: what SQLite can check internally. I that's a red herring, I apologise.

I'm happy helping you sorting things out. Maybe we'll find something to change in your database. Maybe we'll find something to change in GRDB. Maybe we'll add some documentation that will help future users who see this error message deal with it. Maybe the conversation we're having now will be enough. I don't know yet. But you need to be very precise in the information you provide. You didn't tell that your app was catching any error, so I keep on assuming that no SQLITE_MISUSE is happening, and thus this SO question is irrelevant. If your app contains try? statements, or ignores database errors, please tell it because this is crucial information here.

[gereons]

Sure, here's the backtrace from when I hit that breakpoint. As far as I can tell, this is straight from the initial DatabaseQueue initializer.

````

• thread #1, queue = 'com.apple.main-thread', stop reason = breakpoint 4.1
  
  
  
  • frame #0: 0x000000011070247c GRDBstatic Database.setupGlobalErrorLog(self=GRDB.Database) at Database.swift:199 frame #1: 0x0000000110701c74 GRDBDatabase.init(path="/Users/gereon/Library/Developer/CoreSimulator/Devices/0BA34417-A733-4A1F-89FB-D7EA627BE728/data/Containers/Data/Application/A9CBCBB1-CD36-4F36-B09A-89D13CB12354/Library/Application Support/products.sqlite3", configuration=GRDB.Configuration @ 0x00007ffee1d4b338, schemaCache=0x000060000025fe00) at Database.swift:149
    
    frame #2: 0x000000011070151a GRDBDatabase.__allocating_init(path:configuration:schemaCache:) at Database.swift:0 frame #3: 0x000000011081013f GRDBSerializedDatabase.init(path="/Users/gereon/Library/Developer/CoreSimulator/Devices/0BA34417-A733-4A1F-89FB-D7EA627BE728/data/Containers/Data/Application/A9CBCBB1-CD36-4F36-B09A-89D13CB12354/Library/Application Support/products.sqlite3", configuration=GRDB.Configuration @ 0x00007ffee1d4b8c0, schemaCache=0x000060000025fe00) at SerializedDatabase.swift:40
    
    frame #4: 0x000000011080fbea GRDBSerializedDatabase.__allocating_init(path:configuration:schemaCache:) at SerializedDatabase.swift:0 frame #5: 0x000000011073e1ed GRDBDatabaseQueue.init(path="/Users/gereon/Library/Developer/CoreSimulator/Devices/0BA34417-A733-4A1F-89FB-D7EA627BE728/data/Containers/Data/Application/A9CBCBB1-CD36-4F36-B09A-89D13CB12354/Library/Application Support/products.sqlite3", configuration=GRDB.Configuration @ 0x00007ffee1d4bce8) at DatabaseQueue.swift:42
    
    frame #6: 0x000000011073dd6a GRDBDatabaseQueue.__allocating_init(path:configuration:) at DatabaseQueue.swift:0 frame #7: 0x000000010dff833f MyAppstatic ProductDB.openDb(self=MyApp.ProductDB) at ProductDB.swift:109
    
    frame #8: 0x000000010dff75d0 MyAppstatic ProductDB.setup(completion=0x000000010e09c940 MyApppartial apply forwarder for closure #1 (Swift.Bool) -> () in closure #1 () -> () in MyApp.AppDataManager.(in _3354353002F9C9076C07523727618186).init() -> MyApp.AppDataManager at AppDataManager.swift, self=MyApp.ProductDB) at ProductDB.swift:66
    
    frame #9: 0x000000010e09a618 MyAppclosure #1 in AppDataManager.init(self=0x00006000000ba3a0) at AppDataManager.swift:61 frame #10: 0x000000010e09c93c MyApppartial apply for closure #1 in AppDataManager.init() at AppDataManager.swift:0
    
    frame #11: 0x000000010e09afa0 MyAppclosure #1 in AppDataManager.load(data=some, isOffline=false, self=0x00006000000ba3a0, completion=0x000000010e09c930 MyApppartial apply forwarder for closure #1 () -> () in MyApp.AppDataManager.(in _3354353002F9C9076C07523727618186).init() -> MyApp.AppDataManager at AppDataManager.swift) at AppDataManager.swift:83
    
    frame #12: 0x000000010e09ca7b MyApppartial apply for closure #1 in AppDataManager.load(completion:) at AppDataManager.swift:0 frame #13: 0x000000010e049178 MyAppclosure #1 in NetworkManager.getIndexDocument(data=some, isOffline=false, completion=0x000000010e09ca00 MyApppartial apply forwarder for closure #1 (Swift.Optional<Foundation.Data>, Swift.Bool) -> () in MyApp.AppDataManager.(load in _3354353002F9C9076C07523727618186)(completion: () -> ()) -> () at AppDataManager.swift) at NetworkManager.swift:30 frame #14: 0x000000010e04923d MyApppartial apply for closure #1 in NetworkManager.getIndexDocument(_:) at NetworkManager.swift:0
    
    frame #15: 0x000000010e049c26 MyAppclosure #1 in NetworkManager.getData(response=Alamofire.DataResponse<Any> @ 0x00007ffee1d4cfa0, start=534256177.96815598, url="https://sellfio-staging.de/api/MyApp-ecb7bc/metadata/app/ios/1.0", completion=0x000000010e0491e0 MyApppartial apply forwarder for closure #1 (Swift.Optional, Swift.Bool) -> () in MyApp.NetworkManager.getIndexDocument((Swift.Optional, Swift.Bool) -> ()) -> () at NetworkManager.swift, self=0x000060000001ed20) at NetworkManager.swift:56
    
    frame #16: 0x000000010e050680 MyApppartial apply for closure #1 in NetworkManager.getData(_:completion:) at NetworkManager.swift:0 frame #17: 0x000000010ebc1839 Alamofireclosure #1 in closure #1 in DataRequest.response(completionHandler=0x000000010e0505e0 MyApppartial apply forwarder for closure #1 (Alamofire.DataResponse<Any>) -> () in MyApp.NetworkManager.getData(Swift.String, completion: (Swift.Optional<Foundation.Data>, Swift.Bool) -> ()) -> () at NetworkManager.swift, dataResponse=<unavailable>) at ResponseSerialization.swift:167 frame #18: 0x000000010ebca0ae Alamofirepartial apply for closure #1 in closure #1 in DataRequest.response(queue:responseSerializer:completionHandler:) at ResponseSerialization.swift:0
    
    frame #19: 0x000000010eb78829 Alamofirethunk for @callee_owned () -> () at DispatchQueue+Alamofire.swift:0 frame #20: 0x0000000116e263f7 libdispatch.dylib_dispatch_call_block_and_release + 12
    
    frame #21: 0x0000000116e2743c libdispatch.dylib_dispatch_client_callout + 8 frame #22: 0x0000000116e326f0 libdispatch.dylib_dispatch_main_queue_callback_4CF + 628
    
    frame #23: 0x0000000114f32ee9 CoreFoundation__CFRUNLOOP_IS_SERVICING_THE_MAIN_DISPATCH_QUEUE__ + 9 frame #24: 0x0000000114ef7592 CoreFoundation__CFRunLoopRun + 2402
    
    frame #25: 0x0000000114ef69b9 CoreFoundationCFRunLoopRunSpecific + 409 frame #26: 0x000000011aa1a9c6 GraphicsServicesGSEventRunModal + 62
    
    frame #27: 0x00000001117135e8 UIKitUIApplicationMain + 159 frame #28: 0x000000010e0ad277 MyAppmain at AppDelegate.swift:27
    
    frame #29: 0x0000000116ea3d81 libdyld.dylibstart + 1 frame #30: 0x0000000116ea3d81 libdyld.dylibstart + 1
    
    ````
  
  

My code surrounding this uses do {} catch using regular try, and the catch block isn't executed, I do get a valid DatabaseQueue back that I can then use to query the DB successfully.

// from class ProductDB static private func openDb() -> DatabaseQueue? { do { var config = Configuration() config.readonly = true return try DatabaseQueue(path: dbFile, configuration: config) } catch let error { print("db setup error \(error)") return nil } }

[groue]

OK @gereons, that's great, but not quite the stack trace I was expecting.

Don't put a break point on line 199. Put a breakpoint on line 195, and please paste again the bt stack trace

     // breakpoint here:
195: log(resultCode, message)

I'm happy to learn as a positive information that you don't catch any error. Next step is the new stack trace!

[gereons]

Weirdly, that breakpoint doesn't get hit.

I do still get that mysterious log output when single-stepping over the assignment to static let setupErrorLog, i.e. when I set a BP on line 190 and then "step into".

I traced this down a little further by setting a symbolic breakpoint on sqlite3_config. This gets hit twice really early in my app's startup, during the initialization of my NSURLCache, and the third call to it is from GRDB's registerErrorLogCallback. Single-stepping by instruction leads to a callq sqlite3MisuseError.

I'm going to try to reproduce this in a standalone new app, if that helps.

[gereons]

See https://github.com/gereons/GRDBTest

The problem seems to be related not only to iOS 11, but also to how many calls are made to sqlite3_config (and in which order) before GRDB gets to do its thing. In my real-world app, even removing the initialization of both my custom URLCache and Google Analytics wasn't enough to make the log output go away.

[groue]

@gereons, thanks a lot for this detailed enquiry 👍

The error log is global to SQLite. If several libraries attempt to set it, the version of SQLite that ships on iOS11 sees as many attempts at modifying it, and may well consider this practice as a misuse. That's my current interpretation, but I'm not sure yet.

We may well have to change GRDB so that it doesn't mess with sqlite3_config unless explicitly asked to do so.

Thanks a lot for opening this issue. Will you live with this warning until a fix is properly shipped?

[gereons]

Will you live with this warning until a fix is properly shipped?

Absolutely, no problem.

[groue]

Superseded by #284

[groue]

GRDB 2.4.1 has shipped, with the fix for this warning message.