Crash when observing virtual table?

[simme]

What did you do?

I have two tables, one that contains just the contents of a specific record type and another that is a FTS4 search index table of said the previously mentioned content.

Both tables have a corresponding type (struct conforming to TableRecord and FetchableRecord). The type that represents a row in the "regular" table defines a hasOne association with the search index type.

When performing a search in the app I create a QueryInterfaceRequest that among other things joins on the hasOne association which allows me to filter the request on matches in the index table.

It looks like this:

RecipePreview
            .joining(required: RecipePreview.index)
            .order(RecipePreview.Columns.name)
            .filter(filter.filter)
            .filter(tags: tags)
            .filter(query: query)

The query filter is just this extension on QueryInterfaceRequest:

    func filter(query: String?) -> QueryInterfaceRequest {
        guard let query = query?.trimmingCharacters(in: .whitespacesAndNewlines), !query.isEmpty else {
            return self
        }
        return self.filter(sql: "recipeSearchIndex.corpus MATCH ?", arguments: ["*\(query)*"])
    }

What did you expect to happen?

In most cases this works great and allows me to use a UISearchController to populate a collection view with the search results. However, I also observe this request because these items can be "favorited", among other things, which changes the display of the item in the list.

What happened instead?

Whenever a search is performed while the search index is update I get a fatalError on line 201 of DatabaseRegion.swift stating:

precondition failure: event was not filtered out in observes(eventsOfKind:) by region.isModified(byEventsOfKind:)

Environment

GRDB flavor(s): GRDB
GRDB version: 4.2.1
Installation method: Manual (git submodule)
Xcode version: 11
Swift version: 5.1
Platform(s) running GRDB: iOS
macOS version running Xcode: 10.15 beta.. 8?

---

I realise this probably has something to do with the virtual table. I guess my main questions is: is this a bug or intended behaviour? And can it be worked around somehow?

Thanks

[simme]

Had the time to dig into this and do some further debugging. It definitely has to do with my search index table.

The event.tableName variable points to a *_content table, which is not present in the tableRegions dictionary. Which I assume then mean that when the request is turned into an observation does not correctly (?) include the associated index tables in its observation. Now, I guess there might be limited use in observing these tables. Although I guess it could be argued that that would make it possible to update a list of search result if the index is updated in the background?

The observation is created like this — using the request in the first post:

let observation = RecipePreview
            .searchRequest(filter: filter, query: query, tags: tags)
            .observationForAll()

I realize all of this could probably be worked around by creating a custom TransactionObserver implementation that either includes or discards changes to these tables — rather than crashing. I just thought it might be interesting to bring it here to make sure it's intended behaviour. :)

[groue]

Hello @simme,

Thanks for the investigation. It looks like observation and FTS4 virtual tables don't play well together. Is your FTS table an External Content Full-Text Table which mirrors and indexes the content of another non-FTS table?

[simme]

This is how I create the table:

func createRecipeSearchIndex(in db: Database) throws {
    try db.create(virtualTable: "recipeSearchIndex", using: FTS4()) { table in
        table.tokenizer = .porter
        table.column("stringIdentifier").notIndexed()
        table.column("corpus")
    }
}

[simme]

It is not automatically synchronized

[groue]

It is not automatically synchronized

OK. So we can not observe the source regular table instead.

To know if we can observe your full text table, could you run a raw TransactionObserver and log all calls to databaseDidChange(with:) and observes(eventsOfKind:) methods when you modify the index (insert, update, delete)?

[simme]

Alright, so with a custom observer looking like this:

private class MyObserver: TransactionObserver {
    func observes(eventsOfKind eventKind: DatabaseEventKind) -> Bool {
        print("Observes event of kind: \(eventKind)")
        return true
    }

    func databaseDidChange(with event: DatabaseEvent) {
        print("Did change with event of kind \"\(event.kind)\" in table \"\(event.tableName)\"")
    }

    func databaseDidCommit(_ db: Database) { }

    func databaseDidRollback(_ db: Database) { }
}

I am getting this output:

Observes event of kind: delete(tableName: "recipeSearchIndex")
Did change with event of kind "delete" in table "recipeSearchIndex_content"
Did change with event of kind "delete" in table "recipeSearchIndex_docsize"
Did change with event of kind "insert" in table "recipeSearchIndex_stat"
Observes event of kind: insert(tableName: "recipeSearchIndex")
Did change with event of kind "insert" in table "recipeSearchIndex_content"
Did change with event of kind "insert" in table "recipeSearchIndex_docsize"
Did change with event of kind "insert" in table "recipeSearchIndex_stat"

When someone changes the language in the app for example I wipe the old index and insert a new one. (Looking at it like this I should probably do a delete all instead of individually when refreshing, but irrelevant to the issue at hand :) )

[simme]

I've been snooping around, and if I break on line 172 in DatabaseRegion.swift, which is this:

public func isModified(byEventsOfKind eventKind: DatabaseEventKind) -> Bool {
        return intersection(eventKind.modifiedRegion).isEmpty == false
    }

That method in this case returns false. Yet the code continues to notify the observer of the event. Maybe I'm missing something.

[groue]

I am getting this output:

Observes event of kind: delete(tableName: "recipeSearchIndex")
Did change with event of kind "delete" in table "recipeSearchIndex_content"
Did change with event of kind "delete" in table "recipeSearchIndex_docsize"
Did change with event of kind "insert" in table "recipeSearchIndex_stat"
Observes event of kind: insert(tableName: "recipeSearchIndex")
Did change with event of kind "insert" in table "recipeSearchIndex_content"
Did change with event of kind "insert" in table "recipeSearchIndex_docsize"
Did change with event of kind "insert" in table "recipeSearchIndex_stat"

OK, those are all FTS4 "shadow tables". We have to read the raw doc in order to know if we can rely on them in order to observe the index.

isModified(byEventsOfKind:) in this case returns false

For all events? DatabaseRegion has a description or debugDescription property which outputs it in a readable way. What does it give?

[groue]

@simme, I'm sorry to "give you work". I can investigate this myself: it's not hard to create an FTS4 index and reproduce your issue. I admit I appreciate that you are looking for the exact point of failure, because not everybody is interested in how observation works :-)

[simme]

No worries! I'm not expecting any full service support here. I'm using GRDB and deriving great benefit from it, so of course I want to help as much as possible! And it's a core part of my app so trying to understand how it works feels like a given :) Some help in the right direction would be much appreciated though ;)

We have to read the raw doc in order to know if we can rely on them in order to observe the index.

In my case right now I don't even need to observe the index, really. But it wouldn't hurt. And might be what one expects.

For all events? DatabaseRegion has a description or debugDescription property which outputs it in a readable way. What does it give?

Where should I print the debugDescription?

[simme]

This is the output of po self in DatabaseRegion.isModified(byEventsOfKind:):

▿ recipePreview(categoryIdentifier,cookingTime,id,image,intro,isFavorite,isLocked,mealType,name,sourceIdentifier,stringIdentifier,tags)
  ▿ tableRegions : Optional<Dictionary<String, TableRegion>>
    ▿ some : 1 element
      ▿ 0 : 2 elements
        - key : "recipePreview"
        ▿ value : TableRegion
          ▿ columns : Optional<Set<String>>
            ▿ some : 12 elements
              - 0 : "cookingTime"
              - 1 : "isFavorite"
              - 2 : "image"
              - 3 : "isLocked"
              - 4 : "id"
              - 5 : "tags"
              - 6 : "name"
              - 7 : "categoryIdentifier"
              - 8 : "intro"
              - 9 : "sourceIdentifier"
              - 10 : "mealType"
              - 11 : "stringIdentifier"
          - rowIds : nil

And this is eventKind.modifiedRegion:

▿ recipeSearchIndex(*)
  ▿ tableRegions : Optional<Dictionary<String, TableRegion>>
    ▿ some : 1 element
      ▿ 0 : 2 elements
        - key : "recipeSearchIndex"
        ▿ value : TableRegion
          - columns : nil
          - rowIds : nil

[simme]

I'm sorry, the above might've been misleading information.

That method is called again later by another event in which self also contains the modified region and there is an actual intersection. So the observer is added to the statementObservations array in DatabaseObservationBroker.updateStatementWillExecute. However, the event that is then passed on to observation.databaseDidChange(with: event) is then for one of the shadow tables, which is not present in the observed region's list of tables, and hence the fatal error is triggered.

Not sure yet how this connects :P But it seems as though an update to one of the shadow tables are reported as an update to the virtual table, which is observed.

[groue]

@simme, I'll have a look shortly.

[simme]

Could it be that all of the code is working as expected, but when one does an insert in a FTS4 table SQLite also performs another insert into one of these shadow tables as part of the "main" insert, which then triggers the hook that tells GRDB that the change happened. But it's actually another change than what the DatabaseObservationBroker expected so it's internal list of statementObservations is not correct for that event?

[simme]

Don't mean to impose stress because of my spamming. Just posting my findings while debugging in hopes of rubber ducking to make myself understand what's going on and helping you help me :D

[groue]

Could it be that all of the code is working as expected, but when one does an insert in a FTS4 table SQLite also performs another insert into one of these shadow tables as part of the "main" insert, which then triggers the hook that tells GRDB that the change happened. But it's actually another change than what the DatabaseObservationBroker expected so it's internal list of statementObservations is not correct for that event?

It's exactly that.

For simplicity, let's remove all the useless parameters that hide what's happening, and just reduce the problem to an SQL request which joins one regular table and an FTS4 table:

try dbQueue.write { db in
    try db.create(table: "document") { t in
        t.autoIncrementedPrimaryKey("id")
    }
    
    try db.create(virtualTable: "ft_document", using: FTS4()) { t in
        t.column("content")
    }
}

let request = SQLRequest<Row>("""
    SELECT document.* FROM document
    JOIN ft_document ON ft_document.rowid = document.id
    WHERE ft_document MATCH 'foo'
    """)

When asked what this request looks at, SQLite says: the document table, and the ft_document table. This is the database region of the request:

// prints "document(*),ft_document(ROWID,ft_document)"
try dbQueue.read { db in
    try print(request.databaseRegion(db))
}

This region is observed: if it is impacted, the observation will refresh its value. Other database modifications that happen elsewhere will be ignored.

Now let's run this statement:

try dbQueue.write { db in
    try db.execute(
        sql: "INSERT INTO ft_document (rowid, content) VALUES (?, ?)", 
        arguments: [1, "foo"])

When asked what this statement is about to do, SQLite says that it will insert into the ft_document table (this can't be seen with public apis). The statement has not been executed yet.

The observation becomes active, because this insertion can impact its observed region. Its transaction observer waits eagerly for actual changes that may impact its region.

And there lies the crash: the modifications were advertised to happen on the ft_document, and the actually notified changes happen on ft_document_content and other FTS4 shadow tables. This is currently interpreted by GRDB as a misuse (hence the fatal error), because the observation has no way to know if changes to ft_document_content actually impacts its region or not. This is the reason for this precondition.

---

We have a few options:

1. Handle FTS4 shadow tables specifically.

2. Remove the precondition fatal error, and assume that all unexpected changes, just in doubt, do impact the observed region. This would fix your problem. This would not break existing apps, because removing a fatal error never breaks any app. The negative impact is that we miss an opportunity to warn (crash) on misuses.

Options 1 is complex, and makes it less easy to maintain GRDB on the long run. What about FTS3, FTS5, other virtual tables?

So option 2 is probably the correct one.

[groue]

So option 2 is probably the correct one.

It is not quite the end of the story 😁 Observing an External Content Full-Text Table fails to spot changes performed on the source regular table.

[simme]

Nice find!

I've read your tests and looked at the fix. But I fail to come up with anything but naïve workarounds.. :P

[groue]

Fixed! I'm closing this issue in favor of #622.

[groue]

(As always, thanks @simme for your contributions)