Grdb.swift: Question: Snapshot cursor iteration fails

[Kirow]

What did you do?

I've made playground to check snapshot cursor iteration while editing database and got issue I can not explain or understand. It could be SQLite limitation or GRDB issue.

playground setup:

import GRDB
import PlaygroundSupport

let url = playgroundSharedDataDirectory.appendingPathComponent("GRDB")
try! FileManager.default.createDirectory(at: url, withIntermediateDirectories: true)
try? FileManager.default.removeItem(at: url.appendingPathComponent("database.sqlite-wal"))
try? FileManager.default.removeItem(at: url.appendingPathComponent("database.sqlite-shm"))
try? FileManager.default.removeItem(at: url.appendingPathComponent("database.sqlite"))
let databasePath = url.appendingPathComponent("database.sqlite").path

database models:

public struct User: Codable, TableRecord, FetchableRecord, MutablePersistableRecord {
    public static let databaseTableName: String = "user"

    public var id: Int64?
    public var username: String
    public var isFlagged: Bool

    init(id: Int64? = nil, username: String, isFlagged: Bool = false) {
        self.id = id
        self.username = username
        self.isFlagged = isFlagged
    }

    public mutating func didInsert(with rowID: Int64, for column: String?) {
        id = rowID
    }
}

public struct FlagUser: Codable, TableRecord, FetchableRecord, MutablePersistableRecord {
    public static let databaseTableName: String = "flagUser"

    public var username: String
}

GRDB setup:

var configuration = Configuration()
configuration.trace = { print($0) }

var migrator = DatabaseMigrator()

migrator.registerMigration("initial") { database in
    try database.create(table: User.databaseTableName) { definition in
        definition.column("id", .integer).primaryKey(autoincrement: true)
        definition.column("username", .text).notNull()
        definition.column("isFlagged", .boolean).notNull().defaults(to: false)
    }

    try database.create(table: FlagUser.databaseTableName) { definition in
        definition.column("username", .text).notNull()
    }
}

migrator.registerMigration("data") { database in
    [Int](0...50).forEach {
        var user = User(username: "User\($0)")
        try! user.insert(database)
    }

    [Int](40...60).forEach {
        var flag = FlagUser(username: "User\($0)")
        try! flag.insert(database)
    }
}

let pool = try! DatabasePool(path: databasePath, configuration: configuration)
try migrator.migrate(pool)

Exception code:

let query = "SELECT * FROM flagUser WHERE (SELECT COUNT(id) FROM user WHERE username = flagUser.username AND isFlagged = true) = 0"
let snapshot = try! pool.makeSnapshot()

try! snapshot.read { snapshotDatabase in
    let cursor = try FlagUser.fetchCursor(snapshotDatabase, sql: query)
    //try pool.write { database in
        while let flagged = try cursor.next() {
            //fails on next `cursor.next()` if `fetchOne(snapshotDatabase`. works if `fetchOne(database`.
            var user = try User.fetchOne(snapshotDatabase, sql: "SELECT * FROM user WHERE username = '\(flagged.username)' LIMIT 1") ??
                User(username: flagged.username)
        }
    //}
}

If I execute User.fetchOne(snapshotDatabase I will get exception on next cursor.next() (it doesn't matter if something found or not).
But if I will use try User.fetchOne(database or if I remove WHERE (SELECT COUNT(id) FROM user WHERE username = flagUser.username AND isFlagged = true) = 0 from query it will work w/o exception.

What did you expect to happen?

Expected it to work

What happened instead?

Got exception. SQLite error 4: abort due to ROLLBACK. If I run it in debug with breakpoints I can also see BUG IN CLIENT OF libsqlite3.dylib: database integrity compromised by API violation: vnode unlinked while in use

Environment

GRDB flavor(s): GRDB
GRDB version: 4.1.1 (master branch)
Installation method: manual, playground
Xcode version: 10.3
Swift version: 4.2
Platform(s) running GRDB: macOS
macOS version running Xcode: 10.14.6

Demo Project

https://gist.github.com/Kirow/4d5342bb01d8d34f5e5b2259700dc227

[groue]

Hi @Kirow,

Thank you for the detailed bug report, especially the reproducing gist 👍

Got exception. SQLite error 4: abort due to ROLLBACK. If I run it in debug with breakpoints I can also see BUG IN CLIENT OF libsqlite3.dylib: database integrity compromised by API violation: vnode unlinked while in use

The BUG IN CLIENT OF libsqlite3.dylib part is interesting. I usually only see this kind of log when the app messes with the file system and pulls the carpet from under the feet of SQLite. This does not quite explain the SQLite error 4: abort due to ROLLBACK, which I have never seen. Yet this has my eyes look suspiciously at playgroundSharedDataDirectory 👀.

It can be interesting to see if the bug is still present when the database pool is saved at another location on the file system, or when the pool is replaced with an in-memory DatabaseQueue.

Anyway - I'll look at this bug shortly. If it reveals an issue in GRDB, it will be fixed.

[Kirow]

@groue
Same issue during iOS Unit Tests (in my project), so I think it is not related to playgroundSharedDataDirectory
reproduced with in-memory DatabaseQueue - https://gist.github.com/Kirow/4d5342bb01d8d34f5e5b2259700dc227#file-sample2-swift

[groue]

Ha, it looks like you have found a real bug, then. I love that :)

[groue]

I can reproduce 👍

Now investigation can start.

[groue]

SQLite throws an error 516 SQLITE_ABORT_ROLLBACK:

The SQLITE_ABORT_ROLLBACK error code is an extended error code for SQLITE_ABORT indicating that an SQL statement aborted because the transaction that was active when the SQL statement first started was rolled back. Pending write operations always fail with this error when a rollback occurs. A ROLLBACK will cause a pending read operation to fail only if the schema was changed within the transaction being rolled back.

It is a variant of error 4 SQLITE_ABORT:

The SQLITE_ABORT result code indicates that an operation was aborted prior to completion, usually be application request. See also: SQLITE_INTERRUPT.

If the callback function to sqlite3_exec() returns non-zero, then sqlite3_exec() will return SQLITE_ABORT.

If a ROLLBACK operation occurs on the same database connection as a pending read or write, then the pending read or write may fail with an SQLITE_ABORT or SQLITE_ABORT_ROLLBACK error.

In addition to being a result code, the SQLITE_ABORT value is also used as a conflict resolution mode returned from the sqlite3_vtab_on_conflict() interface.

A close inspection of all sqlite3 apis called during the iteration of our cursors does not reveal anything related to the documented conditions for this error.

The same error happens with previous versions of SQLite: if this is a regression, it is an old one.

I'll have to keep on investigating, and maybe request assistance from the SQLite mailing list.

This means that the fix may take some time to come. Do you have a workaround, @Kirow? Something like iterating an array instead of a cursor?

[groue]

I have attempted to reduce your sample code into the simplest C SQLite3 api calls:

Reduced code

try queue.write { database in
    sqlite3_exec(database.sqliteConnection, """
        CREATE TABLE user (
            id INTEGER PRIMARY KEY AUTOINCREMENT,
            username TEXT NOT NULL,
            isFlagged BOOLEAN NOT NULL DEFAULT 0
        );
        CREATE TABLE flagUser (
            username TEXT NOT NULL
        );
        """, nil, nil, nil)

    [Int](0...50).forEach {
        sqlite3_exec(database.sqliteConnection, """
            INSERT INTO user (username) VALUES ('User\($0)')
            """, nil, nil, nil)
    }

    [Int](40...60).forEach {
        sqlite3_exec(database.sqliteConnection, """
            INSERT INTO flagUser (username) VALUES ('User\($0)')
            """, nil, nil, nil)
    }

    var statement1: SQLiteStatement? = nil
    var code = sqlite3_prepare_v3(database.sqliteConnection, """
        SELECT * FROM flagUser WHERE (SELECT COUNT(id) FROM user WHERE username = flagUser.username AND isFlagged = true) = 0
        """, -1, 0, &statement1, nil)
    while true {
        code = sqlite3_step(statement1)
        if code == SQLITE_DONE {
            break
        } else if code == SQLITE_ROW {
            let flaggedUsername =  String(cString: sqlite3_column_text(statement1, 0)!)
            var statement2: SQLiteStatement? = nil
            var code = sqlite3_prepare_v3(database.sqliteConnection, """
                SELECT * FROM user WHERE username = '\(flaggedUsername)' LIMIT 1
                """, -1, 0, &statement2, nil)
            code = sqlite3_step(statement2)
            if code == SQLITE_DONE {
                print("Not found: \(flaggedUsername)")
            } else if code == SQLITE_ROW {
                print("Found: \(flaggedUsername)")
            } else {
                XCTFail("Error \(code)")
            }
            sqlite3_finalize(statement2)
        } else {
            XCTFail("Error \(code)")
            break
        }
    }
    sqlite3_finalize(statement1)
}

In this case, the bug does not happen.

[groue]

I managed to reproduce the bug with C apis. It is an SQLite bug:

var connection: SQLiteConnection? = nil
sqlite3_open_v2(":memory:", &connection, SQLITE_OPEN_READWRITE | SQLITE_OPEN_NOMUTEX, nil)
sqlite3_extended_result_codes(connection, 1)

sqlite3_exec(connection, """
    CREATE TABLE user (username TEXT NOT NULL);
    CREATE TABLE flagUser (username TEXT NOT NULL);
    INSERT INTO flagUser (username) VALUES ('User1');
    INSERT INTO flagUser (username) VALUES ('User2');
    """, nil, nil, nil)

var statement: SQLiteStatement? = nil
sqlite3_set_authorizer(connection, { (_, _, _, _, _, _) in SQLITE_OK }, nil)
sqlite3_prepare_v3(connection, """
    SELECT * FROM flagUser WHERE (SELECT COUNT(*) FROM user WHERE username = flagUser.username) = 0
    """, -1, 0, &statement, nil)
sqlite3_set_authorizer(connection, nil, nil)
while true {
    let code = sqlite3_step(statement)
    if code == SQLITE_DONE {
        break
    } else if code == SQLITE_ROW {
        // part of the compilation of another statement, here
        // reduced to the strict minimum that reproduces
        // the error.
        sqlite3_set_authorizer(connection, nil, nil)
    } else {
        // On second step, error 516 "abort due to ROLLBACK"
        print(String(cString: sqlite3_errmsg(connection)))
        XCTFail("Error \(code)")
        break
    }
}
sqlite3_finalize(statement)
sqlite3_close_v2(connection)

Parallel iteration of several cursors generally is OK, in both SQLite and GRDB.

But this query is special: SELECT * FROM flagUser WHERE (SELECT COUNT(*) FROM user WHERE username = flagUser.username) = 0. Other queries don't suffer.

It is derailed by the sqlite3_set_authorizer method which GRDB uses as support for its database observation techniques.

So this is definitely an SQLite bug.

[groue]

Good news: there is a GRDB workaround - avoiding calling sqlite3_set_authorizer when observation is not needed.

[groue]

Good news

Oops, not quite. This is not manageable without a breaking change:

 final class SelectStatement: Statement {
-    var databaseRegion: DatabaseRegion { get }
 }

I'm afraid we'll have to wait for GRDB 5. I'll prepare a branch anyway.

[groue]

I'm closing this issue in favor of #585.

@Kirow, I'd rather not merge it into master now, because of the breaking change. Please express your concern if the fix is critical for your application.

[Kirow]

@groue Not a problem for me. I don't have such case in dev project. I've found it during tests in playground.

Thanks.

[groue]

Cool. Thanks for reporting the issue anyway. It has revealed a weakness that deserves a fix, eventually. Please keep on chiming in here if you notice anything else that looks weird to you!

[groue]

585 has fixed the issue without introducing any breaking change. Scheduled for GRDB 4.2!