[Kotlin] Coroutine 테스트 디버깅 후기

3달 전에 이런 글을 쓴 적이 있다.

[Kotlin] 코루틴의 실행 순서와 테스트 코드

위의 글에서 언급된 ``ViewModel`` 테스트는 여전히 해결되지 않았다. 실행할 때마다 결과가 달라지는 테스트라니.. 심지어 원격 빌드에서도 실패하는 바람에 빌드가 멈춘 적도 있다.

 

하지만 7월의 마지막 주말, 바로 오늘, 끈질기게 나를 물고 늘어지던 버그를 바로 오늘 해결했다. 이 글에서는 문제 상황과 문제를 풀기 위한 나의 눈물겨운 싸움을 기록하려 한다.

문제

문제의 그 테스트 코드이다.

@Test
fun onTodayWordCheckboxChange_CheckPersistence() = runTest {
    // 1
    val todayWord = TestSampleData.getSampleTodayWord()
    todayWordPersistence.insertTodayWord(todayWord)
    // 2
    withDelay(testDispatcher) {
        viewModel.onTodayWordCheckboxChange(
            HomeTodayWord(
                todayWord.toTodayWordImpl(),
                TestSampleData.getSampleVocaImpl()
            )
        ).join()
    }
    // 3
    val todayWords = todayWordPersistence.loadTodayWords().first()
    val insertedTodayWord = todayWords.find { it.todayId == todayWord.todayId }
    // 4
    assertThat(insertedTodayWord).isNotNull
    assertThat(insertedTodayWord!!.checked).isNotEqualTo(todayWord.checked)
}

1. 테스트 데이터를 세팅한다. 샘플 ``TodayWord`` 객체를 하나 받아서 Persistence에 넣는다. 
2. (문제의 원인) ViewModel에서 특정 ``TodayWord`` 객체의 ``checked`` 속성을 toggle하여 저장한다.
3. 1번에서 넣었던 테스트 데이터를 Persistence에서 가져온다. ViewModel은 내부적으로 Persistence를 이용하여 데이터를 저장하므로, Persistence에 저장된 데이터 역시 ``checked``가 toggle됐어야 한다.
4. 테스트 데이터가 정상적으로 저장 및 수정됐는지 확인한다.

요약하자면 ViewModel이 Persistence를 이용하여 데이터를 올바르게 저장했는지 확인하는 테스트이다. 참고로 ``withDelay`` 함수는 ``withContext`` 안에서 코루틴을 실행한 후 일정 시간 delay하는 함수이다. 위의 글에서 결론 부분을 코드로 구현한 것이다.

suspend fun <T> withDelay(
    context: CoroutineContext,
    delayMilli: Long = 100L,
    block: suspend CoroutineScope.() -> T
): T = withContext(context) {
    val result = block()
    delay(delayMilli)
    return@withContext result
}

첫 번째 시도

순차적으로 실행된다면 당연히 통과하는 코드이지만, 코루틴이 존재하는 세상에서는 먼저 실행된 코루틴이 먼저 끝나지 않을 수도 있다. 즉 ViewModel의 작업이 assert 전에 완료된다고 확신할 수 없는 것이다.

 

그렇다면 ``delay`` 함수로 충분히 기다리면 되지 않을까? ``viewModel.onTodayWordCheckBoxChange`` 함수는 ``launch``를  호출하여 코루틴을 실행한다. ``launch``는 작업을 시작한 후 즉시 리턴하지만, ``withContext`` 안에서 ``delay``되는 동안 ``launch``가 작업을 마칠 수 있을 것이라고 추측했다.

 

하지만 틀렸다. 기다리는 시간을 다르게 해 봐도 테스트를 고칠 수 없었다. 테스트는 여전히 간헐적으로 성공하고, 간헐적으로 실패한다. ``delay``를 무시하는 ``runTest`` 때문이라고 생각할 수도 있겠지만, ``runBlocking``을 써도 똑같다.

 

뭔가 근본적인 문제가 있는 것 같다.

두 번째 시도

문제를 다시 생각해 보자.

 

테스트 객체가 들어간 시점에서의 데이터를 $A$, ViewModel의 작업이 완료되어 ``checked``가 토글된 데이터를 $B$라고 하자. 3번 과정에서 ``StateFlow.first()`` 함수를 호출하여 데이터를 가져오는데, ViewModel의 작업이 완료되었다면 $B$가, 완료되지 않았다면 $A$가 반환될 것이다.

 

그렇다면 $B$가 반환될 때까지 기다리면 되지 않을까? 조건에 맞는 데이터를 기다리는 ``Flow.first { ... }`` 함수를 이용하여 $B$를 기다리자. 시간 대신 데이터를 기다리는 것이다.

@Test
fun onTodayWordCheckboxChange_CheckPersistence() = testScope.runTest {
    val todayWord = TestSampleData.getSampleTodayWord()
    todayWordPersistence.insertTodayWord(todayWord)
    viewModel.onTodayWordCheckboxChange(
        HomeTodayWord(
            todayWord.toTodayWordImpl(),
            TestSampleData.getSampleVocaImpl()
        )
    )
    todayWordPersistence.loadTodayWords().first { todayWords ->
        val insertedTodayWord = todayWords.find { it.todayId == todayWord.todayId }!!
        insertedTodayWord.checked != todayWord.checked
    }
}

테스트는 성공하는 것처럼 보인다. 하지만 새로운 에러가 발생한다.

Unfinished coroutines found during the tear-down. Ensure that all coroutines are completed or cancelled by your test.
kotlinx.coroutines.test.UncompletedCoroutinesError: Unfinished coroutines found during the tear-down. Ensure that all coroutines are completed or cancelled by your test.

해석하면 테스트는 종료되었는데 테스트에서 실행한 코루틴 중 일부가 계속 실행되고 있다는 말이다. 어딘가에서 코루틴 누수가 일어나는 상황. 분명 ViewModel도 종료하고, ``runTest``도 제대로 종료했는데 뭐가 계속 실행된다는 거지?

 

4월달에 여기까지 수정한 후 3달 가까이 손을 놓고 있었다. 솔직히 반쯤 포기했었는데, 도서관에서 할 게 없어서 다시 한 번 도전하기로 했다.

 

그리고 바로 오늘.

세 번째 시도

테스트가 종료될 때 코루틴이 계속 실행되는 상황이라면, 테스트가 종료될 때 실행 중이던 모든 코루틴을 종료하면 된다. 구글링의 도움을 받아 테스트 rule을 작성하고, 테스트에 적용하였다.

class MainCoroutineRule(private val dispatcher: TestDispatcher) : TestWatcher(), CoroutineScope {
    override val coroutineContext: CoroutineContext = dispatcher + Job()

    override fun starting(description: Description?) {
        super.starting(description)
        Dispatchers.setMain(dispatcher)
    }

    // why this function doesn't executed?
    override fun finished(description: Description?) {
        super.finished(description)
        Dispatchers.resetMain()
        dispatcher.cancel()
    }

    override fun apply(base: Statement?, description: Description?) = object : Statement() {
        override fun evaluate() {
            this@MainCoroutineRule.cancel()
        }
    }
}

class ViewModelTest {
    
    @get:Rule
    var mainCoroutineRule = MainCoroutineRule(testDispatcher)
    
    // other tests
}

테스트가 종료될 때, 해당 시점에서 실행 중인 모든 코루틴을 종료하는 코드이다. 코드를 재사용하기 위해 JUnit4 rule로 작성하였다. JUnit5 대신 구버전인 4를 사용한 이유는 Robolectric을 사용하기 위해서이다.

 

테스트가 모두 통과한다. 혹시 몰라서 10번 반복해 봤는데, 단 하나의 테스트도 실패하지 않았다. 드디어 해결했구나.

의문

누수를 막을 수 있었던 결정적인 코드는 ``MainCoroutineRule.apply()``인데, 사실 작년부터 존재했던 ``finished`` 함수가 이미 같은 일을 하고 있다. 분명 ``finished()``에서 ``dispatcher.cancel()``을 호출하는데 뭐가 누수된다는 거지?

---

API 문서에 따르면 하나의 테스트가 끝날 때마다 (결과에 상관없이) ``finished()`` 함수가 호출돼야 하지만, 직접 확인해본 결과 전혀 실행되고 있지 않았다.

override fun finished(description: Description?) {
    println("finished?")
    super.finished(description)
    Dispatchers.resetMain()
    dispatcher.cancel()
}

테스트 4개를 실행했음에도 불구하고 ``finished?`` 문구가 전혀 출력되지 않았다. ``starting()`` 함수도 마찬가지였다. 결론적으로 ``dispatcher.cancel()``이 단 한 번도 실행되지 않고 있었다. 그러니 누수가 날 수밖에..

 

속았다!

 

반면 ``apply`` 함수는 테스트가 끝날 때마다 실제로 실행된다. 따라서 ``apply`` 함수에서 ``cancel()``을 호출하면 매 테스트가 끝날 때마다 아직 끝나지 않은 모든 코루틴을 종료한다. 이렇게 하면 코루틴 누수를 막을 수 있다.

 

의심이 부족했던 것이다. 디버깅의 기본은 출력이라고 배웠건만.. 

---

별개로 ``finished()`` 함수가 실행되지 않은 이유는 아직도 모르겠다. JUnit이 틀렸는가? 아니면 내 코드에 크고 비밀한 버그가 존재하는가? 

 

JUnit4의 rule과 같은 역할을 하는 JUnit5 extension의 함수는 정상적으로 실행된다. JUnit4의 문제인가..

/**
 * Test extension for JUnit5
 */
@OptIn(ExperimentalCoroutinesApi::class)
class MainCoroutineExtension(private val dispatcher: TestDispatcher) :
    BeforeEachCallback, AfterEachCallback {
    override fun beforeEach(context: ExtensionContext?) {
        println("beforeEach")
        Dispatchers.setMain(dispatcher)
    }

    override fun afterEach(context: ExtensionContext?) {
        dispatcher.cancel()
        Dispatchers.resetMain()
        println("afterEach")
    }
}

얘는 되는데..

휴.. 고쳤다

힘들었다. 아마 내 인생에서 가장 오래 디버깅한 사례가 아닐지..

 

그래도 비동기적으로 갱신되는 데이터를 테스트하는 방법을 알게 되었다. 다른 테스트도 고쳐야겠다.

 

코드의 잘못은 테스트가 판단하지만, 테스트의 잘못은 사람이 판단할 수밖에 없다. 테스트를 다룰 땐 정신 똑바로 차리자.

참고

Eliminating Coroutine leaks in tests