search

vapor / fluent-sqlite-driver

Fluent driver for SQLite
MIT License
68 stars 24 forks source link

nil field does not save #89

Closed hyouuu closed 6 months ago

hyouuu commented 9 months ago

Describe the bug

On iOS, I have an entity with an optional editingBy: UUID? field, and once a UUID is assigned to it and saved, then subsequent operations to reset it to nil and save would succeed without exception, but the stored entity still have the previously set value.

To make sure it's the actual cause, I tried set it to a specific UUID before saving if editingBy == nil, and that specific UUID is saved correctly.

Expected behavior

Saved entity would have the field set to nil upon saving.

Environment

0xTim commented 9 months ago

Can you show your model code, code around the update and the DB logs for the query being sent

hyouuu commented 9 months ago

Model:

import Foundation
import FluentSQLiteDriver

final class Note: Model, ReqContent {
    static let schema = "notes"

    // (Quoted from Discord) Fluent's Model and Swift's Identifiable protocol are not compatible unfortunately.
    // and ID is ambiguous because it is both an associatedtype on Identifiable and a property wrapper
    @ID(key: .id)
    var id: UUID?

    // MARK: Date

    // Client app shouldn't touch these fields when saving to local db

    @OptionalField(key: "createdAt")
    var createdAt: Date?
    @OptionalField(key: "updatedAt")
    var updatedAt: Date?
    @OptionalField(key: "deletedAt")
    var deletedAt: Date?

    @OptionalField(key: "editingBy")
    var editingBy: UUID?
hyouuu commented 9 months ago

Code around the update

func doSave(note: Note, isEditing: Bool) {        
        var note = await postNote(note, isUpdate: true)

         note = try await Req.editNote(
                 note.id,
                 userId: curUserId,
                 isEditing: isEditing
           )

           try await self.onNoteUpdated(note)
    }

    func onNoteUpdated(_ note: Note) async throws {
        pr("before save:\(note)")

        // Looks like FluentSQLite has a bug that nil field might not save properly but retain previous value
        // https://github.com/vapor/fluent-sqlite-driver/issues/89
//        if note.editingBy == nil {
//            note.editingBy = Uid.empty
//        }
        try await note.save()
        pr("after save:\(note)")
    }

Note that I have a customized save function because _$id.exists seems to have bug on iOS:

public extension Model {
    static func query() -> QueryBuilder<Self>? {
        guard let database = se.db else { return nil }
        return self.query(on: database)
    }

    static func find(_ id: Self.IDValue?) async throws -> Self? {
        guard let database = se.db else { return nil }
        return try await self.find(id, on: database).get()
    }

    // MARK: - CRUD

    @MainActor
    // If set isNew or exists, then don't query to check existing record
    func save(
        _ src: String = #function,
        isNew: Bool = false,
        exists: Bool = false
    ) async throws {
        guard let uid = id as? Uid else {
            throw makeErr("No id")
        }

        guard !fluentProcessingModelIds.contains(uid) else {
            pr("save while processing - src:\(src) uid:\(uid)")
            return
        }

        guard let database = se.db else {
            throw makeErr("No db")
        }

        if isNew {
            // No-op
        } else if exists {
            _$id.exists = true
        } else if let existing = try await Self.find(id) {
            _$id.exists = true
        }
        pr("save src:\(src) uid:\(uid) id.exists:\(_$id.exists) isNew:\(isNew) exists:\(exists)")

        fluentProcessingModelIds.insert(uid)

        try await self.save(on: database).get()

        pr("finished save id:\(desc(id))")
        fluentProcessingModelIds.remove(uid)
    }

DB init code:

class DbCo {
    let db: Database

    // References to shutdown
    let dbs: Databases

    // Needed?
    var eventLoop: EventLoop { db.eventLoop }

    private init(db: Database, dbs: Databases) {
        self.db = db
        self.dbs = dbs
    }

    static func create(on eventLoop: EventLoop) async throws -> DbCo {
        pr("dbFilePath:\(dbFilePath)")
        return try await self.create(.file(dbFilePath), on: eventLoop).get()
    }

    static func create(_ config: SQLiteConfiguration, on eventLoop: EventLoop)
    -> EventLoopFuture<DbCo>
    {
        let threadPool = NIOThreadPool(numberOfThreads: 1)
        threadPool.start()

        let dbs = Databases(threadPool: threadPool, on: eventLoop)
        dbs.use(.sqlite(config), as: .sqlite)

        var logger = Logger(label: "sqlite")

        #if DEBUG
        logger.logLevel = .debug
        #endif

        let dbCo = DbCo(db: dbs.database(logger: logger, on: eventLoop)!, dbs: dbs)

        delayNext {
            doMigrations(dbs: dbs, logger: logger, on: eventLoop)
        }

        return eventLoop.future(dbCo)
    }
hyouuu commented 9 months ago

Logs around save:

18:14:53 UdoMo:538: onNoteEdited(_:note:removeEmptyLines:deleteNoteIfEmpty:): After isExiting:true editNote:Note(input: [text: "- [v] Grape", datedAt: 2023-12-04 03:11:00 +0000, editedBy: CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1, createdAt: 2023-12-02 03:11:41 +0000, updatedAt: 2024-01-05 18:14:53 +0000, title: "Test5", id: 71541BAE-9F7E-406A-A1BF-44EF441F0313, joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61"])

18:14:53 UdoMo:597: onNoteEdited(_:): before save:Note(input: [text: "- [v] Grape", datedAt: 2023-12-04 03:11:00 +0000, editedBy: CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1, createdAt: 2023-12-02 03:11:41 +0000, updatedAt: 2024-01-05 18:14:53 +0000, title: "Test5", id: 71541BAE-9F7E-406A-A1BF-44EF441F0313, joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61"])

2024-01-05T10:14:53-0800 debug sqlite : database-id=sqlite [FluentKit] query read notes filters=[notes[id] = 71541BAE-9F7E-406A-A1BF-44EF441F0313] limits=[count(1)]
a
2024-01-05T10:14:53-0800 debug sqlite : database-id=sqlite [SQLiteNIO] SELECT "notes"."id" AS "notes_id", "notes"."createdAt" AS "notes_createdAt", "notes"."updatedAt" AS "notes_updatedAt", "notes"."deletedAt" AS "notes_deletedAt", "notes"."editingBy" AS "notes_editingBy", "notes"."editedBy" AS "notes_editedBy", "notes"."title" AS "notes_title", "notes"."text" AS "notes_text", "notes"."datedAt" AS "notes_datedAt", "notes"."doneAt" AS "notes_doneAt", "notes"."ownerId" AS "notes_ownerId", "notes"."type" AS "notes_type", "notes"."tags" AS "notes_tags", "notes"."location" AS "notes_location", "notes"."joinedIds" AS "notes_joinedIds", "notes"."meta" AS "notes_meta" FROM "notes" WHERE "notes"."id" = ?1 LIMIT 1 ["71541BAE-9F7E-406A-A1BF-44EF441F0313"]

18:14:53 DbCo:87: save(_:isNew:exists:): save src:onNoteUpdated(_:) uid:71541BAE-9F7E-406A-A1BF-44EF441F0313 id.exists:true isNew:false exists:false
18:14:53 DbCo:90: save(_:isNew:exists:): save note.editingBy:nil

2024-01-05T10:14:53-0800 debug sqlite : database-id=sqlite [FluentKit] query update notes filters=[notes[id] = 71541BAE-9F7E-406A-A1BF-44EF441F0313] input=[[text: "- [v] Grape", datedAt: 2023-12-04 03:11:00 +0000, editedBy: CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1, createdAt: 2023-12-02 03:11:41 +0000, updatedAt: 2024-01-05 18:14:53 +0000, title: "Test5", id: 71541BAE-9F7E-406A-A1BF-44EF441F0313, joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61"]]

2024-01-05T10:14:53-0800 debug sqlite : database-id=sqlite [SQLiteNIO] UPDATE "notes" SET "id" = ?1, "createdAt" = ?2, "updatedAt" = ?3, "editedBy" = ?4, "title" = ?5, "text" = ?6, "datedAt" = ?7, "joinedIds" = ?8 WHERE "notes"."id" = ?9 ["71541BAE-9F7E-406A-A1BF-44EF441F0313", 1701486701.0, 1704478493.0, "CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1", "Test5", "- [v] Grape", 1701659460.0, "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61", "71541BAE-9F7E-406A-A1BF-44EF441F0313"]

18:14:53 DbCo:105: save(_:isNew:exists:): finished save id:Optional(71541BAE-9F7E-406A-A1BF-44EF441F0313)

18:14:53 UdoMo:605: onNoteUpdated(_:): after save:Note(output: [text: "- [v] Grape", datedAt: 2023-12-04 03:11:00 +0000, editedBy: CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1, createdAt: 2023-12-02 03:11:41 +0000, updatedAt: 2024-01-05 18:14:53 +0000, title: "Test5", id: 71541BAE-9F7E-406A-A1BF-44EF441F0313, joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61"])

Logs of a load after save from app restart:

18:15:25 DbCo:146: create(on:): dbFilePath:/Users/hyouuu/Library/Developer/CoreSimulator/Devices/659239F5-69F8-429E-B0D6-264BDB9A27B9/data/Containers/Data/Application/11614C69-AAFF-4307-92F3-573E3A5FE36F/Documents/data/db.sqlite

2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [FluentKit] query read notes filters=[notes[deletedAt] = nil]
Error enumerating unfinished transactions for first transaction listener: Error Domain=ASDErrorDomain Code=509 "No active account" UserInfo={NSLocalizedDescription=No active account}

2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [SQLiteNIO] SELECT "notes"."id" AS "notes_id", "notes"."createdAt" AS "notes_createdAt", "notes"."updatedAt" AS "notes_updatedAt", "notes"."deletedAt" AS "notes_deletedAt", "notes"."editingBy" AS "notes_editingBy", "notes"."editedBy" AS "notes_editedBy", "notes"."title" AS "notes_title", "notes"."text" AS "notes_text", "notes"."datedAt" AS "notes_datedAt", "notes"."doneAt" AS "notes_doneAt", "notes"."ownerId" AS "notes_ownerId", "notes"."type" AS "notes_type", "notes"."tags" AS "notes_tags", "notes"."location" AS "notes_location", "notes"."joinedIds" AS "notes_joinedIds", "notes"."meta" AS "notes_meta" FROM "notes" WHERE "notes"."deletedAt" IS NULL ORDER BY "notes"."datedAt" DESC []

18:15:26 DbCo:175: doMigrations(dbs:logger:on:): dbCo migrator doMigrations

2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [SQLiteNIO] CREATE TABLE IF NOT EXISTS "_fluent_migrations"("id" UUID PRIMARY KEY, "name" TEXT NOT NULL, "batch" INTEGER NOT NULL, "created_at" REAL, "updated_at" REAL, CONSTRAINT "uq:_fluent_migrations.name" UNIQUE ("name")) []
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [SQLiteNIO] CREATE TABLE IF NOT EXISTS "_fluent_migrations"("id" UUID PRIMARY KEY, "name" TEXT NOT NULL, "batch" INTEGER NOT NULL, "created_at" REAL, "updated_at" REAL, CONSTRAINT "uq:_fluent_migrations.name" UNIQUE ("name")) []
18:15:26 DbCo:184: doMigrations(dbs:logger:on:): dbCo migrator done
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [FluentKit] query read _fluent_migrations limits=[count(1)]
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [SQLiteNIO] SELECT "_fluent_migrations"."id" AS "_fluent_migrations_id", "_fluent_migrations"."name" AS "_fluent_migrations_name", "_fluent_migrations"."batch" AS "_fluent_migrations_batch", "_fluent_migrations"."created_at" AS "_fluent_migrations_created_at", "_fluent_migrations"."updated_at" AS "_fluent_migrations_updated_at" FROM "_fluent_migrations" ORDER BY "_fluent_migrations"."batch" DESC LIMIT 1 []
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [FluentKit] query read _fluent_migrations limits=[count(1)]
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [SQLiteNIO] CREATE TABLE IF NOT EXISTS "_fluent_migrations"("id" UUID PRIMARY KEY, "name" TEXT NOT NULL, "batch" INTEGER NOT NULL, "created_at" REAL, "updated_at" REAL, CONSTRAINT "uq:_fluent_migrations.name" UNIQUE ("name")) []
2024-01-05T10:15:26-0800 debug sqlite : database-id=sqlite [FluentKit] query read _fluent_migrations
18:15:26 UdoMo:92: load(src:): loaded notes:[Note(output: [notes_id: "54E4DB92-6A94-436C-B486-6D521DADA636", notes_createdAt: 1704067037, notes_updatedAt: 1704443727, notes_deletedAt: null, notes_editingBy: "6A65C45F-945E-42BB-A850-EE54F6533B61", notes_editedBy: "CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1", notes_title: "Test todo", notes_text: "- [ ] Some
- [ ] Weird
- [v] Stuff", notes_datedAt: 1704067037, notes_doneAt: null, notes_ownerId: null, notes_type: null, notes_tags: null, notes_location: null, notes_joinedIds: "CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61", notes_meta: null]), Note(output: [notes_id: "71541BAE-9F7E-406A-A1BF-44EF441F0313", notes_createdAt: 1701486701, notes_updatedAt: 1704478493, notes_deletedAt: null, notes_editingBy: "CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1", notes_editedBy: "CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1", notes_title: "Test5", notes_text: "- [v] Grape", notes_datedAt: 1701659460, notes_doneAt: null, notes_ownerId: null, notes_type: null, notes_tags: null, notes_location: null, notes_joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61", notes_meta: null])] src:Udo init
hyouuu commented 9 months ago

Thanks for taking your time to look into this @0xTim !!

0xTim commented 9 months ago

There's a ton of extra stuff here, but where do you actually do

note.editingBy = nil
hyouuu commented 9 months ago

It's from

note = try await Req.editNote(
                 note.id,
                 userId: curUserId,
                 isEditing: isEditing
           )

Where Vapor returns a note with editingBy == nil, and you can confirm from the log "before save" line: 

18:14:53 UdoMo:597: onNoteEdited(_:): before save:Note(input: [text: "- [v] Grape", datedAt: 2023-12-04 03:11:00 +0000, editedBy: CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1, createdAt: 2023-12-02 03:11:41 +0000, updatedAt: 2024-01-05 18:14:53 +0000, title: "Test5", id: 71541BAE-9F7E-406A-A1BF-44EF441F0313, joinedIds: "63F295B3-F037-4332-803E-6B50C1F355D9,CD87DF85-E3E1-4F51-BFA9-A7F4E3F38BB1,88729E9B-1C7E-4A27-B331-DA54CFFF850F,6A65C45F-945E-42BB-A850-EE54F6533B61"])

Basically the field is being omitted from the print because it's nil, and I wonder if the driver has some logic that ignored those nil fields when saving thus the old value is preserved? @0xTim

0xTim commented 9 months ago

Still not seeing where you're setting nil

0xTim commented 9 months ago

And what's pr? Have you implemented description on the model?

hyouuu commented 9 months ago

Sorry I wasn't being clear - the Req.editNote sends a request to my backend made with Vapor that sets it to nil and return the updated Note, it's like this:

struct EditData: ReqContent {
    let targetId: Uid
    let userId: Uid
    let isEditing: Bool
}

    func edit(_ req: Request) async throws -> Note {
        let data = try req.content.decode(EditData.self)
        let noteId = data.targetId
        let userId = data.userId
        let isEditing = data.isEditing

        guard let note = try await Note.query(on: req.db)
            .filter(\.$id == noteId)
            .first()
        else {
            throw Abort(.notFound)
        }

        guard note.editingBy == nil || note.editingBy == userId else {
            throw Abort(.conflict)
        }

        if isEditing {
            note.editingBy = userId
        } else if let editingBy = note.editingBy {
            note.editedBy = editingBy
            note.editingBy = nil
        }
        try await note.save(on: req.db)
        return note
}

And pr is my helper function for print with function: String = #function etc

0xTim commented 6 months ago

@hyouuu would you be able to add a failing test in a PR that exhibits the behaviour?

hyouuu commented 6 months ago

Sorry figured out the cause - I overridden the struct with a server modified response, which loses the "inputValue" and "outputValue" thus it cannot distinguish the differences, although I expected nil values to always write nil to disk - seems like an optimization to only touch changed fields