realm-swift: Writing data to Realm on background thread isn't being seen when returning to main thread, despite realm.refresh() being called

How frequently does the bug occur?

Sometimes

Description

In the following code snippet, we are attempting to write data to Realm in a background thread, and once written, we call another method on the main thread to retrieve more data.

   // Receive Data
    func peripheral(_ peripheral: PBPeripheral, readerOperationalData data: Data?, cartridgeId: String, startTime: Date) {
        DDLogDebug("\(peripheral.preferredName) received \(data == nil ? "no " : "")operational data for \(self.dataFilename(cartridgeId: cartridgeId, startTime: startTime)): \(data?.count ?? 0)")

        // Write data onto background thread backed by a RunLoop and blocks executed within an autoreleasepool
        let app = AppContext.shared.app
        DatabaseService.shared.writeAsync { [weak self, weak peripheral] in
            guard let `self` = self else { return }
            guard let realm = app.persistentRealm else { DDLogDebug("Persistent realm not accessible"); return }
            guard let object = realm.objects(ReaderTestResultObject.self).filter("\(#keyPath(ReaderTestResultObject.cartridgeId)) == %@ AND \(#keyPath(ReaderTestResultObject.startTime)) == %@", cartridgeId, startTime).first else {
                DDLogError("No test results object exists for \(self.dataFilename(cartridgeId: cartridgeId, startTime: startTime)). Ignoring operational data...")
                return
            }
            defer {
                // Check next ops data file to download
                DispatchQueue.main.async { [weak self, weak peripheral] in
                    guard let peripheral = peripheral else { return }
                    self?.transferNextFileIfAvailable(for: peripheral)
                }
            }

            // Update database object
            do {

*** UPDATES OBJECT ***
                try realm.write {
                    object.operationalDataState = opsDataState  // Value either -1 or 1
                    object.modifiedDate = Date()

                    realm.add(object, update: .modified)
                    DDLogDebug("Wrote opsDataState \(opsDataState.rawValue) for \(self.dataFilename(cartridgeId: cartridgeId, startTime: startTime)) @ \(object.modifiedDate.timeIntervalSince1970)")
                }
            } catch {
                DDLogError("Error writing updated result with ops data to persistent realm: \(error)")
            }
        }
    }

// Request New External Data
    func transferNextFileIfAvailable(for peripheral: PBPeripheral) {
        defer { self.uploadNextFileIfAvailable() }

        let app = AppContext.shared.app
        guard let readerSerialNumber = peripheral.deviceInformation?.serialNumber else { return }
        guard let realm = app.persistentRealm else { DDLogDebug("Persistent realm not accessible"); return }
        realm.refresh()

*** SHOULD READ UPDATED OBJECT ***
        guard let object = realm.objects(ReaderTestResultObject.self).filter("\(#keyPath(ReaderTestResultObject.serialNumber)) == %@ AND \(#keyPath(ReaderTestResultObject.operationalDataState)) == %d", readerSerialNumber, ReaderTestResultObject.OperationalDataState.unknown.rawValue).sorted(by: { $0.startTime < $1.startTime }).first else {
            return
        }

        DDLogDebug("(\(peripheral.preferredName)) Read opsDataState \(object.operationalDataState.rawValue) for \(self.dataFilename(cartridgeId: object.cartridgeId, startTime: object.startTime)) @ \(object.modifiedDate.timeIntervalSince1970)")
        DDLogDebug("\(peripheral.preferredName) requesting operational data for \(self.dataFilename(cartridgeId: object.cartridgeId, startTime: object.startTime))")
        peripheral.requestOperationalData(withCartridgeId: object.cartridgeId, date: object.startTime)
    }

The basic idea is that we have a bunch of Realm objects ReaderTestResultObject that represent external files we are retrieving. These objects start with an opsDataState of 0. Once the file is pulled over, or not pulled over, we change opsDataState to -1 or 1, and then try to pull the next file. The process of figuring out what file to transfer is a Realm query to find the first object that still has a value of 0.

Most of the time, this code executes perfectly fine and doesn’t pose any problems. The logic is sound for most users all the time.

However, on certain instances:

We query for the first object that has an opsDataState = 0
We attempt to retrieve the file, which may succeed or not.
On a background thread, we get the same object and update it’s state to -1 or 1 (depending on whether we pulled data or not, and add an updated timestamp when the change occurred.
No error logs are printed, and the happy path of logs is always printed. The last log confirms the updated opsDataState in the write block.
We call the function to retrieve the next file on a DispatchQueue.async.main, which should cycle back to step 1
We expect that since we updated the opsDataState and time, that object should no longer be returned by the readQuery
The updated object isn’t seen by the readQuery, and so keeps returning the same object to retrieve data on, and the cycle never stops.
We attempted to add a manual realm.refresh() call prior to searching for the next object to pull data for, but this failed to address the issue on the iOS devices experiencing the issue.

This is not dependent on Realm version, and we are always on the latest Realm version via Cocoapods. This issue was just seen today, so know that this is occurring on the latest Realm.

Stacktrace & log output

Here is an example where we are attempting to pull a file for the given file name, the file wasn’t found so we update the object to have an opsDataState of -1, but then on subsequent read to look for the first object that has an opsDataState value of 0, the same object is returned. We printed out the modifiedData timestamp of the object, and you can see that the date value never changes, even though on every write, it is being updated to the most current date of the system.

You should note that in the code snippet above, we log any and all potential errors that could happen at any given line, and the below, you will see an absence of any errors. All calls are successful in executing, whether it be getting the realm, writing data to realm, etc. However, the written data on the background thread is never seen on the main thread where it needs to be accessed, despite an explicit call to realm.refresh().


2022-01-21 15:30:22.933 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:22.934 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739422.934417
2022-01-21 15:30:22.956 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:22.956 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:22.956 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.114 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:23.114 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:23.116 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739423.115747
2022-01-21 15:30:23.136 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:23.136 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.136 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.294 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:23.294 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:23.296 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739423.296088
2022-01-21 15:30:23.315 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:23.315 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.315 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.474 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:23.474 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:23.476 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739423.4757838
2022-01-21 15:30:23.496 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:23.496 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.497 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.651 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:23.651 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:23.653 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739423.6527162
2022-01-21 15:30:23.673 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:23.673 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.673 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.834 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:23.834 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:23.836 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739423.836217
2022-01-21 15:30:23.857 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:23.857 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:23.857 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.014 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.014 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.016 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.0158339
2022-01-21 15:30:24.038 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.038 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.038 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.194 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.195 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.196 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.196289
2022-01-21 15:30:24.218 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.218 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.218 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.370 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.371 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.372 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.372291
2022-01-21 15:30:24.392 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.392 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.392 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.554 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.554 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.555 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.555418
2022-01-21 15:30:24.577 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.577 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.577 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.734 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.734 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.736 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.735952
2022-01-21 15:30:24.736 [D] (SettingsCoordinator:163) Settings - selected reportIssue
2022-01-21 15:30:24.806 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.806 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.806 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.913 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:24.913 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:24.914 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739424.914372
2022-01-21 15:30:24.923 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:24.923 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:24.923 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:25.091 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...
2022-01-21 15:30:25.091 [D] (OperationalDataProcess:152) Proof Lab 0117 received no operational data for 2021-12-17T01-07-22Z_C9991234567.tgz: 0
2022-01-21 15:30:25.093 [D] (OperationalDataProcess:198) Wrote opsDataState -1 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1642739425.0929909
2022-01-21 15:30:25.113 [D] (OperationalDataProcess:82) (Proof Lab 0117) Read opsDataState 0 for 2021-12-17T01-07-22Z_C9991234567.tgz @ 1639703534.536449
2022-01-21 15:30:25.113 [D] (OperationalDataProcess:83) Proof Lab 0117 requesting operational data for 2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:25.113 [D] (PBObjectTransferService:273) (Proof Lab 0117) Attempting to download operational data file: results/2021-12-17T01-07-22Z_C9991234567.tgz
2022-01-21 15:30:25.274 [D] (PBObjectTransferService:312) (Proof Lab 0117) Resetting OTS Service...



### Can you reproduce the bug?

Not yet

### Reproduction Steps

_No response_

### Version

10.21.1

### What SDK flavour are you using?

Local Database only

### Are you using encryption?

No, not using encryption

### Platform OS and version(s)

iOS / iPadOS 15.2

### Build environment

Xcode version: 13.2.1
Dependency manager and version: Cocoapods 1.11.2

About this issue

Original URL
State: closed
Created 2 years ago
Comments: 21 (10 by maintainers)

Most upvoted comments

I stumbled across what’s causing this. It turns out that there’s a scenario where refresh() was intentionally not advancing to the latest version, but in a way that’s not actually documented and was just a bad idea.

tgoyne on Aug 29, 2022