How do I properly fork coroutines? I've got this c...

# coroutines

[reactormonk]

How do I properly fork coroutines? I've got this code:

suspend fun reloadData() {
        try {
            Log.d(TAG, "Sup4")
            delay(500)
            Log.d(TAG, "Sup4+")
            val feedWithVideos = dao.getRssFeedWithUnorderedVideos(url)
            Log.d(TAG, "Sup4++, feedWithVideos: $feedWithVideos")
            data = feedWithVideos.let { feed ->
                feed.copy(
                    feedPosition = feed.feedPosition,
                    videos = feed.videos.sortedByDescending { it.pubDate }
                )
            }
            Log.d(TAG, "Sup5")
            Log.d(TAG, "Reloaded, data: $data")
        } catch (e: Exception) {
            Log.e(TAG, "Exception in reloadData: ", e)
        }
    }

Which I'm calling via

LaunchedEffect(false) {
        Log.d(TAG, "Sup3")
        reloadData()
        val feedData = getNewestFeed(url).sortedByDescending { it.pubDate }
        if (data.videos.firstOrNull() != feedData.firstOrNull()) {
            dao.insertAll(*feedData.toTypedArray())
            dao.deletePosition(url)
            reloadData()
        }
    }

Which then hangs on the first delay ("Sup4+" doesn't show up), because getNewestFeed blocks (haven't found a coroutine-enabled HTTP client).

[Joffrey]

haven't found a coroutine-enabled HTTP client

Ktor?

[CLOVIS]

Which then hangs on the first delay

I don't see anything that could block in your example before the "Sup4+" message, are you sure you showed the entire thing?

[Joffrey]

because getNewestFeed blocks

I'm not sure why this call would affect the display of Sub4+ in your case. reloadData is suspending and is called before getNewestFeed, so getNewestFeed shouldn't be called before reloadData is done and returns

[CLOVIS]

The only way in your example that Sup4+ doesn't get printed, is if an exception is thrown

[Joffrey]

By the way, try-catch with the very general Exception is a bad idea. In general, but also especially in coroutines, because CancellationException is an exception used by coroutines to propagate cancellation, and it shouldn't be caught. Even if that's not the cause of your problem here (please confirm the exception handling log is not printed), it should still be fixed

[reactormonk]

Yeah, no exception handling here. The try/catch is only for debugging purposes

[CLOVIS]

Just to insist, @Joffrey is right, the catch (e: Exception) is a bug, do not keep it in prod

[Joffrey]

The try/catch is only for debugging purposes

Even in that case, I'd suggest adding throw e just after the log, so your logging is "transparent"

[reactormonk]

More generally, what should I catch for a more general? Is there a AsyncException / Exception like in Haskell?

[CLOVIS]

You should never catch anything general, you should only catch exceptions that you know the function you're calling throws

[reactormonk]

I'll take a look at ktor and see if that fixes it. The http call fails, so that might be canceling the coroutine

[Joffrey]

The http call fails

Which one? Because as we said getNewestFeed shouldn't even be called before Sup4+ is printed in your case

[CLOVIS]

Maybe your logging is delayed somehow?

[reactormonk]

The one inside getNewestFeed

[reactormonk]

I'm running the test inside robolectric via ShadowLog.stream = System.out // Redirect Logcat to console, maybe that affects things?

[Joffrey]

Are you sharing the exact code you have? Because I don't see how that call can happen at all. Maybe add a log between reloadData and getNewestFeed to confirm that this doesn't happen

[Joffrey]

maybe that affects things?

I can't answer that, I'm not familiar with this tooling

[reactormonk]

I removed the whole getNewestFeed and reran everything

[reactormonk]

... no changes. Log output:

D/RssNewsActivity: Sup1
I/ExoPlayerImpl: Init 11873dbb [AndroidXMedia3/1.1.0] [robolectric, robolectric, robolectric, 33]
D/RssNewsActivity: Sup2
D/RssNewsActivity: Sup3
D/RssNewsActivity: Sup4
0

[CLOVIS]

Can you show the exact code you're running?

[reactormonk]

@Composable
fun RssNewsCompose(dao: RssFeedDao, url: HttpUrl, exoPlayerBuilder: (Context) -> ExoPlayer) {
    val TAG = "RssNewsActivity"
    var data by remember { mutableStateOf(RssFeedWithVideos(null, listOf())) }

    suspend fun reloadData() {
        Log.d(TAG, "Sup4")
        delay(500)
        Log.d(TAG, "Sup4+")
        val feedWithVideos = dao.getRssFeedWithUnorderedVideos(url)
        Log.d(TAG, "Sup4++, feedWithVideos: $feedWithVideos")
        data = feedWithVideos.let { feed ->
            feed.copy(
                feedPosition = feed.feedPosition,
                videos = feed.videos.sortedByDescending { it.pubDate }
            )
        }
        Log.d(TAG, "Sup5")
        Log.d(TAG, "Reloaded, data: $data")
    }

    Log.d(TAG, "Sup1")
    AutoPlayPlaylist(data = data, dao = dao, exoPlayerBuilder = exoPlayerBuilder)

    Log.d(TAG, "Sup2")
    LaunchedEffect(false) {
        Log.d(TAG, "Sup3")
        reloadData()
//        val feedData = getNewestFeed(url).sortedByDescending { it.pubDate }
//        if (data.videos.firstOrNull() != feedData.firstOrNull()) {
//            dao.insertAll(*feedData.toTypedArray())
//            dao.deletePosition(url)
//            reloadData()
//        }
    }
}

The test:

@RunWith(RobolectricTestRunner::class)
//@Config(sdk = [33], shadows = [ ShadowMediaMetricsManager::class ])
@Config(sdk = [33])
class MediathekKtTest {

    private lateinit var database: AppDatabase
    val context: Context = ApplicationProvider.getApplicationContext<Context>()

    @Before
    fun setUp() {
        System.setProperty("kotlinx.coroutines.debug", "")
        ShadowLog.stream = System.out // Redirect Logcat to console
    }

    private fun refreshDB() {
        database = Room.inMemoryDatabaseBuilder(context, AppDatabase::class.java)
            .build()
    }

    @get:Rule
    val composeTestRule = createComposeRule()

    @get:Rule
    val globalTimeout: SharedTimeOut = SharedTimeOut.seconds(5)

    val port = 10023
    @OptIn(ExperimentalTime::class)
    @Test
    fun testBasicRss() {
        refreshDB()
        val server = static(ResourceLoader.Directory("media")).asServer(SunHttp(port)).start()
        // ExoPlayer requires a media_metrics component, not provided by robolectric
        var exo: ExoPlayer? = null

        val capturing = CapturingRenderersFactory(context)

        ShadowLog.stream = System.out // Redirect Logcat to console
        val appShadow = shadowOf(RuntimeEnvironment.getApplication())
        appShadow.setSystemService("media_metrics", mock<MediaMetricsManager> {
            on { createPlaybackSession() } doReturn ( mock {} )
        })

        composeTestRule.setContent {
            RssNewsCompose(database.rssFeedVideoDao(), "<http://localhost>:$port".toHttpUrl()) { context ->
                ExoPlayer.Builder(context, capturing).build().also { exo = it }
            }
        }

        runBlocking {
            println(exo?.mediaItemCount)
            while(exo?.isPlaying == false) {
                println("Not Playing...")
                delay(500)
            }
            while(exo?.isPlaying == true) {
                println("Playing...")
                delay(500)
            }
        }

        composeTestRule.waitForIdle()

        val dumper = Dumper()

        capturing.dump(dumper)
        println("***")
        println(dumper.toString())
        println("***")

        val serializer = Persister()
        val ijLog = serializer.read(IjLog::class.java, dumper.toString())
        println(ijLog)

        server.stop()
        exo?.release()
    }
}

[reactormonk]

I'm running the testBasicRss test only.

[CLOVIS]

Maybe it gets cancelled because of your 5 seconds timeout?

[CLOVIS]

Btw, you should use runTest instead of runBlocking so delays are skipped

[Joffrey]

you should use runTest instead of runBlocking so delays are skipped

Delay-skipping is sometimes undesirable if the SUT interacts with other timed systems that don't get the same virtual time injected into them (e.g. if they are separate processes, like a docker server, or if they simply have their own non-overridden production coroutine scope)

[reactormonk]

It should be faster than 5 seconds. It's reading from an in-memory Room DB.

[Joffrey]

Maybe it gets cancelled because of your 5 seconds timeout?

But wouldn't that still show the exception handling log? (Unless Log.d became suspending somewhere in the last 10 years, of course, which I wouldn't be aware of)

[reactormonk]

D/RssNewsActivity: Sup1
I/ExoPlayerImpl: Init 11873dbb [AndroidXMedia3/1.1.0] [robolectric, robolectric, robolectric, 33]
D/RssNewsActivity: Sup2
D/RssNewsActivity: Sup3
D/RssNewsActivity: Sup4
0
Not Playing...
Not Playing...
Not Playing...
Not Playing...
D/LifecycleMonitor: Lifecycle status change: androidx.activity.ComponentActivity@4e8c368c in: PAUSED
V/ActivityScenario: Update currentActivityStage to PAUSED, currentActivity=androidx.activity.ComponentActivity@4e8c368c
D/LifecycleMonitor: Lifecycle status change: androidx.activity.ComponentActivity@4e8c368c in: STOPPED
V/ActivityScenario: Update currentActivityStage to STOPPED, currentActivity=androidx.activity.ComponentActivity@4e8c368c
I/ExoPlayerImpl: Release 11873dbb [AndroidXMedia3/1.1.0] [robolectric, robolectric, robolectric, 33] [media3.common, media3.exoplayer, media3.decoder]
D/LifecycleMonitor: Lifecycle status change: androidx.activity.ComponentActivity@4e8c368c in: DESTROYED
V/ActivityScenario: Update currentActivityStage to DESTROYED, currentActivity=null
I/Choreographer: Skipped 1000000 frames!  The application may be doing too much work on its main thread.

test timed out after 5000 milliseconds
org.junit.runners.model.TestTimedOutException: test timed out after 5000 milliseconds

So something is blocking somewhere

[CLOVIS]

It could be cancelled before the try

[Joffrey]

Right, a possibility. But then reactormonk wouldn't be able to reproduce as consistently as it appears

[reactormonk]

On the runTest vs. runBlocking - I explicitly changed it, so I can use delays when required.

[Joffrey]

@reactormonk not sure what you mean by that. runTest is very good at testing delay mechanisms without actually spending that time in tests. But yes, it must be handled with care. And if you have problems like the one you have right now, I would probably switch to runBlocking during the investigation just to check if that's not an issue in the test machinery 😆

[reactormonk]

Aye, makes sense.

[reactormonk]

Is there a way I can figure out where exactly things are blocking? Because something somewhere is blocking.

[reactormonk]

Ok wtf. Adding a custom context made it progress to Sup4+

val composeTestRule = createComposeRule(CoroutineName("Test") + Dispatchers.Default)

[Joffrey]

Well, LaunchedEffect launches your code in some coroutine scope. I'm not familiar with Compose, especially on Android, so I can't elaborate on that, but that scope might have a single-threaded context. If you use this same scope in multiple places, and some things do block the thread, then it may prevent other unrelated coroutines from running. You should make sure that calls that are potentially blocking are called on the IO dispatcher to avoid this kind of starvation.

From what I can see with your change, you're overriding the context used by the compose component container, making it multi-threaded (because of Dispatchers.Default), so that would solve such problems

[reactormonk]

The default coroutine context is EmptyCoroutineContext.