Faulty `SingleQueryChange` event when merging remote and local object

rorbech commented 2 years ago

There is an inconsistency in the notifications reported from https://github.com/realm/realm-kotlin-samples/blob/main/MultiplatformDemoWithSync/shared/src/commonMain/kotlin/io/realm/kotlin/demo/model/CounterRepository.kt#L90

The issue is observed when initializing a new instance of the app when there is already data on the server side. Thus, creating a local Counter-object with same primary key as already existing on the remote side. When the remote data is synced the emitted events are not as expected and not consistent across platforms:

On Native (iOS/macos) the emitted changes are:

SingleQueryChange: io.realm.kotlin.notifications.internal.InitialObjectImpl@27e15e8
SingleQueryChange.obj: io.realm.kotlin.demo.model.entity.Counter@2dd17d8

Followed by

SingleQueryChange: io.realm.kotlin.notifications.internal.DeletedObjectImpl@2152478
SingleQueryChange.obj: null

Where as on Android the emitted events are:

SingleQueryChange: io.realm.kotlin.notifications.internal.InitialObjectImpl@883a296
SingleQueryChange.obj: io.realm.kotlin.demo.model.entity.Counter@19a1e17

Followed by:

SingleQueryChange: io.realm.kotlin.notifications.internal.InitialObjectImpl@51c7433
SingleQueryChange.obj: io.realm.kotlin.demo.model.entity.Counter@af733f0

cmelchior commented 2 years ago

I can reproduce the weird behaviour with this test:

    // Check that we see the correct object notifications when bootstrapping data from the server
    @Test
    fun objectNotificationsWhenReplacedByServer() = runBlocking {
        val id = "id-${Random.nextLong()}"
        val serverObject = SyncObjectWithAllTypes().apply {
            _id = id
            stringField = "server"
        }

        // 1. Upload server object
        val (email1, password1) = randomEmail() to "password1234"
        val user1 = app.createUserAndLogIn(email1, password1)
        createSyncConfig(
            user = user1,
            partitionValue = partitionValue,
            schema = setOf(SyncObjectWithAllTypes::class)
        ).let { config ->
            Realm.open(config).use { realm ->
                realm.write {
                    copyToRealm(serverObject)
                }
                realm.syncSession.uploadAllLocalChanges()
            }
        }

        // 2. User opens a Synced Realm, create the initial object and wait for the server
        // to integrate the server changes
        val (email2, password2) = randomEmail() to "password1234"
        val user2 = app.createUserAndLogIn(email2, password2)
        createSyncConfig(
            user = user2,
            partitionValue = partitionValue,
            schema = setOf(SyncObjectWithAllTypes::class)
        ).let { config ->
            Realm.open(config).use { realm ->
                realm.writeBlocking {
                    copyToRealm(SyncObjectWithAllTypes().apply {
                        _id = id
                        stringField = "local"
                    })
                }

                realm.query<SyncObjectWithAllTypes>("_id = $0", id).first()
                    .asFlow()
                    .collect {
                        when(it) {
                            is PendingObject -> println(it)
                            is InitialObject -> println(it)
                            is UpdatedObject -> {
                                println("Fields changed: ${it.changedFields.contentToString()}")
                                println(it)
                            }
                            is DeletedObject -> println(it)
                        }
                        println("Field: ${it.obj?.stringField}")
                    }
            }
        }
    }

Output:

io.realm.kotlin.notifications.internal.InitialObjectImpl@24d88
Field: local
----
Fields changed: [doubleRealmList, longRealmList, intRealmList, booleanRealmList, realmInstantRealmList, shortRealmList, floatRealmList, byteRealmList, objectIdRealmList, charRealmList, stringRealmList]
io.realm.kotlin.notifications.internal.UpdatedObjectImpl@2eec8
Field: local
----

There looks to be some races getting things into the logs but this is the output:

(null)
2022-06-03 17:54:35.968 test.kexe[72715:1768587] INFO: [SYNC] Connection[2]: Negotiated protocol version: 6(null)
2022-06-03 17:54:35.968 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Will emit a ping in 21306 milliseconds(null)
2022-06-03 17:54:35.970 test.kexe[72715:1768564] DEBUG: [REALM] Updating Realm version: VersionId(version=2) -> VersionId(version=3)
2022-06-03 17:54:35.970 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 2045, reliable_download_progress = false, snapshot version = 3(null)
2022-06-03 17:54:35.971 test.kexe[72715:1768594] INFO: [REALM] Realm opened: /Users/cm/Library/Developer/CoreSimulator/Devices/B1FE1861-2BE9-4575-9871-7D0CE53D488D/data/Documents/mongodb-realm/testapp1-imkdz/629a2ebbeb76e68f6b97f728/test.realm
2022-06-03 17:54:35.974 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 2045, reliable_download_progress = false, snapshot version = 3(null)
io.realm.kotlin.notifications.internal.InitialObjectImpl@28f288
Field: local
2022-06-03 17:54:35.976 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 2045, reliable_download_progress = false, snapshot version = 3(null)
2022-06-03 17:54:35.988 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Received: IDENT(client_file_ident=180, client_file_ident_salt=867405408630889328)(null)
2022-06-03 17:54:36.013 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Sending: IDENT(client_file_ident=180, client_file_ident_salt=867405408630889328, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0)(null)
2022-06-03 17:54:36.013 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Sending: MARK(request_ident=1)(null)
2022-06-03 17:54:36.072 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Download message compression: is_body_compressed = true, compressed_body_size=995, uncompressed_body_size=2426(null)
2022-06-03 17:54:36.072 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Received: DOWNLOAD CHANGESET(server_version=1, client_version=0, origin_timestamp=234201275295, origin_file_ident=178, original_changeset_size=1286, changeset_size=1286)(null)
2022-06-03 17:54:36.077 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Changeset(comp): 1286 eAFVktlvm0AQxhcwu4BPfCXOfd/39bqqWkWKVCVWW6mPETYbmxZDBUSq//vuzOISXkYzv/m+8ewYTtjnaRD6w99cM14Dn+vNx1D8RfYy+iXGGTdaQIZeIqIsRxVHJU/gMy3Vkyll3+fR+Es84awPmVL9DLLppzD8Mf8jUm450BiKJI0jbjuzOJrEr76XedypRN5M8KqVCC+cwS41lsoFAimsG95E8IY5hl150xwlQvi8VRvFcSi86DEQErvdvHx+D0NvFAqF260cf4O5X4M04x17NM/ydteFvGzp1YEV+r49nnqJGrfkQl7WL9eBFfpB1Y/f/y+w0lFV2bPaVLRwrTlvYexl6mfW21iUPRsNhIVl0wqi3LDVkmlZvl2TqBDv2KG8thq/60Jelu/VgRX6/WqMX4ByHNRV9eSr+rC3qMtTjtwFLyYddxQrK0+aiha6UzeB/+gpSjNv8a6zwUdWnnDe+9gr5lw46TRO8sNctrEoO68aCAvLdTXNkmBxnpuOqsqm26aiheuu4seTlN/bb0GSZs/w/T5YoadSQohmEKITzSHEwFjBaCKnMtcIw9zC3IZIiSNNlFQNjVAdc13lNU1yo46xYWtEpwa2DWwb2K4gqSAxQUSoichERJswlSKhSFhLlxrm6pKzttyVsg64WFcD0tOA9JEsIVlGMmCgWWGgWZVvoGyNAlmnQDbk2yjbRNcWurbRtYNkF8kekn25IqPsQF6IskN5D8qOHDAfq8aJvInsn5rQPzOhfy7PR5la/gIHXuLAKxx4DcdjN/BMdiuPTi08mHUnB1Fq3UPbesCII2yI/wCNozZS(null)
2022-06-03 17:54:36.078 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Received: DOWNLOAD CHANGESET(server_version=3, client_version=0, origin_timestamp=234201275136, origin_file_ident=177, original_changeset_size=1078, changeset_size=1078)(null)
2022-06-03 17:54:36.080 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Changeset(comp): 1078 eAFlkduK01AUhvfuOUnTNk3bmc6xc7gdmYlTqldRBGFAFFQQvBCSZmsj22RIMkqvfAjv5lEG5k30CXwHNWsfsrsxUP5/fclarH/VR5M362T5KvxMlsW7uFg9pfTt+prkPp7E0dnF+dxbPJ7P5xfeYuE9unzoeX7NyossTj49jwmN/LoRrgvCfcNYroKM+6aZr9Ks4EWrEyfCtg2ayt5ON0xTSoKEf2VYUXoTUjHMND/SNBBdlpORgH65SvIikJO6dsq2vop4u23xmlc9l2/58obSoBrad2BbnQ0c2FpnzpBtr8PhoEyhI9eBNDobjUQqHY9dnk6nkyFLqcOt6WZa/d32WKbW+dTlXKc7fX6F13C9F3Fe+Ls2XEDVezakV/V+jyVX4KBbplbloQ2JVT0biLQKHfV5UkWOeyylAifjbOP/VPzUkekqVkN13Ch/pbZykn0lGYKyjjBipiFNU5qWNG1pOqiG2ccGaiP5wBQTtVgJ3kLNv/J58ufH75/PWEsXmeHtg7v3v84/3JPvEWN22QQtPaF9oQOhjtChUFfoSOhY6EToltBtodNSO+X8HYzq1opQms6+pRmNGNzFEAte71Vuv3IHlTus3AxDfug4whsHAHCMxQWgOMH/nwD4KdZuQNA/LocbMA==(null)
2022-06-03 17:54:36.081 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Received: DOWNLOAD(download_server_version=4, download_client_version=0, latest_server_version=4, latest_server_version_salt=5390724753315322584, upload_client_version=0, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=2, ...)(null)
2022-06-03 17:54:36.081 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Scanning incoming changeset [1/2] (70 instructions)(null)
2022-06-03 17:54:36.082 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Scanning incoming changeset [2/2] (36 instructions)(null)
2022-06-03 17:54:36.082 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Scanning local changeset [1/2] (42 instructions)(null)
2022-06-03 17:54:36.083 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Scanning local changeset [2/2] (36 instructions)(null)
2022-06-03 17:54:36.083 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Indexing incoming changeset [1/2] (70 instructions)(null)
2022-06-03 17:54:36.084 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Indexing incoming changeset [2/2] (36 instructions)(null)
2022-06-03 17:54:36.084 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Finished changeset indexing (incoming: 2 changeset(s) / 106 instructions, local: 2 changeset(s) / 78 instructions, conflict group(s): 7)(null)
2022-06-03 17:54:36.085 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Transforming local changeset [1/2] through 2 incoming changeset(s) with 7 conflict group(s)(null)
2022-06-03 17:54:36.085 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Transforming local changeset [2/2] through 2 incoming changeset(s) with 7 conflict group(s)(null)
2022-06-03 17:54:36.086 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Finished transforming 2 local changesets through 2 incoming changesets (78 vs 106 instructions, in 7 conflict groups)(null)
2022-06-03 17:54:36.087 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_FlexChildObject", type_ObjectId, "_id", false, TopLevel);(null)
2022-06-03 17:54:36.087 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_FlexParentObject", type_ObjectId, "_id", false, TopLevel);(null)
2022-06-03 17:54:36.088 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_ObjectIdPk", type_ObjectId, "_id", false, TopLevel);(null)
2022-06-03 17:54:36.088 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_SyncDog", type_ObjectId, "_id", true, TopLevel);(null)
2022-06-03 17:54:36.089 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_SyncPerson", type_ObjectId, "_id", true, TopLevel);(null)
2022-06-03 17:54:36.089 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_mongo_data", type_ObjectId, "_id", true, TopLevel);(null)
2022-06-03 17:54:36.090 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: sync::create_object_with_primary_key(group, get_table("class_SyncObjectWithAllTypes"), "id-1052795551277284322");(null)
Fields changed: [doubleRealmList, longRealmList, intRealmList, booleanRealmList, realmInstantRealmList, shortRealmList, floatRealmList, byteRealmList, objectIdRealmList, charRealmList, stringRealmList]
2022-06-03 17:54:36.116 test.kexe[72715:1768594] DEBUG: [REALM] Updating Realm version: VersionId(version=3) -> VersionId(version=5)
io.realm.kotlin.notifications.internal.UpdatedObjectImpl@29bca8
2022-06-03 17:54:36.117 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: 2 remote changesets integrated, producing client version 5(null)
Field: local
2022-06-03 17:54:36.117 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 2364, downloadable(total) = 2364, uploaded = 0, uploadable = 2045, reliable_download_progress = true, snapshot version = 5(null)
2022-06-03 17:54:36.118 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 2364, downloadable(total) = 2364, uploaded = 0, uploadable = 2045, reliable_download_progress = true, snapshot version = 5(null)
2022-06-03 17:54:36.118 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Received: MARK(request_ident=1)(null)
2022-06-03 17:54:36.119 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Sending: UPLOAD(progress_client_version=5, progress_server_version=3, locked_server_version=4, num_changesets=2)(null)
2022-06-03 17:54:36.119 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=968, origin_timestamp=234201275903, origin_file_ident=0)(null)
2022-06-03 17:54:36.131 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Changeset: 3F 00 07 43 68 69 6C 64 50 6B 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 50 61 72 65 6E 74 50 6B 00 02 00 01 03 00 3F 03 16 53 79 6E 63 4F 62 6A 65 63 74 57 69 74 68 41 6C 6C 54 79 70 65 73 00 03 00 01 03 00 3F 04 04 6E 61 6D 65 3F 05 00 06 00 04 03 00 00 06 02 04 03 00 00 3F 06 05 63 68 69 6C 64 06 02 06 09 01 00 00 3F 07 0B 73 74 72 69 6E 67 46 69 65 6C 64 06 03 07 03 00 00 3F 08 09 62 79 74 65 46 69 65 6C 64 06 03 08 01 00 00 3F 09 09 63 68 61 72 46 69 65 6C 64 06 03 09 01 00 00 3F 0A 0A 73 68 6F 72 74 46 69 65 6C 64 06 03 0A 01 00 00 3F 0B 08 69 6E 74 46 69 65 6C 64 06 03 0B 01 00 00 3F 0C 09 6C 6F 6E 67 46 69 65 6C 64 06 03 0C 01 00 00 3F 0D 0C 62 6F 6F 6C 65 61 6E 46 69 65 6C 64 06 03 0D 02 00 00 3F 0E 0B 64 6F 75 62 6C 65 46 69 65 6C 64 06 03 0E 07 00 00 3F 0F 0A 66 6C 6F 61 74 46 69 65 6C 64 06 03 0F 06 00 00 3F 10 11 72 65 61 6C 6D 49 6E 73 74 61 6E 74 46 69 65 6C 64 06 03 10 05 00 00 3F 11 0D 6F 62 6A 65 63 74 49 64 46 69 65 6C 64 06 03 11 0A 00 00 3F 12 0B 6F 62 6A 65 63 74 46 69 65 6C 64 06 03 12 09 01 00 03 3F 13 13 73 74 72 69 6E 67 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 13 03 01 00 3F 14 11 62 79 74 65 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 14 01 01 00 3F 15 11 63 68 61 72 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 15 01 01 00 3F 16 12 73 68 6F 72 74 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 16 01 01 00 3F 17 10 69 6E 74 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 17 01 01 00 3F 18 11 6C 6F 6E 67 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 18 01 01 00 3F 19 14 62 6F 6F 6C 65 61 6E 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 19 02 01 00 3F 1A 13 64 6F 75 62 6C 65 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 1A 07 01 00 3F 1B 12 66 6C 6F 61 74 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 1B 06 01 00 3F 1C 19 72 65 61 6C 6D 49 6E 73 74 61 6E 74 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 1C 05 01 00 3F 1D 15 6F 62 6A 65 63 74 49 64 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 1D 0A 01 00 3F 1E 13 6F 62 6A 65 63 74 4E 75 6C 6C 61 62 6C 65 46 69 65 6C 64 06 03 1E 09 01 00 03 3F 1F 0F 73 74 72 69 6E 67 52 65 61 6C 6D 4C 69 73 74 06 03 1F 03 00 01 3F 20 0D 62 79 74 65 52 65 61 6C 6D 4C 69 73 74 06 03 20 01 00 01 3F 21 0D 63 68 61 72 52 65 61 6C 6D 4C 69 73 74 06 03 21 01 00 01 3F 22 0E 73 68 6F 72 74 52 65 61 6C 6D 4C 69 73 74 06 03 22 01 00 01 3F 23 0C 69 6E 74 52 65 61 6C 6D 4C 69 73 74 06 03 23 01 00 01 3F 24 0D 6C 6F 6E 67 52 65 61 6C 6D 4C 69 73 74 06 03 24 01 00 01 3F 25 10 62 6F 6F 6C 65 61 6E 52 65 61 6C 6D 4C 69 73 74 06 03 25 02 00 01 3F 26 0F 64 6F 75 62 6C 65 52 65 61 6C 6D 4C 69 73 74 06 03 26 07 00 01 3F 27 0E 66 6C 6F 61 74 52 65 61 6C 6D 4C 69 73 74 06 03 27 06 00 01 3F 28 15 72 65 61 6C 6D 49 6E 73 74 61 6E 74 52 65 61 6C 6D 4C 69 73 74 06 03 28 05 00 01 3F 29 11 6F 62 6A 65 63 74 49 64 52 65 61 6C 6D 4C 69 73 74 06 03 29 0A 00 01 3F 2A 0F 6F 62 6A 65 63 74 52 65 61 6C 6D 4C 69 73 74 06 03 2A 09 00 01 03(null)
2022-06-03 17:54:36.131 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Fetching changeset for upload (client_version=3, server_version=0, changeset_size=1077, origin_timestamp=234201275953, origin_file_ident=0)(null)
2022-06-03 17:54:36.133 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Session[2]: Changeset(comp): 1077 eAFtkstu00AYhWdytx0ncZykTa/pZVvUmkaB1YAqVapUgQRISCyQ7NglLlMPsl2hrHgIdn2Vqm8CT8A7AP5nasej6SzPd+QZfT4Ejd4vo/lb7zqYpx/DdPGa0g/Lb0FC8Cj0j06Op87s5XQ6PXFmM+fF6XPHqaAqJhUjSeMw+nIeBtSvZUmW1imbuxSRquYt06AgVYQRIjVtvnDjIqzxsK4nCxanRVrnaaMVRquswbOmRlnptiYPW22PMRq4UfGBFqpgRDTDZ7ceXT1BQ02UH6LrV5S5qwt01OCMGFYcuPTmIkpSt/QAA9X/5efV359/fp0h0jYZF3bhF1e3ke7dPbv/9Pv480Pw4xoR0xCdomFm15COLcS9uaXULb+xA7RrgTqFdYH1LDCosB4wq89FKtAC2O9lPhXUB2RboFVhNrDB4NGuggeAh7aQrNAh0FGfS1bgCODauCxa6axBZ32YG1b4OvCxLbhCx0A3usLyO/ihl2GStrKJbmBUNRYBpWzyncXUR2TTBN1SaRPzaW2ZIFsiW4Jsd7hqCW0LtNPOREtgR4BdEzRLZFeQSe9RsgQnmO94rysUS2wPl8e83+GepcY+zhd9MIxLi5ZKB/iJWR9auXSpe4ilbX9F/wGINhqx(null)
2022-06-03 17:54:36.204 test.kexe[72715:1768587] TRACE: [SYNC] Connection[2]: Download message compression: is_body_compressed = false, compressed_body_size=0, uncompressed_body_size=0(null)
2022-06-03 17:54:36.206 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Received: DOWNLOAD(download_server_version=6, download_client_version=3, latest_server_version=6, latest_server_version_salt=4248389537293724398, upload_client_version=5, upload_server_version=3, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=0, ...)(null)
2022-06-03 17:54:36.209 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Sending: UPLOAD(progress_client_version=6, progress_server_version=6, locked_server_version=6, num_changesets=0)(null)
2022-06-03 17:54:36.210 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Session[2]: Progress handler called, downloaded = 2364, downloadable(total) = 2364, uploaded = 2045, uploadable = 2045, reliable_download_progress = true, snapshot version = 6(null)
2022-06-03 17:54:36.243 test.kexe[72715:1768587] TRACE: [SYNC] Connection[1]: Download message compression: is_body_compressed = true, compressed_body_size=507, uncompressed_body_size=1108(null)
2022-06-03 17:54:36.244 test.kexe[72715:1768587] TRACE: [SYNC] Connection[1]: Received: DOWNLOAD CHANGESET(server_version=6, client_version=3, origin_timestamp=234201275953, origin_file_ident=180, original_changeset_size=1077, changeset_size=1077)(null)
2022-06-03 17:54:36.246 test.kexe[72715:1768587] TRACE: [SYNC] Connection[1]: Changeset(comp): 1077 eAFdkdtu00AQhndyth0ncZykTY/p4RbUmkaBK4OQkCohkAAJiQskO3Ybt4sX2a5QrngI7ngV1DeBJ+AdAO/Jm8WS9f/zxTOaf+Kjydt1unwd3sTL4n1SrJ5h/G79Oc59mCTRg/Ozubd4Mp/Pz73Fwnt88cjz/JqVF1mSXr9IYhz5dSNcFzH3DWO5CjLum2a+IlnBi1YnSYVtG5jI3k43JATHQcq/MqyI3IVYDDPNK0wC0WU5WRzgT5dpXgRyUtcmbOvLiLfbFq951XP5lq/uMA6qoX2HbquzgUO31pkzZNvrcDgoU+jIdWganY1GIpWOxy5Pp9PJkKXU4dZ0M63+2/ZYptb51OVcpzt9foU39Hovk7zwd216AVXv2TS9qvd7LLkCB90ytSoPbZpY1bOBSKvQUZ8nVeS4x1IqcDLONv5PxU8dma5iNVSHRvmW2sRkGWBEqzoCxExDmqY0LWna0nRQDdjHBmoj+dApJmqxknoLNf/K5+mfb79/PmctXWSG3x/++PDr7ON9/PWGMbtsoi09oX2hA6GO0KFQV+hI6FjoROiW0G2h01I75fwdgLq1ijEmsy8kwxFQuAsAiLm9yu1X7qByh5WbAdSAdRwBVAdg4BiAXYAVJwD/n4DxU4DNG9zCP3pRGsc=(null)
2022-06-03 17:54:36.247 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=6, download_client_version=3, latest_server_version=6, latest_server_version_salt=4248389537293724398, upload_client_version=7, upload_server_version=4, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=1, ...)(null)
2022-06-03 17:54:36.248 test.kexe[72715:1768587] TRACE: [SYNC] Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_SyncObjectWithAllTypes"), "id-1052795551277284322");(null)
2022-06-03 17:54:36.250 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[1]: Session[1]: 1 remote changeset integrated, producing client version 8(null)
2022-06-03 17:54:36.251 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=8, progress_server_version=6, locked_server_version=6, num_changesets=0)(null)
2022-06-03 17:54:36.251 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[1]: Session[1]: Progress handler called, downloaded = 2363, downloadable(total) = 2363, uploaded = 2046, uploadable = 2046, reliable_download_progress = true, snapshot version = 8(null)
2022-06-03 17:54:57.277 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Sending: PING(timestamp=181605257, rtt=0)(null)
2022-06-03 17:54:57.280 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Received: PONG(timestamp=181605257)(null)
2022-06-03 17:54:57.280 test.kexe[72715:1768587] DEBUG: [SYNC] Connection[2]: Round trip time was 5 milliseconds(null)

cmelchior commented 2 years ago

After some more testing, I don't think my test above surfaces it. The above test used SyncObjectAllTypes which has some default lists with 1 element. These lists gets updated when integrating the server change which triggered the notification...back to scratch.

cmelchior commented 2 years ago

This is the log output from the Demo app @rorbech was testing on, this produced two "InitialObjects" in a row:

2022-06-03 06:07:16.057 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Negotiated protocol version: 4
2022-06-03 06:07:16.059 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Will emit a ping in 47264 milliseconds
2022-06-03 06:07:16.318 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: IDENT(client_file_ident=9, client_file_ident_salt=5107211527141330693)
2022-06-03 06:07:16.339 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: IDENT(client_file_ident=9, client_file_ident_salt=5107211527141330693, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0)
2022-06-03 06:07:16.341 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: MARK(request_ident=1)
2022-06-03 06:07:16.343 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 118, reliable_download_progress = false, snapshot version = 4
2022-06-03 06:07:16.345 8943-8943/io.realm.kotlin.demo D/REALM: Updating Realm version: VersionId(version=2) -> VersionId(version=3)
2022-06-03 06:07:16.346 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 118, reliable_download_progress = false, snapshot version = 4
2022-06-03 06:07:16.448 8943-8943/io.realm.kotlin.demo I/Choreographer: Skipped 283 frames!  The application may be doing too much work on its main thread.
2022-06-03 06:07:16.491 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Download message compression: is_body_compressed = false, compressed_body_size=231, uncompressed_body_size=231
2022-06-03 06:07:16.493 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=1, client_version=0, origin_timestamp=234207488773, origin_file_ident=6, original_changeset_size=70, changeset_size=70)
2022-06-03 06:07:16.495 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 3F 02 04 6C 69 73 74 3F 03 09 70 61 72 74 69 74 69 6F 6E 3F 04 08 72 65 61 6C 6D 5F 69 64 00 00 00 01 03 00 06 00 02 01 00 01 06 00 03 03 00 00 06 00 04 03 01 00
2022-06-03 06:07:16.496 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="_id", 2="list", 3="partition", 4="realm_id"
    AddTable        path="Counter", pk_field="_id", pk_type=String, pk_nullable=0
    AddColumn       table="Counter", field="list", type=Int, nullable=0, collection_type=List
    AddColumn       table="Counter", field="partition", type=String, nullable=0, collection_type=Single
    AddColumn       table="Counter", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:07:16.497 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=2, client_version=0, origin_timestamp=234158403337, origin_file_ident=5, original_changeset_size=29, changeset_size=29)
2022-06-03 06:07:16.501 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 06 00 01 01 00 01
2022-06-03 06:07:16.503 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations"
    AddColumn       table="Counter", field="operations", type=Int, nullable=0, collection_type=List
2022-06-03 06:07:16.506 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=3, client_version=0, origin_timestamp=234158407261, origin_file_ident=5, original_changeset_size=57, changeset_size=57)
2022-06-03 06:07:16.508 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 07 70 72 69 6D 61 72 79 3F 02 08 72 65 61 6C 6D 5F 69 64 02 00 03 01 04 00 03 01 02 00 03 0D 64 65 6D 6F 2D 70 61 72 69 74 69 6F 6E 00
2022-06-03 06:07:16.510 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="primary", 2="realm_id"
    CreateObject    path=Counter["primary"]
    Update          path=Counter["primary"].realm_id, value=String("demo-parition"), default=0
2022-06-03 06:07:16.511 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=3, download_client_version=0, latest_server_version=12, latest_server_version_salt=2799660483100495105, upload_client_version=0, upload_server_version=0, downloadable_bytes=374, last_in_batch=true, query_version=0, num_changesets=3, ...)
2022-06-03 06:07:16.517 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [1/3] (4 instructions)
2022-06-03 06:07:16.519 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [2/3] (1 instructions)
2022-06-03 06:07:16.519 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [3/3] (2 instructions)
2022-06-03 06:07:16.520 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning local changeset [1/2] (3 instructions)
2022-06-03 06:07:16.520 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning local changeset [2/2] (2 instructions)
2022-06-03 06:07:16.521 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [1/3] (4 instructions)
2022-06-03 06:07:16.522 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [2/3] (1 instructions)
2022-06-03 06:07:16.523 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [3/3] (2 instructions)
2022-06-03 06:07:16.523 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Finished changeset indexing (incoming: 3 changeset(s) / 7 instructions, local: 2 changeset(s) / 5 instructions, conflict group(s): 2)
2022-06-03 06:07:16.524 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Transforming local changeset [1/2] through 3 incoming changeset(s) with 2 conflict group(s)
2022-06-03 06:07:16.526 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Transforming local changeset [2/2] through 3 incoming changeset(s) with 2 conflict group(s)
2022-06-03 06:07:16.527 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Finished transforming 2 local changesets through 3 incoming changesets (5 vs 7 instructions, in 2 conflict groups)
2022-06-03 06:07:16.529 8943-8991/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");
2022-06-03 06:07:16.547 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: 3 remote changesets integrated, producing client version 5
2022-06-03 06:07:16.547 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 156, downloadable(total) = 530, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:07:16.550 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 156, downloadable(total) = 530, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5

2022-06-03 06:07:17.464 8943-8943/io.realm.kotlin.demo I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@144ad79
2022-06-03 06:07:17.567 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 156, downloadable(total) = 530, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:07:17.589 8943-8991/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 156, downloadable(total) = 530, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:07:17.598 8943-8943/io.realm.kotlin.demo I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@a6fdb04

cmelchior commented 2 years ago

I can reproduce the behaviour now and have an idea:

2022-06-03 06:29:28.595 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Negotiated protocol version: 4
2022-06-03 06:29:28.596 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Will emit a ping in 29983 milliseconds
2022-06-03 06:29:28.754 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: IDENT(client_file_ident=4, client_file_ident_salt=474388013469382573)
2022-06-03 06:29:29.182 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: IDENT(client_file_ident=4, client_file_ident_salt=474388013469382573, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0)
2022-06-03 06:29:29.183 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: MARK(request_ident=1)
2022-06-03 06:29:29.184 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 118, reliable_download_progress = false, snapshot version = 4
2022-06-03 06:29:29.184 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 118, reliable_download_progress = false, snapshot version = 4
2022-06-03 06:29:29.185 9363-9363/io.realm.kotlin.demo D/REALM: Updating Realm version: VersionId(version=2) -> VersionId(version=3)
2022-06-03 06:29:29.298 9363-9363/io.realm.kotlin.demo I/Choreographer: Skipped 312 frames!  The application may be doing too much work on its main thread.
2022-06-03 06:29:29.328 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Download message compression: is_body_compressed = false, compressed_body_size=536, uncompressed_body_size=536
2022-06-03 06:29:29.329 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=1, client_version=0, origin_timestamp=234209184442, origin_file_ident=2, original_changeset_size=89, changeset_size=89)
2022-06-03 06:29:29.329 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 3F 02 04 6C 69 73 74 3F 03 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 04 09 70 61 72 74 69 74 69 6F 6E 3F 05 08 72 65 61 6C 6D 5F 69 64 00 00 00 01 03 00 06 00 02 01 00 01 06 00 03 01 00 01 06 00 04 03 00 00 06 00 05 03 01 00
2022-06-03 06:29:29.330 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="_id", 2="list", 3="operations", 4="partition", 5="realm_id"
    AddTable        path="Counter", pk_field="_id", pk_type=String, pk_nullable=0
    AddColumn       table="Counter", field="list", type=Int, nullable=0, collection_type=List
    AddColumn       table="Counter", field="operations", type=Int, nullable=0, collection_type=List
    AddColumn       table="Counter", field="partition", type=String, nullable=0, collection_type=Single
    AddColumn       table="Counter", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:29:29.330 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=3, client_version=0, origin_timestamp=234160102874, origin_file_ident=1, original_changeset_size=57, changeset_size=57)
2022-06-03 06:29:29.330 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 07 70 72 69 6D 61 72 79 3F 02 08 72 65 61 6C 6D 5F 69 64 02 00 03 01 04 00 03 01 02 00 03 0D 64 65 6D 6F 2D 70 61 72 69 74 69 6F 6E 00
2022-06-03 06:29:29.331 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="primary", 2="realm_id"
    CreateObject    path=Counter["primary"]
    Update          path=Counter["primary"].realm_id, value=String("demo-parition"), default=0
2022-06-03 06:29:29.331 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=4, client_version=0, origin_timestamp=234160107631, origin_file_ident=1, original_changeset_size=43, changeset_size=43)
2022-06-03 06:29:29.332 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 07 70 72 69 6D 61 72 79 08 00 03 02 01 01 00 01 01 00
2022-06-03 06:29:29.332 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations", 2="primary"
    ArrayInsert     path=Counter["primary"].operations[0], value=Int(1), prior_size=0
2022-06-03 06:29:29.333 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=5, client_version=0, origin_timestamp=234160107871, origin_file_ident=1, original_changeset_size=43, changeset_size=43)
2022-06-03 06:29:29.333 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 07 70 72 69 6D 61 72 79 08 00 03 02 01 01 01 01 01 01
2022-06-03 06:29:29.334 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations", 2="primary"
    ArrayInsert     path=Counter["primary"].operations[1], value=Int(1), prior_size=1
2022-06-03 06:29:29.334 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=6, client_version=0, origin_timestamp=234160108065, origin_file_ident=1, original_changeset_size=43, changeset_size=43)
2022-06-03 06:29:29.334 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 07 70 72 69 6D 61 72 79 08 00 03 02 01 01 02 01 01 02
2022-06-03 06:29:29.335 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations", 2="primary"
    ArrayInsert     path=Counter["primary"].operations[2], value=Int(1), prior_size=2
2022-06-03 06:29:29.336 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=7, client_version=0, origin_timestamp=234160108264, origin_file_ident=1, original_changeset_size=43, changeset_size=43)
2022-06-03 06:29:29.336 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 07 70 72 69 6D 61 72 79 08 00 03 02 01 01 03 01 01 03
2022-06-03 06:29:29.336 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations", 2="primary"
    ArrayInsert     path=Counter["primary"].operations[3], value=Int(1), prior_size=3
2022-06-03 06:29:29.337 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=8, client_version=0, origin_timestamp=234160109275, origin_file_ident=1, original_changeset_size=43, changeset_size=43)
2022-06-03 06:29:29.337 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 07 70 72 69 6D 61 72 79 08 00 03 02 01 01 04 01 01 04
2022-06-03 06:29:29.338 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="operations", 2="primary"
    ArrayInsert     path=Counter["primary"].operations[4], value=Int(1), prior_size=4
2022-06-03 06:29:29.339 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=8, download_client_version=0, latest_server_version=8, latest_server_version_salt=1474922765537927040, upload_client_version=0, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=7, ...)
2022-06-03 06:29:29.343 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [1/7] (5 instructions)
2022-06-03 06:29:29.343 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [2/7] (2 instructions)
2022-06-03 06:29:29.344 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [3/7] (1 instructions)
2022-06-03 06:29:29.346 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [4/7] (1 instructions)
2022-06-03 06:29:29.346 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [5/7] (1 instructions)
2022-06-03 06:29:29.347 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [6/7] (1 instructions)
2022-06-03 06:29:29.348 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning incoming changeset [7/7] (1 instructions)
2022-06-03 06:29:29.350 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning local changeset [1/2] (3 instructions)
2022-06-03 06:29:29.355 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Scanning local changeset [2/2] (2 instructions)
2022-06-03 06:29:29.357 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [1/7] (5 instructions)
2022-06-03 06:29:29.358 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [2/7] (2 instructions)
2022-06-03 06:29:29.359 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [3/7] (1 instructions)
2022-06-03 06:29:29.360 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [4/7] (1 instructions)
2022-06-03 06:29:29.361 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [5/7] (1 instructions)
2022-06-03 06:29:29.361 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [6/7] (1 instructions)
2022-06-03 06:29:29.362 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Indexing incoming changeset [7/7] (1 instructions)
2022-06-03 06:29:29.363 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Finished changeset indexing (incoming: 7 changeset(s) / 12 instructions, local: 2 changeset(s) / 5 instructions, conflict group(s): 2)
2022-06-03 06:29:29.363 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Transforming local changeset [1/2] through 7 incoming changeset(s) with 2 conflict group(s)
2022-06-03 06:29:29.364 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Transforming local changeset [2/2] through 7 incoming changeset(s) with 2 conflict group(s)
2022-06-03 06:29:29.365 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Finished transforming 2 local changesets through 7 incoming changesets (5 vs 12 instructions, in 2 conflict groups)
2022-06-03 06:29:29.367 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");
2022-06-03 06:29:29.379 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: 7 remote changesets integrated, producing client version 5
2022-06-03 06:29:29.379 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:29:29.381 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: MARK(request_ident=1)
2022-06-03 06:29:29.381 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=5, progress_server_version=8, locked_server_version=8, num_changesets=2)
2022-06-03 06:29:29.382 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=61, origin_timestamp=234160168128, origin_file_ident=0)
2022-06-03 06:29:29.383 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 72 65 61 6C 6D 5F 69 64 3F 03 00 06 00 02 03 01 00 3F 04 0A 6F 70 65 72 61 74 69 6F 6E 73 06 00 04 01 00 01
2022-06-03 06:29:29.384 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="_id", 2="realm_id", 3="", 4="operations"
    AddTable        path="Counter", pk_field="_id", pk_type=String, pk_nullable=0
    AddColumn       table="Counter", field="realm_id", type=String, nullable=1, collection_type=Single
    AddColumn       table="Counter", field="operations", type=Int, nullable=0, collection_type=List
2022-06-03 06:29:29.384 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Fetching changeset for upload (client_version=3, server_version=0, changeset_size=57, origin_timestamp=234160169173, origin_file_ident=0)
2022-06-03 06:29:29.385 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 07 70 72 69 6D 61 72 79 02 00 03 01 3F 02 08 72 65 61 6C 6D 5F 69 64 04 00 03 01 02 00 03 0D 64 65 6D 6F 2D 70 61 72 69 74 69 6F 6E 00
2022-06-03 06:29:29.385 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Session[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="primary", 2="realm_id"
    CreateObject    path=Counter["primary"]
    Update          path=Counter["primary"].realm_id, value=String("demo-parition"), default=0
2022-06-03 06:29:29.388 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:29:29.617 9363-9411/io.realm.kotlin.demo V/SYNC: Connection[1]: Download message compression: is_body_compressed = false, compressed_body_size=0, uncompressed_body_size=0
2022-06-03 06:29:29.617 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=10, download_client_version=3, latest_server_version=10, latest_server_version_salt=3827382790288751631, upload_client_version=5, upload_server_version=8, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=0, ...)
2022-06-03 06:29:29.624 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=6, progress_server_version=10, locked_server_version=10, num_changesets=0)
2022-06-03 06:29:29.625 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:29:30.045 581-610/system_process D/CompatibilityChangeReporter: Compat change id reported: 158002302; UID 10180; state: ENABLED
2022-06-03 06:29:30.045 419-520/? W/ServiceManager: Permission failure: android.permission.ACCESS_SURFACE_FLINGER from uid=10180 pid=9363
2022-06-03 06:29:30.046 419-520/? D/PermissionCache: checking android.permission.ACCESS_SURFACE_FLINGER for uid=10180 => denied (540 us)
2022-06-03 06:29:30.046 419-520/? W/ServiceManager: Permission failure: android.permission.ROTATE_SURFACE_FLINGER from uid=10180 pid=9363
2022-06-03 06:29:30.047 419-520/? D/PermissionCache: checking android.permission.ROTATE_SURFACE_FLINGER for uid=10180 => denied (706 us)
2022-06-03 06:29:30.051 9363-9385/io.realm.kotlin.demo D/HostConnection: createUnique: call
2022-06-03 06:29:30.052 9363-9385/io.realm.kotlin.demo D/HostConnection: HostConnection::get() New Host Connection established 0x760999623750, tid 9385
2022-06-03 06:29:30.061 9363-9385/io.realm.kotlin.demo D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV_Cache ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_EGL_image_external_essl3 GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_gles_max_version_3_0 
2022-06-03 06:29:30.067 194-194/? I/hwservicemanager: getTransport: Cannot find entry android.hardware.configstore@1.0::ISurfaceFlingerConfigs/default in either framework or device VINTF manifest.
2022-06-03 06:29:30.068 9363-9385/io.realm.kotlin.demo W/OpenGLRenderer: Failed to choose config with EGL_SWAP_BEHAVIOR_PRESERVED, retrying without...
2022-06-03 06:29:30.068 9363-9385/io.realm.kotlin.demo W/OpenGLRenderer: Failed to initialize 101010-2 format, error = EGL_SUCCESS
2022-06-03 06:29:30.072 9363-9385/io.realm.kotlin.demo D/EGL_emulation: eglCreateContext: 0x760999625610: maj 3 min 0 rcv 3
2022-06-03 06:29:30.076 9363-9385/io.realm.kotlin.demo D/EGL_emulation: eglMakeCurrent: 0x760999625610: ver 3 0 (tinfo 0x760bb95dc080) (first time)
2022-06-03 06:29:30.088 419-520/? E/HWComposer: getSupportedContentTypes: getSupportedContentTypes failed for display 4619827259835644672: Unsupported (8)
2022-06-03 06:29:30.093 194-194/? I/hwservicemanager: getTransport: Cannot find entry android.hardware.graphics.mapper@4.0::IMapper/default in either framework or device VINTF manifest.
2022-06-03 06:29:30.094 9363-9385/io.realm.kotlin.demo I/Gralloc4: mapper 4.x is not supported
2022-06-03 06:29:30.095 9363-9385/io.realm.kotlin.demo D/HostConnection: createUnique: call
2022-06-03 06:29:30.096 9363-9385/io.realm.kotlin.demo D/HostConnection: HostConnection::get() New Host Connection established 0x760999625b50, tid 9385
2022-06-03 06:29:30.097 9363-9385/io.realm.kotlin.demo D/goldfish-address-space: allocate: Ask for block of size 0x100
2022-06-03 06:29:30.098 9363-9385/io.realm.kotlin.demo D/goldfish-address-space: allocate: ioctl allocate returned offset 0x3f3ffe000 size 0x2000
2022-06-03 06:29:30.101 194-194/? I/hwservicemanager: getTransport: Cannot find entry android.hardware.graphics.allocator@4.0::IAllocator/default in either framework or device VINTF manifest.
2022-06-03 06:29:30.102 9363-9385/io.realm.kotlin.demo W/Gralloc4: allocator 4.x is not supported
2022-06-03 06:29:30.105 375-432/? D/goldfish-address-space: claimShared: Ask to claim region [0x3f775f000 0x3f7f48000]
2022-06-03 06:29:30.143 9363-9385/io.realm.kotlin.demo D/HostConnection: HostComposition ext ANDROID_EMU_CHECKSUM_HELPER_v1 ANDROID_EMU_native_sync_v2 ANDROID_EMU_native_sync_v3 ANDROID_EMU_native_sync_v4 ANDROID_EMU_dma_v1 ANDROID_EMU_direct_mem ANDROID_EMU_host_composition_v1 ANDROID_EMU_host_composition_v2 ANDROID_EMU_YUV_Cache ANDROID_EMU_has_shared_slots_host_memory_allocator ANDROID_EMU_sync_buffer_data ANDROID_EMU_read_color_buffer_dma GL_OES_EGL_image_external_essl3 GL_OES_vertex_array_object GL_KHR_texture_compression_astc_ldr ANDROID_EMU_host_side_tracing ANDROID_EMU_gles_max_version_3_0 
2022-06-03 06:29:30.145 375-432/? D/goldfish-address-space: claimShared: Ask to claim region [0x3f4fd2000 0x3f57bb000]
2022-06-03 06:29:30.149 375-432/? D/goldfish-address-space: claimShared: Ask to claim region [0x3f57bb000 0x3f5fa4000]
2022-06-03 06:29:30.221 2088-2168/com.android.systemui D/StartingSurfaceDrawer: Task start finish, remove starting surface for task 349
2022-06-03 06:29:30.223 2088-2168/com.android.systemui V/StartingSurfaceDrawer: Removing splash screen window for task: 349
2022-06-03 06:29:30.226 581-606/system_process I/ActivityTaskManager: Displayed io.realm.kotlin.demo/.ui.counter.CounterActivity: +7s45ms
2022-06-03 06:29:30.231 9363-9378/io.realm.kotlin.demo I/OpenGLRenderer: Davey! duration=6127ms; Flags=1, FrameTimelineVsyncId=27188, IntendedVsync=120082338483607, Vsync=120087538483399, InputEventId=0, HandleInputStart=120087550589043, AnimationStart=120087550643043, PerformTraversalsStart=120087551323043, DrawStart=120088396551043, FrameDeadline=120082355150273, FrameInterval=120087550334043, FrameStartTime=16666666, SyncQueued=120088414630043, SyncStart=120088415591043, IssueDrawCommandsStart=120088417869043, SwapBuffers=120088456314043, FrameCompleted=120088467289043, DequeueBufferDuration=28000, QueueBufferDuration=1999000, GpuCompleted=120088467165043, SwapBuffersCompleted=120088467289043, DisplayPresentTime=0, 
2022-06-03 06:29:30.268 9363-9363/io.realm.kotlin.demo I/Choreographer: Skipped 50 frames!  The application may be doing too much work on its main thread.
2022-06-03 06:29:30.270 9363-9408/io.realm.kotlin.demo D/REALM: Realm opened: /data/user/0/io.realm.kotlin.demo/files/mongodb-realm/realm-kotlin-sync-demo-lhcgs/615791c1540110745e1d12b5/s_demo-parition.realm
2022-06-03 06:29:30.280 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:29:30.359 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:29:30.364 9363-9378/io.realm.kotlin.demo I/OpenGLRenderer: Davey! duration=907ms; Flags=0, FrameTimelineVsyncId=27324, IntendedVsync=120087671816727, Vsync=120088505150027, InputEventId=0, HandleInputStart=120088520586043, AnimationStart=120088520734043, PerformTraversalsStart=120088551882043, DrawStart=120088560397043, FrameDeadline=120087705150059, FrameInterval=120088519810043, FrameStartTime=16666666, SyncQueued=120088561590043, SyncStart=120088562142043, IssueDrawCommandsStart=120088562359043, SwapBuffers=120088567037043, FrameCompleted=120088579830043, DequeueBufferDuration=55000, QueueBufferDuration=3440000, GpuCompleted=120088579541043, SwapBuffersCompleted=120088579830043, DisplayPresentTime=0, 
2022-06-03 06:29:30.377 9363-9363/io.realm.kotlin.demo I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@144ad79
2022-06-03 06:29:30.483 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:29:30.507 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 361, downloadable(total) = 361, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:29:30.513 9363-9363/io.realm.kotlin.demo I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@a6fdb04

I think the issue is in the way we do writes. The model works by:

Creating the initial empty object
Increment array
Increment array
Increment array
Increment array
...

Each of these are write transactions, which must be triggering some edge case in the notifier, but I have no idea what.

cmelchior commented 2 years ago

I tried to reproduce in a unit test, but this seems to work correctly:

    @Test
    fun objectNotificationsWhenReplacedByServer() = runBlocking {
        val schema = setOf(ParentPk::class, ChildPk::class)
        val id = "id-${Random.nextLong()}"
        val serverObject = ParentPk().apply {
            _id = id
            name = "server"
        }

        // 1. Upload server object
        val (email1, password1) = randomEmail() to "password1234"
        val user1 = app.createUserAndLogIn(email1, password1)
        createSyncConfig(
            user = user1,
            partitionValue = partitionValue,
            schema = schema
        ).let { config ->
            Realm.open(config).use { realm ->
                val obj = realm.write {
                    copyToRealm(serverObject)
                }
                repeat(5) { count ->
                    realm.write {
                        findLatest(obj)!!.operations.add(count)
                    }
                }
                realm.syncSession.uploadAllLocalChanges()
            }
        }

        // 2. User opens a Synced Realm, create the initial object and wait for the server
        // to integrate the server changes
        val (email2, password2) = randomEmail() to "password1234"
        val user2 = app.createUserAndLogIn(email2, password2)
        createSyncConfig(
            user = user2,
            partitionValue = partitionValue,
            schema = schema
        ).let { config ->
            Realm.open(config).use { realm ->
                realm.writeBlocking {
                    copyToRealm(ParentPk().apply {
                        _id = id
                        name = "local"
                    })
                }

                // realm.query<SyncObjectWithAllTypes>("_id = $0", id).first()
                realm.query<ParentPk>("_id = $0", id).first()
                    .asFlow()
                    .collect {
                        when(it) {
                            is PendingObject -> println(it)
                            is InitialObject -> println(it)
                            is UpdatedObject -> {
                                println("Fields changed: ${it.changedFields.contentToString()}")
                                println(it)
                            }
                            is DeletedObject -> println(it)
                        }
                        println("Field: ${it.obj?.name}, size: ${it.obj?.operations?.size ?: "-"}")
                    }
            }
        }
    }

2022-06-03 06:54:12.031 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Negotiated protocol version: 6
2022-06-03 06:54:12.038 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Will emit a ping in 7067 milliseconds
2022-06-03 06:54:12.053 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Progress handler called, downloaded = 0, downloadable(total) = 0, uploaded = 0, uploadable = 173, reliable_download_progress = false, snapshot version = 3
2022-06-03 06:54:12.056 9701-9720/io.realm.sync.testapp.test I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@6d8d13d
2022-06-03 06:54:12.057 9701-9720/io.realm.sync.testapp.test I/System.out: Field: local, size: 0
2022-06-03 06:54:12.068 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Received: IDENT(client_file_ident=227, client_file_ident_salt=6272091758361501491)
2022-06-03 06:54:12.081 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Sending: IDENT(client_file_ident=227, client_file_ident_salt=6272091758361501491, scan_server_version=0, scan_client_version=0, latest_server_version=0, latest_server_version_salt=0)
2022-06-03 06:54:12.082 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Sending: MARK(request_ident=1)
2022-06-03 06:54:12.232 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Download message compression: is_body_compressed = true, compressed_body_size=792, uncompressed_body_size=1877
2022-06-03 06:54:12.233 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=1, client_version=0, origin_timestamp=234210731131, origin_file_ident=225, original_changeset_size=1305, changeset_size=1305)
2022-06-03 06:54:12.236 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset(comp): 1305 eAFVkklv2zAQhYeSRUrybsfZ0+z7vh+JokWAAEVqtAV6DGSLsdUoYiApQPPvixnaVXQZzHzvvRFFUIL4Mo7isP8smf0YhdJq3sXqL7Hvgz9qmEu7haQfpCrJJ6jim+Yec45rtP6z5OLnezL8qkdSzGJnXL+jfPw5jn+9v6pMuj4KfZVmOpGe/6KTkX4MgzyQfiUJXpSsuqkK4hc8S01kaphHOpF1Oxgp2XCGeFbZ9PWrSgNUMtlyBqlSoWzXBlrHKkjuIhWHsjMzGR/e4jgYxMrgbmuCf+BHvkVZLme8wXs+kXtt7MuR2Tqywj/nDcdBatbNt7Ev+xfqyAr/YjXUb/8PsNQ1Uzmz3DS0SK34T7EOcvOZTx0aypnVBsEisuZGySSw3oqSvGzfqEVJXpg3vVgnI7N+q4192b5dR1b4d6qanoNJ7NbNdB+aea83nctb9ttTXmw66BpWdh42DS18R216CPdJlgfT/zpe+MjKG056H7Viz6mfjXU6uZizDg3l5HmDYBG5qGZ5Gk2v57JrpnLoqmlokbquhHqUyRvvKUqz/AEf860bB6YFAGYDWMB8AJtqhapDnAPzGQjqXeo9rBx8G4BD1WbALeot09cYALfrVBseA4vbJNsk2yRXiFSIOGgC7hBymgwYd0jgLdzNiXMiom0BcNGxGHDRtYBxMYNZ0WNIZjEr5ojME1kgsijQsyTQsyzQs8KRfOJIVjmSNUqtU2qDUptEtohsE9nxGAgudn0M7/kY3vcxfGCEQw+Y4OLIQf3YQf3EQd0c/pQWntHCc1p4gVcoLvE3xZUNjLt0be61B4xz9wZl95YqrfCw/gNj+jta
2022-06-03 06:54:12.245 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
2022-06-03 06:54:12.246 9701-9782/io.realm.sync.testapp.test V/SYNC: InternStrings   0="ChildPk", 1="_id", 2="FlexChildObject", 3="FlexParentObject", 4="ObjectIdPk", 5="ParentPk", 6="SyncDog", 7="SyncObjectWithAllTypes", 8="SyncPerson", 9="mongo_data", 10="name", 11="realm_id", 12="section", 13="age", 14="child", 15="operations", 16="breed", 17="booleanField", 18="booleanNullableField", 19="booleanRealmList", 20="byteField", 21="byteNullableField", 22="byteRealmList", 23="charField", 24="charNullableField", 25="charRealmList", 26="doubleField", 27="doubleNullableField", 28="doubleRealmList", 29="floatField", 30="floatNullableField", 31="floatRealmList", 32="intField", 33="intNullableField", 34="intRealmList", 35="longField", 36="longNullableField", 37="longRealmList", 38="objectField", 39="objectIdField", 40="objectIdNullableField", 41="objectIdRealmList", 42="objectNullableField", 43="objectRealmList", 44="realmInstantField", 45="realmInstantNullableField", 46="realmInstantRealmList", 47="shortField", 48="shortNullableField", 49="shortRealmList", 50="stringField", 51="stringNullableField", 52="stringRealmList", 53="dogs", 54="firstName", 55="lastName"
2022-06-03 06:54:12.247 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="ChildPk", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.247 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="FlexChildObject", pk_field="_id", pk_type=ObjectId, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.247 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="FlexParentObject", pk_field="_id", pk_type=ObjectId, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.248 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="ObjectIdPk", pk_field="_id", pk_type=ObjectId, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.249 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="ParentPk", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.252 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="SyncDog", pk_field="_id", pk_type=ObjectId, pk_nullable=1, is_asymmetric=0
2022-06-03 06:54:12.253 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="SyncObjectWithAllTypes", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
2022-06-03 06:54:12.254 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="SyncPerson", pk_field="_id", pk_type=ObjectId, pk_nullable=1, is_asymmetric=0
2022-06-03 06:54:12.254 9701-9782/io.realm.sync.testapp.test V/SYNC: AddTable        path="mongo_data", pk_field="_id", pk_type=ObjectId, pk_nullable=1, is_asymmetric=0
2022-06-03 06:54:12.255 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ChildPk", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.255 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ChildPk", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.257 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexChildObject", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.258 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexChildObject", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.259 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexChildObject", field="section", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.259 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexParentObject", field="age", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.260 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexParentObject", field="child", type=Link, nullable=1, collection_type=Single, target_table="FlexChildObject"
2022-06-03 06:54:12.262 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexParentObject", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.263 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexParentObject", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.263 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="FlexParentObject", field="section", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.264 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ObjectIdPk", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.265 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ObjectIdPk", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.265 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ParentPk", field="child", type=Link, nullable=1, collection_type=Single, target_table="ChildPk"
2022-06-03 06:54:12.266 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ParentPk", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.267 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ParentPk", field="operations", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.267 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="ParentPk", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.268 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncDog", field="breed", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.269 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncDog", field="name", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.269 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncDog", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.270 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="booleanField", type=Bool, nullable=0, collection_type=Single
2022-06-03 06:54:12.271 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="booleanNullableField", type=Bool, nullable=1, collection_type=Single
2022-06-03 06:54:12.271 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="booleanRealmList", type=Bool, nullable=0, collection_type=List
2022-06-03 06:54:12.271 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="byteField", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.271 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="byteNullableField", type=Int, nullable=1, collection_type=Single
2022-06-03 06:54:12.272 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="byteRealmList", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.272 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="charField", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.273 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="charNullableField", type=Int, nullable=1, collection_type=Single
2022-06-03 06:54:12.273 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="charRealmList", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.273 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="doubleField", type=Double, nullable=0, collection_type=Single
2022-06-03 06:54:12.274 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="doubleNullableField", type=Double, nullable=1, collection_type=Single
2022-06-03 06:54:12.275 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="doubleRealmList", type=Double, nullable=0, collection_type=List
2022-06-03 06:54:12.275 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="floatField", type=Float, nullable=0, collection_type=Single
2022-06-03 06:54:12.275 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="floatNullableField", type=Float, nullable=1, collection_type=Single
2022-06-03 06:54:12.276 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="floatRealmList", type=Float, nullable=0, collection_type=List
2022-06-03 06:54:12.276 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="intField", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.277 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="intNullableField", type=Int, nullable=1, collection_type=Single
2022-06-03 06:54:12.277 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="intRealmList", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.277 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="longField", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.277 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="longNullableField", type=Int, nullable=1, collection_type=Single
2022-06-03 06:54:12.278 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="longRealmList", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.278 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectField", type=Link, nullable=1, collection_type=Single, target_table="SyncObjectWithAllTypes"
2022-06-03 06:54:12.279 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectIdField", type=ObjectId, nullable=0, collection_type=Single
2022-06-03 06:54:12.279 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectIdNullableField", type=ObjectId, nullable=1, collection_type=Single
2022-06-03 06:54:12.280 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectIdRealmList", type=ObjectId, nullable=0, collection_type=List
2022-06-03 06:54:12.280 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectNullableField", type=Link, nullable=1, collection_type=Single, target_table="SyncObjectWithAllTypes"
2022-06-03 06:54:12.281 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="objectRealmList", type=Link, nullable=0, collection_type=List, target_table="SyncObjectWithAllTypes"
2022-06-03 06:54:12.282 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="realmInstantField", type=Timestamp, nullable=0, collection_type=Single
2022-06-03 06:54:12.282 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="realmInstantNullableField", type=Timestamp, nullable=1, collection_type=Single
2022-06-03 06:54:12.283 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="realmInstantRealmList", type=Timestamp, nullable=0, collection_type=List
2022-06-03 06:54:12.283 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.284 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="shortField", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.284 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="shortNullableField", type=Int, nullable=1, collection_type=Single
2022-06-03 06:54:12.285 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="shortRealmList", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.286 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="stringField", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.286 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="stringNullableField", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.287 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncObjectWithAllTypes", field="stringRealmList", type=String, nullable=0, collection_type=List
2022-06-03 06:54:12.287 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncPerson", field="age", type=Int, nullable=0, collection_type=Single
2022-06-03 06:54:12.287 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncPerson", field="dogs", type=Link, nullable=0, collection_type=List, target_table="SyncDog"
2022-06-03 06:54:12.288 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncPerson", field="firstName", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.289 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncPerson", field="lastName", type=String, nullable=0, collection_type=Single
2022-06-03 06:54:12.289 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="SyncPerson", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.289 9701-9782/io.realm.sync.testapp.test V/SYNC: AddColumn       table="mongo_data", field="realm_id", type=String, nullable=1, collection_type=Single
2022-06-03 06:54:12.290 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=3, client_version=0, origin_timestamp=234161649871, origin_file_ident=224, original_changeset_size=79, changeset_size=79)
2022-06-03 06:54:12.290 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 3F 02 04 6E 61 6D 65 3F 03 05 63 68 69 6C 64 02 00 03 01 04 00 03 01 02 00 03 06 73 65 72 76 65 72 00 04 00 03 01 03 00 00 00
2022-06-03 06:54:12.291 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="id--6239994307369344856", 2="name", 3="child"
    CreateObject    path=ParentPk["id--6239994307369344856"]
    Update          path=ParentPk["id--6239994307369344856"].name, value=String("server"), default=0
    Update          path=ParentPk["id--6239994307369344856"].child, value=Null(), default=0
2022-06-03 06:54:12.291 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=4, client_version=0, origin_timestamp=234161649894, origin_file_ident=224, original_changeset_size=60, changeset_size=60)
2022-06-03 06:54:12.292 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 08 00 03 02 01 01 00 01 00 00
2022-06-03 06:54:12.292 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="operations", 2="id--6239994307369344856"
    ArrayInsert     path=ParentPk["id--6239994307369344856"].operations[0], value=Int(0), prior_size=0
2022-06-03 06:54:12.293 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=5, client_version=0, origin_timestamp=234161649913, origin_file_ident=224, original_changeset_size=60, changeset_size=60)
2022-06-03 06:54:12.293 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 08 00 03 02 01 01 01 01 01 01
2022-06-03 06:54:12.294 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="operations", 2="id--6239994307369344856"
    ArrayInsert     path=ParentPk["id--6239994307369344856"].operations[1], value=Int(1), prior_size=1
2022-06-03 06:54:12.294 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=6, client_version=0, origin_timestamp=234161649924, origin_file_ident=224, original_changeset_size=60, changeset_size=60)
2022-06-03 06:54:12.295 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 08 00 03 02 01 01 02 01 02 02
2022-06-03 06:54:12.296 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="operations", 2="id--6239994307369344856"
    ArrayInsert     path=ParentPk["id--6239994307369344856"].operations[2], value=Int(2), prior_size=2
2022-06-03 06:54:12.296 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=7, client_version=0, origin_timestamp=234161649934, origin_file_ident=224, original_changeset_size=60, changeset_size=60)
2022-06-03 06:54:12.296 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 08 00 03 02 01 01 03 01 03 03
2022-06-03 06:54:12.297 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="operations", 2="id--6239994307369344856"
    ArrayInsert     path=ParentPk["id--6239994307369344856"].operations[3], value=Int(3), prior_size=3
2022-06-03 06:54:12.298 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Received: DOWNLOAD CHANGESET(server_version=8, client_version=0, origin_timestamp=234161649947, origin_file_ident=224, original_changeset_size=60, changeset_size=60)
2022-06-03 06:54:12.298 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 0A 6F 70 65 72 61 74 69 6F 6E 73 3F 02 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 08 00 03 02 01 01 04 01 04 04
2022-06-03 06:54:12.299 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="operations", 2="id--6239994307369344856"
    ArrayInsert     path=ParentPk["id--6239994307369344856"].operations[4], value=Int(4), prior_size=4
2022-06-03 06:54:12.299 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Received: DOWNLOAD(download_server_version=9, download_client_version=0, latest_server_version=9, latest_server_version_salt=4694847365390516512, upload_client_version=0, upload_server_version=0, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=7, ...)
2022-06-03 06:54:12.301 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [1/7] (71 instructions)
2022-06-03 06:54:12.302 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [2/7] (3 instructions)
2022-06-03 06:54:12.302 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [3/7] (1 instructions)
2022-06-03 06:54:12.303 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [4/7] (1 instructions)
2022-06-03 06:54:12.303 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [5/7] (1 instructions)
2022-06-03 06:54:12.304 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [6/7] (1 instructions)
2022-06-03 06:54:12.304 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning incoming changeset [7/7] (1 instructions)
2022-06-03 06:54:12.305 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning local changeset [1/2] (6 instructions)
2022-06-03 06:54:12.305 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Scanning local changeset [2/2] (3 instructions)
2022-06-03 06:54:12.306 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [1/7] (71 instructions)
2022-06-03 06:54:12.306 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [2/7] (3 instructions)
2022-06-03 06:54:12.307 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [3/7] (1 instructions)
2022-06-03 06:54:12.308 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [4/7] (1 instructions)
2022-06-03 06:54:12.309 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [5/7] (1 instructions)
2022-06-03 06:54:12.310 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [6/7] (1 instructions)
2022-06-03 06:54:12.310 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Indexing incoming changeset [7/7] (1 instructions)
2022-06-03 06:54:12.310 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Finished changeset indexing (incoming: 7 changeset(s) / 79 instructions, local: 2 changeset(s) / 9 instructions, conflict group(s): 7)
2022-06-03 06:54:12.311 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Transforming local changeset [1/2] through 7 incoming changeset(s) with 7 conflict group(s)
2022-06-03 06:54:12.313 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Transforming local changeset [2/2] through 7 incoming changeset(s) with 7 conflict group(s)
2022-06-03 06:54:12.315 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Finished transforming 2 local changesets through 7 incoming changesets (9 vs 79 instructions, in 7 conflict groups)
2022-06-03 06:54:12.318 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_FlexChildObject", type_ObjectId, "_id", false, TopLevel);
2022-06-03 06:54:12.319 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_FlexParentObject", type_ObjectId, "_id", false, TopLevel);
2022-06-03 06:54:12.320 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_ObjectIdPk", type_ObjectId, "_id", false, TopLevel);
2022-06-03 06:54:12.321 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_SyncDog", type_ObjectId, "_id", true, TopLevel);
2022-06-03 06:54:12.322 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_SyncObjectWithAllTypes", type_String, "_id", false, TopLevel);
2022-06-03 06:54:12.323 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_SyncPerson", type_ObjectId, "_id", true, TopLevel);
2022-06-03 06:54:12.324 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: group.get_or_add_table_with_primary_key(group, "class_mongo_data", type_ObjectId, "_id", true, TopLevel);
2022-06-03 06:54:12.328 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: sync::create_object_with_primary_key(group, get_table("class_ParentPk"), "id--6239994307369344856");
2022-06-03 06:54:12.348 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: 7 remote changesets integrated, producing client version 5
2022-06-03 06:54:12.349 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Progress handler called, downloaded = 1684, downloadable(total) = 1684, uploaded = 0, uploadable = 173, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:54:12.350 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Received: MARK(request_ident=1)
2022-06-03 06:54:12.351 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Sending: UPLOAD(progress_client_version=5, progress_server_version=8, locked_server_version=9, num_changesets=2)
2022-06-03 06:54:12.351 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=95, origin_timestamp=234161651909, origin_file_ident=0)
2022-06-03 06:54:12.352 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Changeset: 3F 00 07 43 68 69 6C 64 50 6B 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 50 61 72 65 6E 74 50 6B 00 02 00 01 03 00 3F 03 04 6E 61 6D 65 3F 04 00 06 00 03 03 00 00 06 02 03 03 00 00 3F 05 05 63 68 69 6C 64 06 02 05 09 01 00 00 3F 06 0A 6F 70 65 72 61 74 69 6F 6E 73 06 02 06 01 00 01
2022-06-03 06:54:12.352 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Changeset (parsed):
    InternStrings   0="ChildPk", 1="_id", 2="ParentPk", 3="name", 4="", 5="child", 6="operations"
    AddTable        path="ChildPk", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
    AddTable        path="ParentPk", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
    AddColumn       table="ChildPk", field="name", type=String, nullable=0, collection_type=Single
    AddColumn       table="ParentPk", field="name", type=String, nullable=0, collection_type=Single
    AddColumn       table="ParentPk", field="child", type=Link, nullable=1, collection_type=Single, target_table="ChildPk"
    AddColumn       table="ParentPk", field="operations", type=Int, nullable=0, collection_type=List
2022-06-03 06:54:12.353 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Fetching changeset for upload (client_version=3, server_version=0, changeset_size=78, origin_timestamp=234161651964, origin_file_ident=0)
2022-06-03 06:54:12.354 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 02 00 03 01 3F 02 04 6E 61 6D 65 04 00 03 01 02 00 03 05 6C 6F 63 61 6C 00 3F 03 05 63 68 69 6C 64 04 00 03 01 03 00 00 00
2022-06-03 06:54:12.355 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Session[2]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="id--6239994307369344856", 2="name", 3="child"
    CreateObject    path=ParentPk["id--6239994307369344856"]
    Update          path=ParentPk["id--6239994307369344856"].name, value=String("local"), default=0
    Update          path=ParentPk["id--6239994307369344856"].child, value=Null(), default=0
2022-06-03 06:54:12.356 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Progress handler called, downloaded = 1684, downloadable(total) = 1684, uploaded = 0, uploadable = 173, reliable_download_progress = true, snapshot version = 5
2022-06-03 06:54:12.363 9701-9720/io.realm.sync.testapp.test I/System.out: Fields changed: [operations]
2022-06-03 06:54:12.364 9701-9720/io.realm.sync.testapp.test I/System.out: io.realm.kotlin.notifications.internal.UpdatedObjectImpl@2c1e400
2022-06-03 06:54:12.366 9701-9792/io.realm.sync.testapp.test D/REALM: Updating Realm version: VersionId(version=3) -> VersionId(version=5)
2022-06-03 06:54:12.370 9701-9720/io.realm.sync.testapp.test I/System.out: Field: local, size: 5
2022-06-03 06:54:12.493 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[1]: Download message compression: is_body_compressed = false, compressed_body_size=106, uncompressed_body_size=106
2022-06-03 06:54:12.494 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[1]: Received: DOWNLOAD CHANGESET(server_version=11, client_version=9, origin_timestamp=234161651964, origin_file_ident=227, original_changeset_size=78, changeset_size=78)
2022-06-03 06:54:12.494 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[1]: Changeset: 3F 00 08 50 61 72 65 6E 74 50 6B 3F 01 17 69 64 2D 2D 36 32 33 39 39 39 34 33 30 37 33 36 39 33 34 34 38 35 36 3F 02 04 6E 61 6D 65 3F 03 05 63 68 69 6C 64 02 00 03 01 04 00 03 01 02 00 03 05 6C 6F 63 61 6C 00 04 00 03 01 03 00 00 00
2022-06-03 06:54:12.495 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[1]: Changeset (parsed):
    InternStrings   0="ParentPk", 1="id--6239994307369344856", 2="name", 3="child"
    CreateObject    path=ParentPk["id--6239994307369344856"]
    Update          path=ParentPk["id--6239994307369344856"].name, value=String("local"), default=0
    Update          path=ParentPk["id--6239994307369344856"].child, value=Null(), default=0
2022-06-03 06:54:12.495 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=11, download_client_version=9, latest_server_version=11, latest_server_version_salt=5840239287309619594, upload_client_version=12, upload_server_version=9, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=1, ...)
2022-06-03 06:54:12.497 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_ParentPk"), "id--6239994307369344856");
2022-06-03 06:54:12.507 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Session[1]: 1 remote changeset integrated, producing client version 13
2022-06-03 06:54:12.507 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=13, progress_server_version=11, locked_server_version=11, num_changesets=0)
2022-06-03 06:54:12.508 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 1383, downloadable(total) = 1383, uploaded = 474, uploadable = 474, reliable_download_progress = true, snapshot version = 13
2022-06-03 06:54:12.509 9701-9782/io.realm.sync.testapp.test V/SYNC: Connection[2]: Download message compression: is_body_compressed = false, compressed_body_size=0, uncompressed_body_size=0
2022-06-03 06:54:12.510 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Received: DOWNLOAD(download_server_version=11, download_client_version=3, latest_server_version=11, latest_server_version_salt=5840239287309619594, upload_client_version=5, upload_server_version=8, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=0, ...)
2022-06-03 06:54:12.519 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Sending: UPLOAD(progress_client_version=6, progress_server_version=11, locked_server_version=11, num_changesets=0)
2022-06-03 06:54:12.519 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Session[2]: Progress handler called, downloaded = 1684, downloadable(total) = 1684, uploaded = 173, uploadable = 173, reliable_download_progress = true, snapshot version = 6
2022-06-03 06:54:19.114 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Sending: PING(timestamp=121577365, rtt=0)
2022-06-03 06:54:19.128 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Received: PONG(timestamp=121577365)
2022-06-03 06:54:19.129 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Round trip time was 15 milliseconds
2022-06-03 06:54:19.131 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[2]: Will emit a ping in 59678 milliseconds
2022-06-03 06:54:46.691 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Sending: PING(timestamp=121604942, rtt=120)
2022-06-03 06:54:46.816 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Received: PONG(timestamp=121604942)
2022-06-03 06:54:46.817 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Round trip time was 126 milliseconds
2022-06-03 06:54:46.818 9363-9411/io.realm.kotlin.demo D/SYNC: Connection[1]: Will emit a ping in 54375 milliseconds
2022-06-03 06:54:52.002 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Sending: PING(timestamp=121610253, rtt=0)
2022-06-03 06:54:52.009 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Received: PONG(timestamp=121610253)
2022-06-03 06:54:52.010 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Round trip time was 8 milliseconds
2022-06-03 06:54:52.010 9701-9782/io.realm.sync.testapp.test D/SYNC: Connection[1]: Will emit a ping in 58400 milliseconds

clementetb commented 2 years ago

I was able to trigger a similar issue on jvm that might be related:

Attach a SingleQueryChange listener
Perform two writes transactions on the same object
We get a [PendingObject] and a [UpdatedObject] events, instead of [PendingObject], [InitialObject] and [UpdatedObject]

If we stop the execution on each breakpoint (see test comments), then we get the correct events.

Adding a breakpoint at the callback set at RealmInterop.realm_object_add_notification_callback() shows that after those two writes only an object event is triggered by core, it is skipping one.

This might affect the shim at SingleQuery.flow().

@ ReadMeTests.kt


    class Person : RealmObject {
        @PrimaryKey
        var name: String = ""
        var address: String = ""
        var dog: Dog? = null
        var addresses: RealmList<String> = realmListOf()
    }

    @Test
    fun notifications_realmSingleQuery() = runBlocking {
        val pendingReceived = Channel<Unit>(1)
        // Subscribe for a single object query change notifications
        val job = CoroutineScope(context).async {
            // ### RealmSingleQuery example begin
            realm.query<Person>("name = $0", "Carlo").first().asFlow()
                .collect { objectChange: SingleQueryChange<Person> ->
                    when (objectChange) {
                        is PendingObject -> {
                            println("Pending object")
                            pendingReceived.trySend(Unit)
                        }
                        is InitialObject -> println("Initial object: name: ${objectChange.obj.name}")
                        is UpdatedObject -> println("Updated object: name: ${objectChange.obj.name}, address: ${objectChange.obj.address}")
                        is DeletedObject -> println("Deleted object")
                    }
                }
            // ### RealmSingleQuery example end
        }

        pendingReceived.receive()

        realm.writeBlocking { // Breakpoint 1
            copyToRealm(Person().apply {
                name = "Carlo"
                address = "0"
            }, UpdatePolicy.ALL)
        }

        realm.writeBlocking { // Breakpoint 2
            copyToRealm(Person().apply {
                name = "Carlo"
                address = "1"
            }, UpdatePolicy.ALL)
        }

        realm.writeBlocking { // Breakpoint 3
            copyToRealm(Person().apply {
                name = "Carlo"
                address = "2"
            }, UpdatePolicy.ALL)
        }

        job.await()
    }

Output:

Pending object
Updated object: name: Carlo, address: 1
Updated object: name: Carlo, address: 2

cmelchior commented 2 years ago

Hm, I think that is intentional...i.e. the Notification system is allowed to handle multiple transactions at once and combine their notification. But we probably failed to consider the implications in our implementation of SingleQueryChange.

I suspect that we might have to fake some of these notifications.

What is concerning though is that @rorbech is seeing a DeletedObject on Native...I don't have a good explanation for that one ... Unless...it is DiscardLocal client reset happening without us noticing it? 🤔

rorbech commented 2 years ago

Seems like the diverging behavior from platform to platform is just a matter of timing. On Macos the initial query-subscription is done before the underlying data is downloaded, where as the subscription is running after the data is downloaded.

Traces are made with the sync-app running against a local build with additional traces available in https://github.com/realm/realm-kotlin/pull/873

MacOS (subscription is already up and running before data is downloaded):

2022-06-05 14:33:14.972734+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Finished changeset indexing (incoming: 59 changeset(s) / 62 instructions, local: 2 changeset(s) / 5 instructions, conflict group(s): 2)(null)
2022-06-05 14:33:14.973067+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Transforming local changeset [1/2] through 59 incoming changeset(s) with 2 conflict group(s)(null)
2022-06-05 14:33:14.973443+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Transforming local changeset [2/2] through 59 incoming changeset(s) with 2 conflict group(s)(null)
2022-06-05 14:33:14.973839+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Finished transforming 2 local changesets through 59 incoming changesets (5 vs 62 instructions, in 2 conflict groups)(null)
2022-06-05 14:33:14.974349+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");(null)
2022-06-05 14:33:14.974685+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");(null)
2022-06-05 14:33:14.975952+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");(null)
2022-06-05 14:33:14.976408+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");(null)
2022-06-05 14:33:15.014926+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: 59 remote changesets integrated, producing client version 5(null)
2022-06-05 14:33:15.015355+0200 macosApp[38749:3997952] DEBUG: [REALM] emit: io.realm.kotlin.internal.query.SingleQuery@3eac4c8
2022-06-05 14:33:15.015627+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5(null)
2022-06-05 14:33:15.015646+0200 macosApp[38749:3997952] DEBUG: [REALM] emit: io.realm.kotlin.internal.RealmObjectReference@3e92108
2022-06-05 14:33:15.015694+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-filter: io.realm.kotlin.notifications.internal.UpdatedResultsImpl@2f8e188
2022-06-05 14:33:15.015740+0200 macosApp[38749:3997952] DEBUG: [REALM] emitFrozenUpdate: VersionId(version=5) VersionId(version=5) null
2022-06-05 14:33:15.015758+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-filter: VersionId(version=3)
2022-06-05 14:33:15.015911+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-merge: io.realm.kotlin.notifications.internal.UpdatedResultsImpl@2f8e188
2022-06-05 14:33:15.015956+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Received: MARK(request_ident=1)(null)
2022-06-05 14:33:15.015975+0200 macosApp[38749:3997952] DEBUG: [REALM] Updating Realm version: VersionId(version=3) -> VersionId(version=5)
2022-06-05 14:33:15.016034+0200 macosApp[38749:3997917] DEBUG: [REALM] asFlow: VersionId(version=5)
2022-06-05 14:33:15.016437+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=5, progress_server_version=255, locked_server_version=281, num_changesets=2)(null)
2022-06-05 14:33:15.016955+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=61, origin_timestamp=234361994389, origin_file_ident=0)(null)
2022-06-05 14:33:15.017607+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 72 65 61 6C 6D 5F 69 64 3F 03 00 06 00 02 03 01 00 3F 04 0A 6F 70 65 72 61 74 69 6F 6E 73 06 00 04 01 00 01(null)
CHANGE: io.realm.kotlin.notifications.internal.DeletedObjectImpl@2902348
2022-06-05 14:33:15.017954+0200 macosApp[38749:3997952] DEBUG: [REALM] Register flow: io.realm.kotlin.internal.RealmObjectReference@3ea7a88
2022-06-05 14:33:15.018173+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Fetching changeset for upload (client_version=3, server_version=0, changeset_size=57, origin_timestamp=234361994430, origin_file_ident=0)(null)
2022-06-05 14:33:15.018308+0200 macosApp[38749:3997952] DEBUG: [REALM] emit: io.realm.kotlin.internal.RealmObjectReference@3ea7a88
2022-06-05 14:33:15.018411+0200 macosApp[38749:3997952] DEBUG: [REALM] emitFrozenUpdate: VersionId(version=5) VersionId(version=5) io.realm.kotlin.internal.RealmObjectReference@3eb4848
2022-06-05 14:33:15.018472+0200 macosApp[38749:3997952] DEBUG: [REALM] emitFrozenUpdate: []
2022-06-05 14:33:15.018815+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 07 70 72 69 6D 61 72 79 02 00 03 01 3F 02 08 72 65 61 6C 6D 5F 69 64 04 00 03 01 02 00 03 0D 64 65 6D 6F 2D 70 61 72 69 74 69 6F 6E 00(null)
CHANGE: io.realm.kotlin.notifications.internal.InitialObjectImpl@2f76548

Android

2022-06-05 14:39:15.425 26754-26808/? D/SYNC: Connection[1]: Session[1]: Finished changeset indexing (incoming: 59 changeset(s) / 62 instructions, local: 2 changeset(s) / 5 instructions, conflict group(s): 2)
2022-06-05 14:39:15.425 26754-26808/? V/SYNC: Connection[1]: Session[1]: Transforming local changeset [1/2] through 59 incoming changeset(s) with 2 conflict group(s)
2022-06-05 14:39:15.425 26754-26808/? V/SYNC: Connection[1]: Session[1]: Transforming local changeset [2/2] through 59 incoming changeset(s) with 2 conflict group(s)
2022-06-05 14:39:15.425 26754-26808/? D/SYNC: Connection[1]: Session[1]: Finished transforming 2 local changesets through 59 incoming changesets (5 vs 62 instructions, in 2 conflict groups)
2022-06-05 14:39:15.426 26754-26808/? V/SYNC: Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");
2022-06-05 14:39:15.427 26754-26808/? I/chatty: uid=10121(io.realm.kotlin.demo) Thread-7 identical 2 lines
2022-06-05 14:39:15.427 26754-26808/? V/SYNC: Connection[1]: Session[1]: sync::create_object_with_primary_key(group, get_table("class_Counter"), "primary");
2022-06-05 14:39:15.442 26754-26808/? D/SYNC: Connection[1]: Session[1]: 59 remote changesets integrated, producing client version 5
2022-06-05 14:39:15.442 26754-26808/? D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-05 14:39:15.442 26754-26808/? D/SYNC: Connection[1]: Session[1]: Received: MARK(request_ident=1)
2022-06-05 14:39:15.442 26754-26808/? D/SYNC: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=5, progress_server_version=255, locked_server_version=283, num_changesets=2)
2022-06-05 14:39:15.442 26754-26808/? V/SYNC: Connection[1]: Session[1]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=61, origin_timestamp=234362354329, origin_file_ident=0)
2022-06-05 14:39:15.443 26754-26808/? V/SYNC: Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 72 65 61 6C 6D 5F 69 64 3F 03 00 06 00 02 03 01 00 3F 04 0A 6F 70 65 72 61 74 69 6F 6E 73 06 00 04 01 00 01
2022-06-05 14:39:15.443 26754-26808/? V/SYNC: Connection[1]: Session[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="_id", 2="realm_id", 3="", 4="operations"
    AddTable        path="Counter", pk_field="_id", pk_type=String, pk_nullable=0, is_asymmetric=0
    AddColumn       table="Counter", field="realm_id", type=String, nullable=1, collection_type=Single
    AddColumn       table="Counter", field="operations", type=Int, nullable=0, collection_type=List
2022-06-05 14:39:15.443 26754-26808/? V/SYNC: Connection[1]: Session[1]: Fetching changeset for upload (client_version=3, server_version=0, changeset_size=57, origin_timestamp=234362355254, origin_file_ident=0)
2022-06-05 14:39:15.443 26754-26808/? V/SYNC: Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 07 70 72 69 6D 61 72 79 02 00 03 01 3F 02 08 72 65 61 6C 6D 5F 69 64 04 00 03 01 02 00 03 0D 64 65 6D 6F 2D 70 61 72 69 74 69 6F 6E 00
2022-06-05 14:39:15.444 26754-26808/? V/SYNC: Connection[1]: Session[1]: Changeset (parsed):
    InternStrings   0="Counter", 1="primary", 2="realm_id"
    CreateObject    path=Counter["primary"]
    Update          path=Counter["primary"].realm_id, value=String("demo-parition"), default=0
2022-06-05 14:39:15.445 26754-26808/? D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5
2022-06-05 14:39:15.561 26754-26808/? V/SYNC: Connection[1]: Download message compression: is_body_compressed = false, compressed_body_size=0, uncompressed_body_size=0
2022-06-05 14:39:15.561 26754-26808/? D/SYNC: Connection[1]: Session[1]: Received: DOWNLOAD(download_server_version=285, download_client_version=3, latest_server_version=285, latest_server_version_salt=1673497655164105910, upload_client_version=5, upload_server_version=255, downloadable_bytes=0, last_in_batch=true, query_version=0, num_changesets=0, ...)
2022-06-05 14:39:15.567 26754-26808/? D/SYNC: Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=6, progress_server_version=285, locked_server_version=285, num_changesets=0)
2022-06-05 14:39:15.569 26754-26808/? D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-05 14:39:17.287 26754-26795/? D/REALM: Realm opened: /data/user/0/io.realm.kotlin.demo/files/mongodb-realm/realm-kotlin-sync-demo-pcvre/616f0c107ef9cc32ea2b3091/s_demo-parition.realm
2022-06-05 14:39:17.287 26754-26795/? D/REALM: Register flow: io.realm.kotlin.internal.query.SingleQuery@20431e9
2022-06-05 14:39:17.289 26754-26795/? D/REALM: emit: io.realm.kotlin.internal.query.SingleQuery@20431e9
2022-06-05 14:39:17.293 26754-26808/? D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-05 14:39:17.301 26754-26754/? D/REALM: SingleQuery-filter: io.realm.kotlin.notifications.internal.InitialResultsImpl@d3d037a
2022-06-05 14:39:17.301 26754-26754/? D/REALM: SingleQuery-filter: VersionId(version=3)
2022-06-05 14:39:17.303 26754-26754/? D/REALM: SingleQuery-merge: io.realm.kotlin.notifications.internal.InitialResultsImpl@d3d037a
2022-06-05 14:39:17.303 26754-26754/? D/REALM: asFlow: VersionId(version=6)
2022-06-05 14:39:17.306 26754-26795/? D/REALM: Register flow: io.realm.kotlin.internal.RealmObjectReference@465d72b
2022-06-05 14:39:17.309 26754-26808/? D/SYNC: Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 118, uploadable = 118, reliable_download_progress = true, snapshot version = 6
2022-06-05 14:39:17.309 26754-26795/? D/REALM: emit: io.realm.kotlin.internal.RealmObjectReference@465d72b
2022-06-05 14:39:17.313 26754-26795/? D/REALM: emitFrozenUpdate: VersionId(version=6) VersionId(version=6) io.realm.kotlin.internal.RealmObjectReference@d2de788
2022-06-05 14:39:17.313 26754-26795/? D/REALM: emitFrozenUpdate: []
2022-06-05 14:39:17.313 26754-26775/? I/OpenGLRenderer: Davey! duration=1366ms; Flags=0, IntendedVsync=284333186539951, Vsync=284334519873231, OldestInputEvent=9223372036854775807, NewestInputEvent=0, HandleInputStart=284334528699132, AnimationStart=284334528729132, PerformTraversalsStart=284334532569132, DrawStart=284334533109132, SyncQueued=284334533317132, SyncStart=284334536198132, IssueDrawCommandsStart=284334537864132, SwapBuffers=284334548847132, FrameCompleted=284334556009132, DequeueBufferDuration=95000, QueueBufferDuration=2952000, 
2022-06-05 14:39:17.314 26754-26754/? I/System.out: CHANGE: io.realm.kotlin.notifications.internal.InitialObjectImpl@4473521

rorbech commented 2 years ago

Some details about the observation on MacOS.

There are multiple issues here:

Seems like we are emitting multiple updates as both the result-notification notification and the object-notification will cause the overall flow to emit events, but maybe even more concerning:
It seems to be that we somehow cannot resolve the frozen object after the merge of the remote data in the line

Traces according to https://github.com/realm/realm-kotlin/pull/873

This line indicates that we cannot look up the live object in the new frozen realm of the same version 🤔

2022-06-05 14:33:15.015740+0200 macosApp[38749:3997952] DEBUG: [REALM] emitFrozenUpdate: VersionId(version=5) VersionId(version=5) null

Trace with a bit more context:

2022-06-05 14:33:15.015355+0200 macosApp[38749:3997952] DEBUG: [REALM] emit: io.realm.kotlin.internal.query.SingleQuery@3eac4c8
2022-06-05 14:33:15.015627+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Progress handler called, downloaded = 2476, downloadable(total) = 2476, uploaded = 0, uploadable = 118, reliable_download_progress = true, snapshot version = 5(null)
2022-06-05 14:33:15.015646+0200 macosApp[38749:3997952] DEBUG: [REALM] emit: io.realm.kotlin.internal.RealmObjectReference@3e92108
2022-06-05 14:33:15.015694+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-filter: io.realm.kotlin.notifications.internal.UpdatedResultsImpl@2f8e188
2022-06-05 14:33:15.015740+0200 macosApp[38749:3997952] DEBUG: [REALM] emitFrozenUpdate: VersionId(version=5) VersionId(version=5) null
2022-06-05 14:33:15.015758+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-filter: VersionId(version=3)
2022-06-05 14:33:15.015911+0200 macosApp[38749:3997917] DEBUG: [REALM] SingleQuery-merge: io.realm.kotlin.notifications.internal.UpdatedResultsImpl@2f8e188
2022-06-05 14:33:15.015956+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Received: MARK(request_ident=1)(null)
2022-06-05 14:33:15.015975+0200 macosApp[38749:3997952] DEBUG: [REALM] Updating Realm version: VersionId(version=3) -> VersionId(version=5)
2022-06-05 14:33:15.016034+0200 macosApp[38749:3997917] DEBUG: [REALM] asFlow: VersionId(version=5)
2022-06-05 14:33:15.016437+0200 macosApp[38749:3997955] DEBUG: [SYNC] Connection[1]: Session[1]: Sending: UPLOAD(progress_client_version=5, progress_server_version=255, locked_server_version=281, num_changesets=2)(null)
2022-06-05 14:33:15.016955+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Fetching changeset for upload (client_version=2, server_version=0, changeset_size=61, origin_timestamp=234361994389, origin_file_ident=0)(null)
2022-06-05 14:33:15.017607+0200 macosApp[38749:3997955] TRACE: [SYNC] Connection[1]: Session[1]: Changeset: 3F 00 07 43 6F 75 6E 74 65 72 3F 01 03 5F 69 64 00 00 00 01 03 00 3F 02 08 72 65 61 6C 6D 5F 69 64 3F 03 00 06 00 02 03 01 00 3F 04 0A 6F 70 65 72 61 74 69 6F 6E 73 06 00 04 01 00 01(null)
CHANGE: io.realm.kotlin.notifications.internal.DeletedObjectImpl@2902348

cmelchior commented 2 years ago

I have pursued a different route and discovered that our Compose implementation in the examples is probably faulty:

I have so far not been able to reproduce the initial -> delete sequence, but I was seeing initial -> initial on Android... or so I thought.

But after more investigation it turns out that we are using Compose slightly wrong which caused it to subscribe multiple times, thus making the sequence very valid.

Basically this code:

                Box(Modifier.fillMaxSize()) {
                    val value: String by vm.observeCounter().collectAsState(initial = "-")
                    Text(
                        text = value,
                        modifier = Modifier.align(Alignment.Center),
                        style = MaterialTheme.typography.h1,
                        fontWeight = FontWeight.Bold
                    )
                }

Causes two flows two be created, while this only creates one flow:

class AndroidCounterViewModel: CounterViewModel, ViewModel() {
    private val vm = SharedCounterViewModel()
    override fun observeCounter(): CommonFlow<String> = TODO()
    // val required here as using a function will cause Compose to recompose in a loop because you would get a new flow every time.
    val counter: StateFlow<String> = vm.observeCounter().stateIn(viewModelScope, SharingStarted.WhileSubscribed(), "-")
    override fun increment() = vm.increment()
    override fun decrement() = vm.decrement()
}

                Box(Modifier.fillMaxSize()) {
                    val value by vm.counter.collectAsState()
                    Text(
                        text = value,
                        modifier = Modifier.align(Alignment.Center),
                        style = MaterialTheme.typography.h1,
                        fontWeight = FontWeight.Bold
                    )
                }

So guess that was a goose chase

cmelchior commented 2 years ago

Looking into SingleQuery and I'm wondering about a few things:

    override fun asFlow(): Flow<SingleQueryChange<E>> {
        realmReference.checkClosed()

        var head: E? = null
        var headFlow: Cancellable? = null

        return realmReference.owner.registerObserver(this)
            .filter { resultsChange: ResultsChange<E> ->
                // This filter prevents flat mapping an object flow if the object is the same.
                val newHead: E? = resultsChange.list.firstOrNull()

                val isSameObject = newHead != null && !newHead.hasSameObjectKey(head)
                val pendingObject = resultsChange is InitialResults<E> && resultsChange.list.isEmpty()

                (isSameObject || pendingObject).also {
                    head = newHead
                }
            }.flatMapMerge { resultsChange ->
                // Head was changed, cancel any active flow unless the head was deleted. In the case
                // the head was deleted the flow would emit a [DeletedObject] and terminate.
                if (resultsChange is UpdatedResults<*> && !resultsChange.deletions.contains(0)) {
                    headFlow?.cancel()
                }

                if (resultsChange is InitialResults<E> && resultsChange.list.isEmpty()) {
                    flowOf(PendingObjectImpl())
                } else {
                    resultsChange.list
                        .first()
                        .asFlow()
                        .also {
                            headFlow = it as Cancellable
                        }
                }
            }
    }

1) Why do we filter out pendingObject, doesn't that mean that we never see the PendingObject, expect we have tests showing we do...so something about that logic could probably use a renaming of variables?

2) Why are we using flatmapMerge instead of flatmapLatest`. The later would handle the cancelation for us if I read the documentation correctly: https://kotlin.github.io/kotlinx.coroutines/kotlinx-coroutines-core/kotlinx.coroutines.flow/flat-map-latest.html

/cc @clementetb

clementetb commented 2 years ago

Actually we are filtering it in, the issue is that isSameObject should be isNotSameObject.
It is done to allow the previous flow to emit a ObjectDelete.

In the case that we change flows because the head element is deleted flatmapMerge a final ObjectDeleted would be emitted, if he flows are automatically cancelled it might not be triggered.

cmelchior commented 2 years ago

Ah yeah, good points 👍

rorbech commented 2 years ago

Added an integration test to #873 that shows the issue ... at least on Android

2022-06-06 09:01:51.340 31204-31225/? I/System.out: io.realm.kotlin.notifications.internal.InitialObjectImpl@8d9461d
2022-06-06 09:01:51.340 31204-31225/? I/System.out: io.realm.kotlin.entities.sync.ParentPk@f4de092
2022-06-06 09:01:51.340 31204-31225/? I/System.out: 1
2022-06-06 09:01:51.389 31204-31225/? I/System.out: v7TPOZtm50q8kMBoKiKRaD2JhXgjM6OUNzHojXuFXvxdtwtN9fCVIW4njdwVdZ9aChvXCtW4nzUYeYWbI6wuSspbyjvACtMtjQTtOoe12ZEPZPII6PAFTfbrQQxc3ymJv7TPOZtm50q8kM 
2022-06-06 09:01:51.589 31204-31225/? I/System.out: io.realm.kotlin.notifications.internal.DeletedObjectImpl@fa8288c
2022-06-06 09:01:51.589 31204-31225/? I/System.out: null

rorbech commented 2 years ago

The object deletion events was caused by re-running tests that creates objects with statically assigned primary keys but different partition values. Sync will correctly delete new objects with the same primary key even though the partition value is different because it is backed by a collection that only uses the primary key-field as primary key.

The behaviour in the sample demo app must have been due to old sync history with same situation (same primary key object but different partition key) laying around generating the same deletion events. Disabling and reenabling sync flushed that history and eliminate the issue.

realm / realm-kotlin

Faulty `SingleQueryChange` event when merging remote and local object #871