search

realm / realm-kotlin

Kotlin Multiplatform and Android SDK for the Realm Mobile Database: Build Better Apps Faster.
Apache License 2.0
944 stars 57 forks source link

Flaky test: cancelAsFlow ā€“ io.realm.kotlin.test.common.notifications.RealmNotificationsTests #1574

Closed clementetb closed 9 months ago

clementetb commented 10 months ago

We have seen this test failing with the following stack trace

kotlinx.coroutines.TimeoutCancellationException: Timeout: null
at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$2$2.invokeSuspend(Utils.kt:102)
at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$2$2.invoke(Unknown Source:8)
at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$2$2.invoke(Unknown Source:2)
at kotlinx.coroutines.selects.SelectImplementation$ClauseData.invokeBlock(Select.kt:818)
at kotlinx.coroutines.selects.SelectImplementation.complete(Select.kt:692)
at kotlinx.coroutines.selects.SelectImplementation.doSelectSuspend(Select.kt:434)
at kotlinx.coroutines.selects.SelectImplementation.access$doSelectSuspend(Select.kt:243)
at kotlinx.coroutines.selects.SelectImplementation$doSelectSuspend$1.invokeSuspend(Unknown Source:14)
at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106)
at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking(CoroutineUtilsSharedJvm.kt:22)
at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking$default(CoroutineUtilsSharedJvm.kt:21)
at io.realm.kotlin.test.common.notifications.RealmNotificationsTests.cancelAsFlow(RealmNotificationsTests.kt:125)

Observed here

cmelchior commented 10 months ago

Hmm, that looks new. I wonder if that is related to our scheduler changes? šŸ¤”

cmelchior commented 10 months ago

I saw this fail on Github Actions as well

cmelchior commented 10 months ago

Potentially related to https://github.com/realm/realm-kotlin/issues/1582

cmelchior commented 10 months ago

Failed again here: https://github.com/realm/realm-kotlin/runs/19053315743 With improved error message: kotlinx.coroutines.TimeoutCancellationException: Timeout after 1m: Did not receive Update event on Channel 1

cmelchior commented 10 months ago

After more testing, I am now seeing logs that indicate that it is indeed our own callbacks that do not trigger:

11-28 14:50:16.373  3222  3238 I TestRunner: started: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-28 14:50:16.438  3222  3238 I System.out: Received from realm1.asFlow(). Sending: io.realm.kotlin.notifications.internal.InitialRealmImpl@2d88345
11-28 14:50:16.438  3222  3238 I System.out: Received from realm2.asFlow(). Sending: io.realm.kotlin.notifications.internal.InitialRealmImpl@a8d1a9a
11-28 14:50:16.731   594   712 D ActivityManager: freezing 2052 com.android.cellbroadcastreceiver.module
11-28 14:50:23.975   913  1051 D EGL_emulation: app_time_stats: avg=23884.97ms min=23884.97ms max=23884.97ms count=1
11-28 14:50:25.400   594   712 D ActivityManager: freezing 2137 com.android.messaging
11-28 14:50:30.198   594   712 D ActivityManager: freezing 2363 com.android.onetimeinitializer
11-28 14:50:34.567   594   712 D ActivityManager: freezing 1658 com.android.providers.calendar
11-28 14:50:36.864   594   712 D ActivityManager: freezing 1606 android.process.media
11-28 14:50:42.200   594   712 D ActivityManager: freezing 1129 com.android.settings
11-28 14:50:44.936   594   712 D ActivityManager: freezing 2451 com.android.statementservice
11-28 14:50:50.133   594   712 D ActivityManager: freezing 2402 com.android.remoteprovisioner
11-28 14:51:00.046   913  1051 D EGL_emulation: app_time_stats: avg=36067.95ms min=36067.95ms max=36067.95ms count=1
11-28 14:51:06.049     0     0 W healthd : battery l=100 v=5000 t=25.0 h=2 st=2 c=900000 fc=3000000 cc=10 chg=a
11-28 14:51:16.481  3222  3238 E TestRunner: failed: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-28 14:51:16.484  3222  3238 E TestRunner: ----- begin exception -----
11-28 14:51:16.486  3222  3238 E TestRunner: kotlinx.coroutines.TimeoutCancellationException: Timeout after 1m: Did not receive Update event on Channel 1
11-28 14:51:16.486  3222  3238 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt.receiveOrFail-dWUq8MI(Utils.kt:114)
11-28 14:51:16.486  3222  3238 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$1.invokeSuspend(Unknown Source:15)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:32)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
11-28 14:51:16.486  3222  3238 E TestRunner:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
11-28 14:51:16.486  3222  3238 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking(CoroutineUtilsSharedJvm.kt:22)
11-28 14:51:16.486  3222  3238 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking$default(CoroutineUtilsSharedJvm.kt:21)
11-28 14:51:16.486  3222  3238 E TestRunner:    at io.realm.kotlin.test.common.notifications.RealmNotificationsTests.cancelAsFlow(RealmNotificationsTests.kt:124)
11-28 14:51:16.486  3222  3238 E TestRunner:    at java.lang.reflect.Method.invoke(Native Method)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
11-28 14:51:16.486  3222  3238 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
11-28 14:51:16.486  3222  3238 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:128)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:27)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
11-28 14:51:16.486  3222  3238 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
11-28 14:51:16.486  3222  3238 E TestRunner:    at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
11-28 14:51:16.486  3222  3238 E TestRunner:    at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:444)
11-28 14:51:16.486  3222  3238 E TestRunner:    at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2361)
11-28 14:51:16.489  3222  3238 E TestRunner: ----- end exception -----
11-28 14:51:16.503  3222  3238 I TestRunner: finished: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)

This was after using unlimited buffers and receive to get elements. Unclear if we had bugs in both our Channel usage and changelisteners. Adding more logs to see if that reveals anything

cmelchior commented 10 months ago

After 7 successfull runs, I suddenly saw an error in asFlow as well. Which didn't have extended logging šŸ™ˆ 

11-29 07:37:17.400  2778  2794 I TestRunner: started: asFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-29 07:37:27.862   573   674 D ActivityManager: freezing 1507 com.android.provision
11-29 07:37:43.685   573   674 D ActivityManager: freezing 1685 com.android.localtransport
11-29 07:37:46.582   849   953 D EGL_emulation: app_time_stats: avg=46117.02ms min=46117.02ms max=46117.02ms count=1
11-29 07:37:48.477   849   902 D ControlsListingControllerImpl: Subscribing callback, service count: 0
11-29 07:37:48.504   849   902 D ControlsListingControllerImpl: Unsubscribing callback
11-29 07:37:49.432   573   674 D ActivityManager: freezing 1743 com.android.printspooler
11-29 07:37:52.283   573   674 D ActivityManager: freezing 1552 com.android.externalstorage
11-29 07:37:53.353   573   678 E ActivityManager: Sending non-protected broadcast com.android.bluetooth.btservice.BLUETOOTH_COUNTER_METRICS_ACTION from system uid 1002 pkg com.android.bluetooth
11-29 07:37:53.353   573   678 E ActivityManager: java.lang.Throwable
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.ActivityManagerService.checkBroadcastFromSystem(ActivityManagerService.java:13550)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:14268)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.ActivityManagerService.broadcastIntentInPackage(ActivityManagerService.java:14468)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.ActivityManagerService$LocalService.broadcastIntentInPackage(ActivityManagerService.java:16971)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.PendingIntentRecord.sendInner(PendingIntentRecord.java:526)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.PendingIntentRecord.sendWithResult(PendingIntentRecord.java:311)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.am.ActivityManagerService.sendIntentSender(ActivityManagerService.java:5373)
11-29 07:37:53.353   573   678 E ActivityManager:   at android.app.PendingIntent.sendAndReturnResult(PendingIntent.java:1012)
11-29 07:37:53.353   573   678 E ActivityManager:   at android.app.PendingIntent.send(PendingIntent.java:983)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.alarm.AlarmManagerService$DeliveryTracker.deliverLocked(AlarmManagerService.java:5544)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.alarm.AlarmManagerService.deliverAlarmsLocked(AlarmManagerService.java:4444)
11-29 07:37:53.353   573   678 E ActivityManager:   at com.android.server.alarm.AlarmManagerService$AlarmThread.run(AlarmManagerService.java:4755)
11-29 07:37:53.366   573   607 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
11-29 07:37:53.380   573   607 I ActivityManager: Killing 2127:com.android.onetimeinitializer/u0a82 (adj 975): empty #17
11-29 07:37:53.391   573   607 I ActivityManager: Killing 1646:com.android.managedprovisioning/u0a53 (adj 975): empty #18
11-29 07:37:53.392   573   607 I ActivityManager: Killing 2057:com.android.dynsystem:dynsystem/1000 (adj 985): empty #19
11-29 07:37:53.393   573   607 I ActivityManager: Killing 1813:com.android.cellbroadcastreceiver/u0a64 (adj 985): empty #20
11-29 07:37:53.394   573   607 I ActivityManager: Killing 2042:com.android.dynsystem/1000 (adj 995): empty #21
11-29 07:37:53.395   573   607 I ActivityManager: Killing 1328:com.android.deskclock/u0a94 (adj 995): empty #22
11-29 07:37:53.395   573   607 I ActivityManager: Killing 2013:com.android.contacts/u0a85 (adj 999): empty #23
11-29 07:37:53.396   573   607 I ActivityManager: Killing 1965:com.android.carrierconfig/u0a105 (adj 999): empty #24
11-29 07:37:53.397   573   607 I ActivityManager: Killing 1996:com.android.camera2/u0a91 (adj 999): empty #25
11-29 07:37:53.398   573   607 I ActivityManager: Killing 1980:com.android.calendar/u0a90 (adj 999): empty #26
11-29 07:37:53.399   573   607 I ActivityManager: Killing 1662:com.android.quicksearchbox/u0a93 (adj 999): empty #27
11-29 07:37:53.400   573   607 I ActivityManager: Killing 1926:com.android.traceur/u0a80 (adj 999): empty #28
11-29 07:37:53.401   573   607 I ActivityManager: Killing 1743:com.android.printspooler/u0a76 (adj 999): empty #29
11-29 07:37:53.402   573   607 I ActivityManager: Killing 1685:com.android.localtransport/1000 (adj 999): empty #30
11-29 07:37:53.402   573   607 I ActivityManager: Killing 1552:com.android.externalstorage/u0a48 (adj 999): empty #31
11-29 07:37:53.403   573   607 I ActivityManager: Killing 1507:com.android.provision/u0a102 (adj 999): empty #32
11-29 07:37:53.405   573   607 I ActivityManager: Killing 1442:com.android.documentsui/u0a59 (adj 999): empty #33
11-29 07:37:53.482   573   663 W DeviceIdleController: motion timeout went off and device isn't stationary
11-29 07:37:53.523   573   609 I libprocessgroup: Successfully killed process cgroup uid 10082 pid 2127 in 118ms
11-29 07:37:53.628   356   356 I Zygote  : Process 1442 exited due to signal 9 (Killed)
11-29 07:37:53.748  2592  2592 I BluetoothMetricsLogger: drainBufferedCounters().
11-29 07:37:53.897   356   356 I Zygote  : Process 1328 exited due to signal 9 (Killed)
11-29 07:37:53.897   356   356 I Zygote  : Process 1552 exited due to signal 9 (Killed)
11-29 07:37:53.898   356   356 I Zygote  : Process 1646 exited due to signal 9 (Killed)
11-29 07:37:53.898   356   356 I Zygote  : Process 1662 exited due to signal 9 (Killed)
11-29 07:37:53.899   356   356 I Zygote  : Process 1685 exited due to signal 9 (Killed)
11-29 07:37:53.899   356   356 I Zygote  : Process 1743 exited due to signal 9 (Killed)
11-29 07:37:53.899   356   356 I Zygote  : Process 1813 exited due to signal 9 (Killed)
11-29 07:37:53.899   356   356 I Zygote  : Process 1926 exited due to signal 9 (Killed)
11-29 07:37:53.900   356   356 I Zygote  : Process 1980 exited due to signal 9 (Killed)
11-29 07:37:53.900   356   356 I Zygote  : Process 1996 exited due to signal 9 (Killed)
11-29 07:37:53.900   356   356 I Zygote  : Process 2013 exited due to signal 9 (Killed)
11-29 07:37:53.900   356   356 I Zygote  : Process 2042 exited due to signal 9 (Killed)
11-29 07:37:53.915   356   356 I Zygote  : Process 2057 exited due to signal 9 (Killed)
11-29 07:37:53.921   356   356 I Zygote  : Process 1507 exited due to signal 9 (Killed)
11-29 07:37:53.923   356   356 I Zygote  : Process 2127 exited due to signal 9 (Killed)
11-29 07:37:53.929   356   356 I Zygote  : Process 1965 exited due to signal 9 (Killed)
11-29 07:37:53.954   573   609 I libprocessgroup: Successfully killed process cgroup uid 10053 pid 1646 in 0ms
11-29 07:37:53.960   573   609 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 2057 in 0ms
11-29 07:37:53.965   573   609 I libprocessgroup: Successfully killed process cgroup uid 10064 pid 1813 in 0ms
11-29 07:37:53.967   573   609 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 2042 in 0ms
11-29 07:37:53.969   573   609 I libprocessgroup: Successfully killed process cgroup uid 10094 pid 1328 in 0ms
11-29 07:37:53.971   573   609 I libprocessgroup: Successfully killed process cgroup uid 10085 pid 2013 in 0ms
11-29 07:37:53.973   573   609 I libprocessgroup: Successfully killed process cgroup uid 10105 pid 1965 in 0ms
11-29 07:37:53.978   573   609 I libprocessgroup: Successfully killed process cgroup uid 10091 pid 1996 in 0ms
11-29 07:37:54.064   573   609 I libprocessgroup: Successfully killed process cgroup uid 10090 pid 1980 in 0ms
11-29 07:37:54.068   573   609 I libprocessgroup: Successfully killed process cgroup uid 10093 pid 1662 in 0ms
11-29 07:37:54.070   573   609 I libprocessgroup: Successfully killed process cgroup uid 10080 pid 1926 in 0ms
11-29 07:37:54.072   573   609 I libprocessgroup: Successfully killed process cgroup uid 10076 pid 1743 in 0ms
11-29 07:37:54.074   573   609 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 1685 in 0ms
11-29 07:37:54.078   573   609 I libprocessgroup: Successfully killed process cgroup uid 10048 pid 1552 in 0ms
11-29 07:37:54.080   573   609 I libprocessgroup: Successfully killed process cgroup uid 10102 pid 1507 in 0ms
11-29 07:37:54.081   573   609 I libprocessgroup: Successfully killed process cgroup uid 10059 pid 1442 in 0ms
11-29 07:37:54.110   573  1565 W system_server: Long monitor contention with owner binder:573_18 (2535) at void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied()(ActivityManagerService.java:1481) waiters=6 in void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied() for 152ms
11-29 07:37:54.129   573   950 W system_server: Long monitor contention with owner binder:573_18 (2535) at void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied()(ActivityManagerService.java:1481) waiters=9 in void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied() for 170ms
11-29 07:38:00.083   849   953 D EGL_emulation: app_time_stats: avg=13497.16ms min=13497.16ms max=13497.16ms count=1
11-29 07:38:15.055     0     0 W healthd : battery l=100 v=5000 t=25.0 h=2 st=2 c=900000 fc=3000000 cc=10 chg=a
11-29 07:38:17.510  2778  2794 E TestRunner: failed: asFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-29 07:38:17.515  2778  2794 E TestRunner: ----- begin exception -----
11-29 07:38:17.516  2778  2794 E TestRunner: kotlinx.coroutines.TimeoutCancellationException: Timeout after 1m: <no message>
11-29 07:38:17.516  2778  2794 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt.receiveOrFail-dWUq8MI(Utils.kt:114)
11-29 07:38:17.516  2778  2794 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$1.invokeSuspend(Unknown Source:15)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:32)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
11-29 07:38:17.516  2778  2794 E TestRunner:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
11-29 07:38:17.516  2778  2794 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking(CoroutineUtilsSharedJvm.kt:22)
11-29 07:38:17.516  2778  2794 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking$default(CoroutineUtilsSharedJvm.kt:21)
11-29 07:38:17.516  2778  2794 E TestRunner:    at io.realm.kotlin.test.common.notifications.RealmNotificationsTests.asFlow(RealmNotificationsTests.kt:95)
11-29 07:38:17.516  2778  2794 E TestRunner:    at java.lang.reflect.Method.invoke(Native Method)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
11-29 07:38:17.516  2778  2794 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
11-29 07:38:17.516  2778  2794 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:128)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:27)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
11-29 07:38:17.516  2778  2794 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
11-29 07:38:17.516  2778  2794 E TestRunner:    at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
11-29 07:38:17.516  2778  2794 E TestRunner:    at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:444)
11-29 07:38:17.516  2778  2794 E TestRunner:    at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2361)
11-29 07:38:17.526  2778  2794 E TestRunner: ----- end exception -----
11-29 07:38:17.533  2778  2794 I TestRunner: finished: asFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)

All of the flaky tests seems to be centered around our global Realm notifications. I am starting to suspect that Core has a bug there somewhere. Maybe it is related to us doing empty writes, which Core in some cases do not treat as a change?

cmelchior commented 10 months ago

Another one that indicate it is the the flow changelistener not triggering: https://github.com/realm/realm-kotlin/actions/runs/7030468089

11-29 13:02:58.518  2677  2692 I TestRunner: started: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-29 13:02:58.620  2677  2692 I System.out: Received from realm1.asFlow(). Sending: io.realm.kotlin.notifications.internal.InitialRealmImpl@f73cc4
11-29 13:02:58.625  2677  2692 I System.out: Sent message from realm1.asFlow(): io.realm.kotlin.notifications.internal.InitialRealmImpl@f73cc4
11-29 13:02:58.628  2677  2692 I System.out: Received from realm2.asFlow(). Sending: io.realm.kotlin.notifications.internal.InitialRealmImpl@160c7ad
11-29 13:02:58.630  2677  2692 I System.out: Sent message from realm2.asFlow(): io.realm.kotlin.notifications.internal.InitialRealmImpl@160c7ad
11-29 13:03:00.311   879  1015 D EGL_emulation: app_time_stats: avg=60204.82ms min=60204.82ms max=60204.82ms count=1
11-29 13:03:03.900   879   934 D ControlsListingControllerImpl: Subscribing callback, service count: 0
11-29 13:03:03.961   879   934 D ControlsListingControllerImpl: Unsubscribing callback
11-29 13:03:08.026   576   694 D ActivityManager: freezing 1673 com.android.provision
11-29 13:03:16.986   576   694 D ActivityManager: freezing 1621 com.android.localtransport
11-29 13:03:17.153   576   694 D ActivityManager: freezing 1526 com.android.keychain
11-29 13:03:19.811   879  1015 D EGL_emulation: app_time_stats: avg=19493.48ms min=19493.48ms max=19493.48ms count=1
11-29 13:03:21.952   576   694 D ActivityManager: freezing 1587 com.android.externalstorage
11-29 13:03:22.450   576   694 D ActivityManager: freezing 1728 com.android.printspooler
11-29 13:03:22.787     0     0 W healthd : battery l=100 v=5000 t=25.0 h=2 st=2 c=900000 fc=3000000 cc=10 chg=a
11-29 13:03:33.119   576   698 E ActivityManager: Sending non-protected broadcast com.android.bluetooth.btservice.BLUETOOTH_COUNTER_METRICS_ACTION from system uid 1002 pkg com.android.bluetooth
11-29 13:03:33.119   576   698 E ActivityManager: java.lang.Throwable
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.ActivityManagerService.checkBroadcastFromSystem(ActivityManagerService.java:13550)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.ActivityManagerService.broadcastIntentLocked(ActivityManagerService.java:14268)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.ActivityManagerService.broadcastIntentInPackage(ActivityManagerService.java:14468)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.ActivityManagerService$LocalService.broadcastIntentInPackage(ActivityManagerService.java:16971)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.PendingIntentRecord.sendInner(PendingIntentRecord.java:526)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.PendingIntentRecord.sendWithResult(PendingIntentRecord.java:311)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.am.ActivityManagerService.sendIntentSender(ActivityManagerService.java:5373)
11-29 13:03:33.119   576   698 E ActivityManager:   at android.app.PendingIntent.sendAndReturnResult(PendingIntent.java:1012)
11-29 13:03:33.119   576   698 E ActivityManager:   at android.app.PendingIntent.send(PendingIntent.java:983)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.alarm.AlarmManagerService$DeliveryTracker.deliverLocked(AlarmManagerService.java:5544)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.alarm.AlarmManagerService.deliverAlarmsLocked(AlarmManagerService.java:4444)
11-29 13:03:33.119   576   698 E ActivityManager:   at com.android.server.alarm.AlarmManagerService$AlarmThread.run(AlarmManagerService.java:4755)
11-29 13:03:33.129   576   620 I DropBoxManagerService: add tag=system_server_wtf isTagEnabled=true flags=0x2
11-29 13:03:33.149   576   620 I ActivityManager: Killing 2137:com.android.carrierconfig/u0a105 (adj 965): empty #17
11-29 13:03:33.158   576   620 I ActivityManager: Killing 2149:com.android.onetimeinitializer/u0a82 (adj 975): empty #18
11-29 13:03:33.159   576   620 I ActivityManager: Killing 1544:com.android.managedprovisioning/u0a55 (adj 975): empty #19
11-29 13:03:33.160   576   620 I ActivityManager: Killing 2073:com.android.dynsystem:dynsystem/1000 (adj 985): empty #20
11-29 13:03:33.215   576   623 I libprocessgroup: Successfully killed process cgroup uid 10105 pid 2137 in 0ms
11-29 13:03:33.218   357   357 I Zygote  : Process 1544 exited due to signal 9 (Killed)
11-29 13:03:33.219   357   357 I Zygote  : Process 2073 exited due to signal 9 (Killed)
11-29 13:03:33.220   357   357 I Zygote  : Process 2137 exited due to signal 9 (Killed)
11-29 13:03:33.221   357   357 I Zygote  : Process 2149 exited due to signal 9 (Killed)
11-29 13:03:33.234   576   620 I ActivityManager: Killing 2060:com.android.dynsystem/1000 (adj 985): empty #21
11-29 13:03:33.278   576   623 I libprocessgroup: Successfully killed process cgroup uid 10082 pid 2149 in 0ms
11-29 13:03:33.280   576   623 I libprocessgroup: Successfully killed process cgroup uid 10055 pid 1544 in 0ms
11-29 13:03:33.281   576   623 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 2073 in 0ms
11-29 13:03:33.283   576   620 I ActivityManager: Killing 1344:com.android.deskclock/u0a98 (adj 995): empty #22
11-29 13:03:33.284   576   620 I ActivityManager: Killing 2021:com.android.contacts/u0a85 (adj 995): empty #23
11-29 13:03:33.285   576   620 I ActivityManager: Killing 2003:com.android.camera2/u0a88 (adj 999): empty #24
11-29 13:03:33.286   576   620 I ActivityManager: Killing 1795:com.android.calendar/u0a97 (adj 999): empty #25
11-29 13:03:33.287   576   620 I ActivityManager: Killing 1779:com.android.quicksearchbox/u0a95 (adj 999): empty #26
11-29 13:03:33.288   576   620 I ActivityManager: Killing 1901:com.android.traceur/u0a81 (adj 999): empty #27
11-29 13:03:33.325   576   623 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 2060 in 0ms
11-29 13:03:33.331   576   620 I ActivityManager: Killing 1728:com.android.printspooler/u0a77 (adj 999): empty #28
11-29 13:03:33.332   576   620 I ActivityManager: Killing 1526:com.android.keychain/1000 (adj 999): empty #29
11-29 13:03:33.333   576   620 I ActivityManager: Killing 1587:com.android.externalstorage/u0a48 (adj 999): empty #30
11-29 13:03:33.334   576   620 I ActivityManager: Killing 1673:com.android.provision/u0a100 (adj 999): empty #31
11-29 13:03:33.335   576   620 I ActivityManager: Killing 1621:com.android.localtransport/1000 (adj 999): empty #32
11-29 13:03:33.340   576   620 I ActivityManager: Killing 1461:com.android.documentsui/u0a63 (adj 999): empty #33
11-29 13:03:33.408   576  2295 W system_server: Long monitor contention with owner ActivityManager (620) at void com.android.server.am.BroadcastQueue.processNextBroadcast(boolean)(BroadcastQueue.java:1160) waiters=0 in void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied() for 146ms
11-29 13:03:33.466   576  1289 W system_server: Long monitor contention with owner ActivityManager (620) at void com.android.server.am.BroadcastQueue.processNextBroadcast(boolean)(BroadcastQueue.java:1160) waiters=1 in void com.android.server.am.ActivityManagerService$AppDeathRecipient.binderDied() for 204ms
11-29 13:03:33.536   576   623 I libprocessgroup: Successfully killed process cgroup uid 10098 pid 1344 in 0ms
11-29 13:03:33.539   576   623 I libprocessgroup: Successfully killed process cgroup uid 10085 pid 2021 in 0ms
11-29 13:03:33.542   576   623 I libprocessgroup: Successfully killed process cgroup uid 10088 pid 2003 in 0ms
11-29 13:03:33.546   576   623 I libprocessgroup: Successfully killed process cgroup uid 10097 pid 1795 in 0ms
11-29 13:03:33.549   576   623 I libprocessgroup: Successfully killed process cgroup uid 10095 pid 1779 in 0ms
11-29 13:03:33.558   357   357 I Zygote  : Process 1344 exited due to signal 9 (Killed)
11-29 13:03:33.559   357   357 I Zygote  : Process 1461 exited due to signal 9 (Killed)
11-29 13:03:33.560   357   357 I Zygote  : Process 1526 exited due to signal 9 (Killed)
11-29 13:03:33.561   357   357 I Zygote  : Process 1587 exited due to signal 9 (Killed)
11-29 13:03:33.562   357   357 I Zygote  : Process 1621 exited due to signal 9 (Killed)
11-29 13:03:33.563   357   357 I Zygote  : Process 1673 exited due to signal 9 (Killed)
11-29 13:03:33.564   357   357 I Zygote  : Process 1728 exited due to signal 9 (Killed)
11-29 13:03:33.565   357   357 I Zygote  : Process 1779 exited due to signal 9 (Killed)
11-29 13:03:33.566   357   357 I Zygote  : Process 1795 exited due to signal 9 (Killed)
11-29 13:03:33.567   357   357 I Zygote  : Process 1901 exited due to signal 9 (Killed)
11-29 13:03:33.568   357   357 I Zygote  : Process 2003 exited due to signal 9 (Killed)
11-29 13:03:33.569   357   357 I Zygote  : Process 2021 exited due to signal 9 (Killed)
11-29 13:03:33.570   357   357 I Zygote  : Process 2060 exited due to signal 9 (Killed)
11-29 13:03:33.573   576   610 W Looper  : Slow dispatch took 161ms android.ui h=com.android.server.am.ActivityManagerService$UiHandler c=com.android.server.am.UidObserverController$$ExternalSyntheticLambda0@de353b3 m=0
11-29 13:03:33.701   576   623 I libprocessgroup: Successfully killed process cgroup uid 10081 pid 1901 in 0ms
11-29 13:03:33.704   576   623 I libprocessgroup: Successfully killed process cgroup uid 10077 pid 1728 in 0ms
11-29 13:03:33.707   576   623 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 1526 in 0ms
11-29 13:03:33.709   576   623 I libprocessgroup: Successfully killed process cgroup uid 10048 pid 1587 in 0ms
11-29 13:03:33.712   576   623 I libprocessgroup: Successfully killed process cgroup uid 10100 pid 1673 in 0ms
11-29 13:03:33.721   576   610 W Looper  : Slow dispatch took 147ms android.ui h=com.android.server.am.ActivityManagerService$UiHandler c=com.android.server.am.UidObserverController$$ExternalSyntheticLambda0@de353b3 m=0
11-29 13:03:33.722   576   610 W Looper  : Slow delivery took 253ms android.ui h=com.android.server.am.ActivityManagerService$UiHandler c=null m=32
11-29 13:03:33.741   576   610 W Looper  : Drained
11-29 13:03:33.766   576   623 I libprocessgroup: Successfully killed process cgroup uid 1000 pid 1621 in 0ms
11-29 13:03:33.771   576   623 I libprocessgroup: Successfully killed process cgroup uid 10063 pid 1461 in 0ms
11-29 13:03:33.778  2486  2486 I BluetoothMetricsLogger: drainBufferedCounters().
11-29 13:03:33.825   576   684 W DeviceIdleController: motion timeout went off and device isn't stationary
11-29 13:03:58.697  2677  2692 E TestRunner: failed: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
11-29 13:03:58.701  2677  2692 E TestRunner: ----- begin exception -----
11-29 13:03:58.703  2677  2692 E TestRunner: kotlinx.coroutines.TimeoutCancellationException: Timeout after 1m: Did not receive Update event on Channel 1
11-29 13:03:58.703  2677  2692 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt.receiveOrFail-dWUq8MI(Utils.kt:114)
11-29 13:03:58.703  2677  2692 E TestRunner:    at io.realm.kotlin.test.util.UtilsKt$receiveOrFail$1.invokeSuspend(Unknown Source:15)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.internal.ScopeCoroutine.afterResume(Scopes.kt:32)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.AbstractCoroutine.resumeWith(AbstractCoroutine.kt:102)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:46)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:104)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:280)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
11-29 13:03:58.703  2677  2692 E TestRunner:    at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source:1)
11-29 13:03:58.703  2677  2692 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking(CoroutineUtilsSharedJvm.kt:22)
11-29 13:03:58.703  2677  2692 E TestRunner:    at io.realm.kotlin.internal.platform.CoroutineUtilsSharedJvmKt.runBlocking$default(CoroutineUtilsSharedJvm.kt:21)
11-29 13:03:58.703  2677  2692 E TestRunner:    at io.realm.kotlin.test.common.notifications.RealmNotificationsTests.cancelAsFlow(RealmNotificationsTests.kt:126)
11-29 13:03:58.703  2677  2692 E TestRunner:    at java.lang.reflect.Method.invoke(Native Method)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
11-29 13:03:58.703  2677  2692 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunBefores.evaluate(RunBefores.java:80)
11-29 13:03:58.703  2677  2692 E TestRunner:    at androidx.test.internal.runner.junit4.statement.RunAfters.evaluate(RunAfters.java:61)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:128)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.Suite.runChild(Suite.java:27)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
11-29 13:03:58.703  2677  2692 E TestRunner:    at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
11-29 13:03:58.703  2677  2692 E TestRunner:    at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:56)
11-29 13:03:58.703  2677  2692 E TestRunner:    at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:444)
11-29 13:03:58.703  2677  2692 E TestRunner:    at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2361)
11-29 13:03:58.711  2677  2692 E TestRunner: ----- end exception -----
11-29 13:03:58.726  2677  2692 I TestRunner: finished: cancelAsFlow(io.realm.kotlin.test.common.notifications.RealmNotificationsTests)
cmelchior commented 10 months ago

I think I found the root cause.

This was the code in RealmImpl:

    override fun asFlow(): Flow<RealmChange<Realm>> = scopedFlow {
        notifierFlow.onStart { emit(InitialRealmImpl(this@RealmImpl)) }
    }

And this is the docs for onStart()

Returns a flow that invokes the given action before this flow starts to be collected.
The action is called before the upstream flow is started, so if it is used with a SharedFlow there is no guarantee that emissions from the upstream flow that happen inside or immediately after this onStart action will be collected (see onSubscription for an alternative operator on shared flows).

This is exactly the case we have here. By using asStart() there was no guarantee that the underlying Notifier Realm was started and the Realm changelistener was attached, but we still emitted the InitialRealm event.

This caused our tests to continue, doing a write, which was then missed by the notifier because it was still starting up when the write completed.

This is supported by these kinds of logs I got from the failed runs:

12-08 18:27:52.947  2458  2474 I TestRunner: started: initialVersionDereferencedAfterFirstWrite(io.realm.kotlin.test.common.VersionTrackingTests)
12-08 18:27:53.070  2458  4556 I System.out: Register realmChange callback: 158292677 // Writer Realm
12-08 18:27:53.113  2458  4556 I System.out: onRealmChanged triggered: 158292677
12-08 18:27:53.121  2458  4556 I System.out: onRealmChanged in WriterRealm was called
12-08 18:27:53.132  2458  4555 I System.out: Register realmChange callback: 191880218 // Notifier Realm
12-08 18:28:53.139  2458  4556 I System.out: Remove realmChange callback: 158292677
12-08 18:28:53.149  2458  4555 I System.out: Remove realmChange callback: 191880218
12-08 18:28:53.176  2458  2474 E TestRunner: failed: initialVersionDereferencedAfterFirstWrite(io.realm.kotlin.test.common.VersionTrackingTests)

Switching to onSubscription should fix it:

Returns a flow that invokes the given action after this shared flow starts to be collected (after the subscription is registered).
The action is called before any value is emitted from the upstream flow to this subscription but after the subscription is established. It is guaranteed that all emissions to the upstream flow that happen inside or immediately after this onSubscription action will be collected by this subscription.

I also discovered this issue that describes the problem in other similar cases: https://github.com/Kotlin/kotlinx.coroutines/issues/1758