Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

CI test flakiness collection #11091

Closed
mikehardy opened this issue Apr 25, 2022 · 32 comments
Closed

CI test flakiness collection #11091

mikehardy opened this issue Apr 25, 2022 · 32 comments
Labels
CI Dev Development, testing & CI Good First Issue! Help Wanted Requesting Pull Requests from volunteers Stale

Comments

@mikehardy
Copy link
Member

mikehardy commented Apr 25, 2022

Reproduction Steps
  1. make any PR request or manually trigger testing run
  2. watch logs
Expected Result

Tests should succeed every single time unless there is a legitimate test failure

Actual Result

They flake sometimes.

The situation has been improved recently with #11032 but this issue will collect experiences after that merge to tack it down completely

@mikehardy
Copy link
Member Author

mikehardy commented Apr 25, 2022

Here is one I just saw:

https://github.com/ankidroid/Anki-Android/runs/6157540326?check_suite_focus=true#step:9:275


> Task :AnkiDroid:connectedPlayDebugAndroidTest
Apr 25, 2022 12:50:33 PM com.android.tools.utp.plugins.result.listener.gradle.GradleAndroidTestResultListener$configure$responseObserver$1 onError
SEVERE: recordTestResultEvent failed with an error: io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
Apr 25, 2022 12:50:33 PM io.grpc.internal.SerializingExecutor run
SEVERE: Exception while executing runnable io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed@7c945c49
io.grpc.StatusRuntimeException: UNAVAILABLE: io exception
	at io.grpc.Status.asRuntimeException(Status.java:533)
	at io.grpc.stub.ClientCalls$StreamObserverToCallListenerAdapter.onClose(ClientCalls.java:442)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at io.grpc.internal.CensusStatsModule$StatsClientInterceptor$1$1.onClose(CensusStatsModule.java:700)
	at io.grpc.PartialForwardingClientCallListener.onClose(PartialForwardingClientCallListener.java:39)
	at io.grpc.ForwardingClientCallListener.onClose(ForwardingClientCallListener.java:23)
	at io.grpc.ForwardingClientCallListener$SimpleForwardingClientCallListener.onClose(ForwardingClientCallListener.java:40)
	at io.grpc.internal.CensusTracingModule$TracingClientInterceptor$1$1.onClose(CensusTracingModule.java:399)
	at io.grpc.internal.ClientCallImpl.closeObserver(ClientCallImpl.java:500)
	at io.grpc.internal.ClientCallImpl.access$300(ClientCallImpl.java:65)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.close(ClientCallImpl.java:592)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl.access$700(ClientCallImpl.java:508)
	at io.grpc.internal.ClientCallImpl$ClientStreamListenerImpl$1StreamClosed.runInContext(ClientCallImpl.java:632)
	at io.grpc.internal.ContextRunnable.run(ContextRunnable.java:37)
	at io.grpc.internal.SerializingExecutor.run(SerializingExecutor.java:123)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base/java.lang.Thread.run(Thread.java:829)
Caused by: javax.net.ssl.SSLException: handshake timed out
	at io.netty.handler.ssl.SslHandler.handshake(...)(Unknown Source)

Completed successfully after re-run

Seen again once 20220430 or thereabouts https://github.com/ankidroid/Anki-Android/runs/6227166753?check_suite_focus=true#step:9:274 on #11162

@mikehardy mikehardy added Dev Development, testing & CI CI labels Apr 25, 2022
@mikehardy mikehardy changed the title CI Emulator test flakiness collection CI test flakiness collection May 10, 2022
@mikehardy
Copy link
Member Author

This just popped up on unit tests, first time I've seen it. Logging for frequency analysis over time

https://github.com/ankidroid/Anki-Android/runs/6372125564?check_suite_focus=true#step:7:143

SchedTest > test_newBoxes_v1 FAILED
    java.lang.NullPointerException
        at com.ichi2.libanki.template.ParsedNode.parse_inner(ParsedNode.java:88)
        at com.ichi2.libanki.Model.parsedNodes(Model.java:128)
        at com.ichi2.libanki.Models._availStandardOrds(Models.java:1014)
        at com.ichi2.libanki.Models.availOrds(Models.java:1006)
        at com.ichi2.libanki.Collection.findTemplates(Collection.java:723)
        at com.ichi2.libanki.Collection.addNote(Collection.java:668)
        at com.ichi2.libanki.Collection.addNote(Collection.java:657)
        at com.ichi2.libanki.sched.SchedTest.test_newBoxes_v1(SchedTest.java:310)

From #11173

@mikehardy

This comment was marked as resolved.

@mikehardy

This comment was marked as outdated.

@mikehardy

This comment was marked as outdated.

@mikehardy
Copy link
Member Author

mikehardy commented May 18, 2022

These are failing for me semi-frequently locally as part of unit test on ubuntu

CollectionTaskSearchCardsTest > searchCardsNumberOfResultCount FAILED
    Wanted but not invoked:
    taskListener.onProgressUpdate(
        <Capturing argument>
    );
    -> at com.ichi2.async.TaskListener.onProgressUpdate(TaskListener.kt:44)

    However, there was exactly 1 interaction with this mock:
    taskListener.onPreExecute();
    -> at com.ichi2.async.CollectionTask.onPreExecute(CollectionTask.kt:140)
        at com.ichi2.async.TaskListener.onProgressUpdate(TaskListener.kt:44)
        at com.ichi2.async.CollectionTaskSearchCardsTest.searchCardsNumberOfResultCount(CollectionTaskSearchCardsTest.kt:53)

@mikehardy
Copy link
Member Author

The cache restore step has failed on macOS once recently and windows twice recently. I'm not sure 5mins is enough for that step.

@mikehardy

This comment was marked as outdated.

@mikehardy mikehardy added Help Wanted Requesting Pull Requests from volunteers Good First Issue! labels Jun 1, 2022
@mikehardy
Copy link
Member Author

windows unit test gradle cache restore timeout hit at 5 minutes, perhaps slacken. Tracking failure rate here.

@mikehardy

This comment was marked as outdated.

@mikehardy
Copy link
Member Author

mikehardy commented Jun 13, 2022

Some new ones, these are odd


ReviewerNoParamTest > drawerConflictsIfRight FAILED
    java.lang.AssertionError: 
    Expected: <true>
         but: was <false>
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:20)
        at org.hamcrest.MatcherAssert.assertThat(MatcherAssert.java:6)
        at com.ichi2.anki.ReviewerNoParamTest.drawerConflictsIfRight(ReviewerNoParamTest.kt:234)

CollectionTaskSearchCardsTest > searchCardsNumberOfResultCount FAILED
    Wanted but not invoked:
    taskListener.onProgressUpdate(
        <Capturing argument>
    );
    -> at com.ichi2.async.TaskListener.onProgressUpdate(TaskListener.kt:44)
    However, there was exactly 1 interaction with this mock:
    taskListener.onPreExecute();
    -> at com.ichi2.async.CollectionTask.onPreExecute(CollectionTask.kt:140)
        at com.ichi2.async.TaskListener.onProgressUpdate(TaskListener.kt:44)
        at com.ichi2.async.CollectionTaskSearchCardsTest.searchCardsNumberOfResultCount(CollectionTaskSearchCardsTest.kt:53)

Saw this one again 20220616

@thedroiddiv

This comment was marked as outdated.

@mikehardy

This comment was marked as outdated.

@thedroiddiv

This comment was marked as outdated.

@thedroiddiv

This comment was marked as outdated.

@mikehardy

This comment was marked as outdated.

@dae

This comment was marked as resolved.

@mikehardy

This comment was marked as resolved.

@mikehardy

This comment was marked as resolved.

@david-allison
Copy link
Member

Only seen locally (macOS):

After waiting for 60000 ms, the test coroutine is not completing
kotlinx.coroutines.test.UncompletedCoroutinesError: After waiting for 60000 ms, the test coroutine is not completing
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt$runTestCoroutine$3$3.invokeSuspend(TestBuilders.kt:342)
	(Coroutine boundary)
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt.runTestCoroutine(TestBuilders.kt:326)
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt$runTest$1$1.invokeSuspend(TestBuilders.kt:167)
	at kotlinx.coroutines.test.TestBuildersJvmKt$createTestResult$1.invokeSuspend(TestBuildersJvm.kt:13)
	Suppressed: org.robolectric.android.internal.AndroidTestEnvironment$UnExecutedRunnablesException: Main looper has queued unexecuted runnables. This might be the cause of the test failure. You might need a shadowOf(Looper.getMainLooper()).idle() call.
Caused by: kotlinx.coroutines.test.UncompletedCoroutinesError: After waiting for 60000 ms, the test coroutine is not completing
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt$runTestCoroutine$3$3.invokeSuspend(TestBuilders.kt:342)
	at app//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:284)
	at kotlinx.coroutines.BlockingCoroutine.joinBlocking(Builders.kt:85)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking(Builders.kt:59)
	at kotlinx.coroutines.BuildersKt.runBlocking(Unknown Source)
	at kotlinx.coroutines.BuildersKt__BuildersKt.runBlocking$default(Builders.kt:38)
	at kotlinx.coroutines.BuildersKt.runBlocking$default(Unknown Source)
	at kotlinx.coroutines.test.TestBuildersJvmKt.createTestResult(TestBuildersJvm.kt:12)
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt.runTest(TestBuilders.kt:166)
	at kotlinx.coroutines.test.TestBuildersKt.runTest(Unknown Source)
	at kotlinx.coroutines.test.TestBuildersKt__TestBuildersKt.runTest(TestBuilders.kt:154)
	at kotlinx.coroutines.test.TestBuildersKt.runTest(Unknown Source)
	at com.ichi2.anki.RobolectricTest.runTest(RobolectricTest.kt:627)
	at com.ichi2.anki.RobolectricTest.runTest$default(RobolectricTest.kt:622)
	at com.ichi2.anki.stats.AnkiStatsTaskHandlerTest.testCreateReviewSummaryStatistics(AnkiStatsTaskHandlerTest.kt:59)
	at java.base@11.0.12/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
	at java.base@11.0.12/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
	at java.base@11.0.12/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
	at java.base@11.0.12/java.lang.reflect.Method.invoke(Method.java:566)
	at app//org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at app//org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at app//org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at app//org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at app//org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
	at app//org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:27)
	at app//org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at app//org.robolectric.RobolectricTestRunner$HelperTestRunner$1.evaluate(RobolectricTestRunner.java:591)
	at app//org.robolectric.internal.SandboxTestRunner$2.lambda$evaluate$0(SandboxTestRunner.java:274)
	at app//org.robolectric.internal.bytecode.Sandbox.lambda$runOnMainThread$0(Sandbox.java:88)
	at java.base@11.0.12/java.util.concurrent.FutureTask.run(FutureTask.java:264)
	at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base@11.0.12/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at java.base@11.0.12/java.lang.Thread.run(Thread.java:829)

@dae
Copy link
Contributor

dae commented Sep 2, 2022

Can't reproduce, but does this help? Changed the test to exercise the non-null case, and removed the mutex in the process, as withCol should enforce single execution.

diff --git a/AnkiDroid/src/main/java/com/ichi2/anki/DeckPicker.kt b/AnkiDroid/src/main/java/com/ichi2/anki/DeckPicker.kt
index 7b0dab6df..c783889f5 100644
--- a/AnkiDroid/src/main/java/com/ichi2/anki/DeckPicker.kt
+++ b/AnkiDroid/src/main/java/com/ichi2/anki/DeckPicker.kt
@@ -2206,7 +2206,12 @@ open class DeckPicker :
             context.renderPage()
             // Update the mini statistics bar as well
             deckPicker?.launchCatchingTask {
-                AnkiStatsTaskHandler.createReviewSummaryStatistics(context.col, context.mReviewSummaryTextView)
+                val text = AnkiStatsTaskHandler.createReviewSummaryStatistics(context)
+                context.mReviewSummaryTextView.apply {
+                    this.text = text ?: ""
+                    visibility = View.VISIBLE
+                    invalidate()
+                }
             }
             Timber.d("Startup - Deck List UI Completed")
         }
diff --git a/AnkiDroid/src/main/java/com/ichi2/anki/stats/AnkiStatsTaskHandler.kt b/AnkiDroid/src/main/java/com/ichi2/anki/stats/AnkiStatsTaskHandler.kt
index f31d80d47..8cff1dc11 100644
--- a/AnkiDroid/src/main/java/com/ichi2/anki/stats/AnkiStatsTaskHandler.kt
+++ b/AnkiDroid/src/main/java/com/ichi2/anki/stats/AnkiStatsTaskHandler.kt
@@ -16,10 +16,13 @@
 package com.ichi2.anki.stats
 
 import android.R
+import android.content.Context
 import android.view.View
 import android.webkit.WebView
 import android.widget.ProgressBar
 import android.widget.TextView
+import com.ichi2.anki.CollectionManager.withOpenColOrNull
 import com.ichi2.libanki.Collection
 import com.ichi2.libanki.DeckId
 import com.ichi2.libanki.stats.Stats
@@ -129,43 +132,32 @@ class AnkiStatsTaskHandler private constructor(
 
         @JvmStatic
         suspend fun createReviewSummaryStatistics(
-            col: Collection,
-            view: TextView,
-            mainDispatcher: CoroutineDispatcher = Dispatchers.Main,
-            defaultDispatcher: CoroutineDispatcher = Dispatchers.IO
-        ): Unit = mutex.withLock {
-            withContext(defaultDispatcher) {
-                val todayStatString = if (!isActive || col.dbClosed) {
-                    Timber.d("Quitting DeckPreviewStatistics before execution")
-                    null
-                } else {
-                    Timber.d("Starting DeckPreviewStatistics")
-                    // eventually put this in Stats (in desktop it is not though)
-                    var cards: Int
-                    var minutes: Int
-                    /* cards, excludes rescheduled cards https://github.com/ankidroid/Anki-Android/issues/8592 */
-                    val query = "select sum(case when ease > 0 then 1 else 0 end), " +
-                        "sum(time)/1000 from revlog where id > " + (col.sched.dayCutoff - Stats.SECONDS_PER_DAY) * 1000
-                    Timber.d("DeckPreviewStatistics query: %s", query)
-                    col.db
-                        .query(query).use { cur ->
-                            cur.moveToFirst()
-                            cards = cur.getInt(0)
-                            minutes = (cur.getInt(1) / 60.0).roundToInt()
-                        }
-                    val res = view.resources
-                    val span = res.getQuantityString(com.ichi2.anki.R.plurals.in_minutes, minutes, minutes)
-                    res.getQuantityString(com.ichi2.anki.R.plurals.studied_cards_today, cards, cards, span)
-                }
-                todayStatString?.let {
-                    withContext(mainDispatcher) {
-                        view.apply {
-                            text = it
-                            visibility = View.VISIBLE
-                            invalidate()
-                        }
+            context: Context,
+        ): String? {
+            return withOpenColOrNull {
+                Timber.d("Starting DeckPreviewStatistics")
+                // eventually put this in Stats (in desktop it is not though)
+                var cards: Int
+                var minutes: Int
+                /* cards, excludes rescheduled cards https://github.com/ankidroid/Anki-Android/issues/8592 */
+                val query = "select sum(case when ease > 0 then 1 else 0 end), " +
+                        "sum(time)/1000 from revlog where id > " + (sched.dayCutoff - Stats.SECONDS_PER_DAY) * 1000
+                Timber.d("DeckPreviewStatistics query: %s", query)
+                db
+                    .query(query).use { cur ->
+                        cur.moveToFirst()
+                        cards = cur.getInt(0)
+                        minutes = (cur.getInt(1) / 60.0).roundToInt()
                     }
-                }
+                val res = context.resources
+                val span =
+                    res.getQuantityString(com.ichi2.anki.R.plurals.in_minutes, minutes, minutes)
+                res.getQuantityString(
+                    com.ichi2.anki.R.plurals.studied_cards_today,
+                    cards,
+                    cards,
+                    span
+                )
             }
         }
     }
diff --git a/AnkiDroid/src/test/java/com/ichi2/anki/stats/AnkiStatsTaskHandlerTest.kt b/AnkiDroid/src/test/java/com/ichi2/anki/stats/AnkiStatsTaskHandlerTest.kt
index be542c2d1..98442b49d 100644
--- a/AnkiDroid/src/test/java/com/ichi2/anki/stats/AnkiStatsTaskHandlerTest.kt
+++ b/AnkiDroid/src/test/java/com/ichi2/anki/stats/AnkiStatsTaskHandlerTest.kt
@@ -15,8 +15,11 @@
  ****************************************************************************************/
 package com.ichi2.anki.stats
 
+import android.content.Intent
 import android.widget.TextView
+import androidx.test.core.app.ActivityScenario
 import androidx.test.ext.junit.runners.AndroidJUnit4
+import com.ichi2.anki.DeckPicker
 import com.ichi2.anki.RobolectricTest
 import com.ichi2.anki.stats.AnkiStatsTaskHandler.Companion.createReviewSummaryStatistics
 import com.ichi2.annotations.NeedsTest
@@ -33,34 +36,18 @@ import org.mockito.Mockito.*
 import org.mockito.MockitoAnnotations
 import org.mockito.kotlin.whenever
 import java.util.concurrent.ExecutionException
+import kotlin.coroutines.resume
+import kotlin.coroutines.suspendCoroutine
+import kotlin.test.assertEquals
 
 @OptIn(ExperimentalCoroutinesApi::class)
 @RunWith(AndroidJUnit4::class)
 class AnkiStatsTaskHandlerTest : RobolectricTest() {
-    @Mock
-    private lateinit var mCol: Collection
-
-    @Mock
-    private lateinit var mView: TextView
-
-    private val testDispatcher = StandardTestDispatcher()
-
-    @Before
-    override fun setUp() {
-        super.setUp()
-        MockitoAnnotations.openMocks(this)
-        whenever(mCol.db).thenReturn(null)
-        whenever(mCol.dbClosed).thenReturn(true)
-    }
-
     @Test
-    @Throws(ExecutionException::class, InterruptedException::class)
-    @NeedsTest("explain this test")
-    fun testCreateReviewSummaryStatistics() = runTest(testDispatcher) {
-        verify(mCol, atMost(0))!!.db
-        createReviewSummaryStatistics(mCol, mView, testDispatcher, testDispatcher)
-        advanceUntilIdle()
-        verify(mCol, atLeast(0))!!.db
-        verify(mCol, atLeast(1))!!.dbClosed
+    fun testCreateReviewSummaryStatistics() = runTest {
+        val deckPicker = startActivityNormallyOpenCollectionWithIntent(
+            DeckPicker::class.java, Intent()
+        )
+        assertEquals(createReviewSummaryStatistics(deckPicker), "Studied 0 cards in 0 minutes today")
     }
 }

@david-allison
Copy link
Member

It's only occasionally flaky. The patch provided fails with:

expected: <null> but was: <Studied 0 cards in 0 minutes today>
Expected :null
Actual   :Studied 0 cards in 0 minutes today
<Click to see difference>

@dae
Copy link
Contributor

dae commented Sep 2, 2022

Whoops, I changed withCol to withOpenColOrNull at the last minute, so the assert should now check for null as well. Looks like I got the arg order on the assert wrong too.

@mikehardy
Copy link
Member Author

Some sort of windows flake in CI, using legacy schema

ReviewerTest > [SchedV2] > com.ichi2.anki.ReviewerTest.baseDeckName[SchedV2] FAILED
    net.ankiweb.rsdroid.exceptions.BackendInvalidInputException$BackendCollectionAlreadyOpenException: CollectionAlreadyOpen
        at net.ankiweb.rsdroid.exceptions.BackendInvalidInputException$Companion.fromInvalidInputError(BackendInvalidInputException.kt:34)
        at net.ankiweb.rsdroid.BackendException$Companion.fromError(BackendException.kt:114)
        at net.ankiweb.rsdroid.BackendKt.unpackResult(Backend.kt:323)
        at net.ankiweb.rsdroid.BackendKt.access$unpackResult(Backend.kt:1)
        at net.ankiweb.rsdroid.Backend$runMethodRaw$1.invoke(Backend.kt:130)
        at net.ankiweb.rsdroid.Backend$runMethodRaw$1.invoke(Backend.kt:[129](https://github.com/ankidroid/Anki-Android/actions/runs/3044985621/jobs/4905989460#step:8:130))
        at net.ankiweb.rsdroid.Backend.withBackend(Backend.kt:157)
        at net.ankiweb.rsdroid.Backend.runMethodRaw(Backend.kt:129)
        at anki.backend.GeneratedBackend.openCollectionRaw(GeneratedBackend.kt:26)
        at anki.backend.GeneratedBackend.openCollection(GeneratedBackend.kt:40)
        at net.ankiweb.rsdroid.Backend.openCollection(Backend.kt:109)
        at net.ankiweb.rsdroid.Backend.openCollection(Backend.kt:61)
        at com.ichi2.libanki.Storage.openDB$AnkiDroid_playDebug(Storage.kt:106)
        at com.ichi2.libanki.Collection.reopen(Collection.kt:457)
        at com.ichi2.libanki.Collection.reopen$default(Collection.kt:454)
        at com.ichi2.libanki.Collection.<init>(Collection.kt:187)
        at com.ichi2.libanki.Storage.collection(Storage.kt:88)
        at com.ichi2.anki.CollectionManager.ensureOpenInner(CollectionManager.kt:209)
        at com.ichi2.anki.CollectionManager.access$ensureOpenInner(CollectionManager.kt:36)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1$1.invoke(CollectionManager.kt:251)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1$1.invoke(CollectionManager.kt:250)
        at com.ichi2.anki.CollectionManager.blockForQueue(CollectionManager.kt:230)
        at com.ichi2.anki.CollectionManager.access$blockForQueue(CollectionManager.kt:36)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1.invoke(CollectionManager.kt:250)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1.invoke(CollectionManager.kt:249)
        at com.ichi2.anki.CollectionManager.logUIHangs(CollectionManager.kt:266)
        at com.ichi2.anki.CollectionManager.getColUnsafe(CollectionManager.kt:249)
        at com.ichi2.anki.CollectionHelper.getCol(CollectionHelper.kt:88)
        at com.ichi2.anki.RobolectricTest.getCol(RobolectricTest.kt:309)
        at com.ichi2.anki.ReviewerTest.setUp(ReviewerTest.kt:59)

@dae
Copy link
Contributor

dae commented Sep 14, 2022

Is there a way to get the logcat output from the failing test?

@mikehardy
Copy link
Member Author

Hmm - for the emulator test it's available as an artifact uploaded to the workflow which you may access by clicking on the summary, you can see an example here https://github.com/ankidroid/Anki-Android/actions/runs/3048002169

For the unit tests though (and the windows run is unit test only), not sure...

I made some provision for android logs to flow through here

When I run tests in Android Studio so it never occurred to me, but now that you mention it I've never seen them in my command-line runs, nor in the github actions logs

Looks like one of the configurables needs to be changed?

http://robolectric.org/configuring/
https://hanru-yeh.medium.com/ways-to-enable-robolectric-log-and-their-difference-eb99eaed2beb

Then something the output probably needs to be piped to a file somehow, as it will otherwise overwhelm the github actions output limits and make that window useless. Then upload the file similar to the androidTest strategy -

- name: Compress Emulator Log
if: always()
run: gzip -9 adb-log.txt
shell: bash
- name: Upload Emulator Log
uses: actions/upload-artifact@v3
if: always()
with:
name: ${{ matrix.api-level }}-${{ matrix.arch }}-${{matrix.target}}-${{matrix.first-boot-delay}}-${{matrix.iteration}}-adb_logs
path: adb-log.txt.gz

all looks a little fiddly to discover the exact way to get logcat flowing through to stdout or stderr, selecting which of those is best, and redirecting that to a file. Alternatively instead of binding the ShadowLog stream to System.out, maybe detecting an env var that's a desired filename and sending it there directly 🤔

@mikehardy
Copy link
Member Author

Looks like something racy that windows (just happens to be our slowest CI unit) appears to expose:

CardBrowserTest > checkDisplayOrderPersistence FAILED
    java.lang.AssertionError: Modification time must change. Actual: 1596783600410
        at org.junit.Assert.fail(Assert.java:89)
        at org.junit.Assert.failEquals(Assert.java:187)
        at org.junit.Assert.assertNotEquals(Assert.java:201)
        at com.ichi2.anki.CardBrowserTest.checkDisplayOrderPersistence(CardBrowserTest.kt:573)

@mikehardy
Copy link
Member Author

windows unit test just kicked out the one above ☝️ again plus this one:

ReviewerTest > [SchedV2] > com.ichi2.anki.ReviewerTest.baseDeckName[SchedV2] FAILED
    net.ankiweb.rsdroid.exceptions.BackendInvalidInputException$BackendCollectionAlreadyOpenException: CollectionAlreadyOpen
        at net.ankiweb.rsdroid.exceptions.BackendInvalidInputException$Companion.fromInvalidInputError(BackendInvalidInputException.kt:34)
        at net.ankiweb.rsdroid.BackendException$Companion.fromError(BackendException.kt:114)
        at net.ankiweb.rsdroid.BackendKt.unpackResult(Backend.kt:323)
        at net.ankiweb.rsdroid.BackendKt.access$unpackResult(Backend.kt:1)
        at net.ankiweb.rsdroid.Backend$runMethodRaw$1.invoke(Backend.kt:130)
        at net.ankiweb.rsdroid.Backend$runMethodRaw$1.invoke(Backend.kt:129)
        at net.ankiweb.rsdroid.Backend.withBackend(Backend.kt:157)
        at net.ankiweb.rsdroid.Backend.runMethodRaw(Backend.kt:[129](https://github.com/ankidroid/Anki-Android/actions/runs/3077680970/jobs/4972710497#step:8:130))
        at anki.backend.GeneratedBackend.openCollectionRaw(GeneratedBackend.kt:26)
        at anki.backend.GeneratedBackend.openCollection(GeneratedBackend.kt:40)
        at net.ankiweb.rsdroid.Backend.openCollection(Backend.kt:109)
        at net.ankiweb.rsdroid.Backend.openCollection(Backend.kt:61)
        at com.ichi2.libanki.Storage.openDB$AnkiDroid_playDebug(Storage.kt:106)
        at com.ichi2.libanki.Collection.reopen(Collection.kt:457)
        at com.ichi2.libanki.Collection.reopen$default(Collection.kt:454)
        at com.ichi2.libanki.Collection.<init>(Collection.kt:187)
        at com.ichi2.libanki.Storage.collection(Storage.kt:88)
        at com.ichi2.anki.CollectionManager.ensureOpenInner(CollectionManager.kt:209)
        at com.ichi2.anki.CollectionManager.access$ensureOpenInner(CollectionManager.kt:36)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1$1.invoke(CollectionManager.kt:251)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1$1.invoke(CollectionManager.kt:250)
        at com.ichi2.anki.CollectionManager.blockForQueue(CollectionManager.kt:230)
        at com.ichi2.anki.CollectionManager.access$blockForQueue(CollectionManager.kt:36)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1.invoke(CollectionManager.kt:250)
        at com.ichi2.anki.CollectionManager$getColUnsafe$1.invoke(CollectionManager.kt:249)
        at com.ichi2.anki.CollectionManager.logUIHangs(CollectionManager.kt:266)
        at com.ichi2.anki.CollectionManager.getColUnsafe(CollectionManager.kt:249)
        at com.ichi2.anki.CollectionHelper.getCol(CollectionHelper.kt:88)
        at com.ichi2.anki.RobolectricTest.getCol(RobolectricTest.kt:309)
        at com.ichi2.anki.ReviewerTest.setUp(ReviewerTest.kt:59)

@dae
Copy link
Contributor

dae commented Sep 20, 2022

In my latest PR CardBrowserTest > checkDisplayOrderPersistence FAILED happened on both Ubuntu and Windows; retrying now.

@dae
Copy link
Contributor

dae commented Sep 20, 2022

Failed again. Will push a probable fix.

@mikehardy
Copy link
Member Author

Strange one, only turning up on macOS runner unit test workflow (which gives me a hunch it is timing-related, as that runner is bare metal so should be faster, maybe exposing unexpected race conditions)

Caused by:
        java.lang.RuntimeException: GoogleAnalyticsExecutor is null
            at com.brsanthu.googleanalytics.request.GoogleAnalyticsRequest.sendAsync(GoogleAnalyticsRequest.java:[187](https://github.com/ankidroid/Anki-Android/actions/runs/3210447310/jobs/5247896009#step:8:188)1)
            at java.base/java.lang.invoke.MethodHandle.invokeWithArguments(MethodHandle.java:710)
            at com.brsanthu.googleanalytics.request.GoogleAnalyticsRequest.sendAsync(GoogleAnalyticsRequest.java:1870)
            at com.ichi2.anki.analytics.UsageAnalytics.sendAnalyticsException(UsageAnalytics.kt:276)
            at com.ichi2.anki.analytics.UsageAnalytics.sendAnalyticsException(UsageAnalytics.kt:252)
            at com.ichi2.anki.analytics.UsageAnalytics.installDefaultExceptionHandler$lambda$1(UsageAnalytics.kt:122)
            at org.acra.builder.ReportExecutor.handReportToDefaultExceptionHandler(ReportExecutor.java:102)
            at org.acra.reporter.ErrorReporterImpl.uncaughtException(ErrorReporterImpl.java:147)
            at com.ichi2.anki.analytics.UsageAnalytics.installDefaultExceptionHandler$lambda$1(UsageAnalytics.kt:127)
            at java.base/java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1055)
            at java.base/java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1050)
            at java.base/java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1050)
            at kotlinx.coroutines.CoroutineExceptionHandlerImplKt.handleCoroutineExceptionImpl(CoroutineExceptionHandlerImpl.kt:61)
            at kotlinx.coroutines.CoroutineExceptionHandlerKt.handleCoroutineException(CoroutineExceptionHandler.kt:33)
            at kotlinx.coroutines.DispatchedTask.handleFatalException(DispatchedTask.kt:146)
            at kotlinx.coroutines.internal.DispatchedContinuationKt.resumeCancellableWith(DispatchedContinuation.kt:383)
            at kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable(Cancellable.kt:30)
            at kotlinx.coroutines.intrinsics.CancellableKt.startCoroutineCancellable$default(Cancellable.kt:25)
            at kotlinx.coroutines.CoroutineStart.invoke(CoroutineStart.kt:110)
            at kotlinx.coroutines.AbstractCoroutine.start(AbstractCoroutine.kt:126)
            at kotlinx.coroutines.BuildersKt__Builders_commonKt.launch(Builders.common.kt:56)
            at kotlinx.coroutines.BuildersKt.launch(Unknown Source)
            at kotlinx.coroutines.BuildersKt__Builders_commonKt.launch$default(Builders.common.kt:47)
            at kotlinx.coroutines.BuildersKt.launch$default(Unknown Source)
            at com.ichi2.anki.CoroutineHelpersKt.launchCatchingTask(CoroutineHelpers.kt:122)
            at com.ichi2.anki.CoroutineHelpersKt.launchCatchingTask(CoroutineHelpers.kt:131)
            at com.ichi2.anki.CoroutineHelpersKt.launchCatchingTask$default(CoroutineHelpers.kt:128)
            at com.ichi2.anki.StudyOptionsFragment.refreshInterface(StudyOptionsFragment.kt:499)
            at com.ichi2.anki.StudyOptionsFragment.refreshInterface(StudyOptionsFragment.kt:483)

This one was of interest to me because that's my library, and I honestly cannot see how the executor there can ever be null.

UsageAnalytics must have been initialized or the analytics system itself would have null pointered earlier, so initialize must have been called, and in there the GoogleAnalyticsBuilder is used with a final build() call, which gets you a valid GoogleAnalyticsImpl.

When you ask for an analytics "hit" of some time (in this case an exception(), the GoogleAnalayticsImpl creates the correct GoogleAnalyticsRequest sub-type and sets itself into that request as the executor, in a fluent api call chain, and returns the result. So the executor should not be null ever

Yet...it is - could be related to this #12317 (@JvmStatic declaration removals) but unknown. I do not reproduce it locally on my macOS machines and it doesn't happen every time in CI either.

@github-actions
Copy link
Contributor

Hello 👋, this issue has been opened for more than 2 months with no activity on it. If the issue is still here, please keep in mind that we need community support and help to fix it! Just comment something like still searching for solutions and if you found one, please open a pull request! You have 7 days until this gets closed automatically

@github-actions github-actions bot added the Stale label Dec 12, 2022
@github-actions github-actions bot closed this as not planned Won't fix, can't repro, duplicate, stale Dec 19, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
CI Dev Development, testing & CI Good First Issue! Help Wanted Requesting Pull Requests from volunteers Stale
Projects
None yet
Development

No branches or pull requests

4 participants