가끔만 실패하는 테스트는 왜 생길까

제 컴퓨터에서는 항상 통과하는데 CI에서는 가끔 실패하는 테스트가 있었습니다. 실패할 때 남는 말은 missed message #0 한 줄이었습니다. 이 실패는 apache/pulsar#26683에 정리해 두었습니다. 다시 받아야 할 message를 하나도 받지 못했다는 뜻입니다.

이런 테스트를 flaky test라고 부릅니다. 이 글에서는 그 테스트가 왜 가끔만 실패했는지, 그리고 제 컴퓨터에서 한 번도 재현하지 못한 문제를 어떻게 분석했는지 적습니다.

테스트가 하려던 일

이 테스트는 consumer가 ack를 보낸 직후에 재전송이 끼어드는 상황을 확인합니다. 순서는 이렇습니다.

consumer가 “여기까지 받았다"는 cumulative ack를 보냅니다.
ack가 끝났다는 것을 consumer가 알아채기 직전에, 테스트가 broker 쪽 cursor를 맨 앞으로 되감습니다.
되감았으니 message가 처음부터 다시 옵니다.

테스트가 기대하는 순서는 “ack가 먼저, 되감기가 나중"입니다.

나중에 시킨 일이 먼저 도착했습니다

ack와 되감기는 가는 길이 다릅니다.

동작	가는 길
ack	consumer가 연결에 써 넣고, 네트워크를 거쳐 broker가 받아서 처리
되감기	테스트가 같은 process 안의 broker 객체를 직접 호출

테스트 코드에서는 ack를 먼저 호출하고 되감기를 나중에 호출합니다. 하지만 ack는 “연결에 써 넣었다"까지만 끝난 상태입니다. broker가 그것을 받아 처리했는지는 알 수 없습니다. 되감기는 네트워크를 거치지 않으니 컴퓨터가 바쁠 때는 되감기가 ack를 앞질러 도착합니다.

코드에 적힌 순서와 상대가 받는 순서는 같지 않을 수 있습니다.

cursor는 도착한 순서대로 처리합니다. 되감기가 먼저, ack가 나중에 적용되면 ack가 되감기를 덮어써 버립니다. 그러면 cursor는 다시 맨 끝을 가리키고 다시 올 message는 없습니다. 그래서 missed message #0이 나옵니다.

재현하지 못한 문제를 분석한 방법

제 컴퓨터에서는 CPU를 가득 채운 상태로 돌려도 이 순서가 한 번도 나오지 않았습니다. 그래서 CI에서 실패한 실행의 broker log와 통과한 실행의 log를 나란히 놓고 비교했습니다.

통과한 실행에는 Reset readPosition ... 줄이 있었습니다. 되감기가 읽는 위치를 바꿨다고 남기는 줄입니다. 실패한 실행에는 그 줄이 없었습니다. 되감기 호출 자체는 정상으로 끝났다고 나오는데 실제 위치는 바뀌지 않았습니다. 이 차이에서 “되감기가 ack보다 먼저 들어가서 묻혔다"는 설명을 세울 수 있었습니다.

기다려야 할 것을 기다리게 했습니다

고친 곳은 테스트 코드의 이 부분입니다. 되감기 전에 ack가 broker에 실제로 반영되고 저장될 때까지 기다립니다.

V5StreamConsumerAckWatermarkTest.java85~97행

 impl.beforeAckWatermarkUpdateHook = () -> {
     impl.beforeAckWatermarkUpdateHook = null;
     try {
+        var cursor = brokerSub.getCursor();
+        Awaitility.await().untilAsserted(() -> {
+            // 밀린 message가 0이면 ack가 반영된 것
+            assertEquals(subscriptionBacklog(topic, subscription), 0L);
+            // 저장된 위치가 현재 위치와 같으면 ack가 저장까지 끝난 것
+            assertEquals(cursor.getPersistentMarkDeletedPosition(),
+                    cursor.getMarkDeletedPosition());
+        });
         // 이제 ack를 앞지를 수 없다
         brokerSub.resetCursor(PositionFactory.EARLIEST).get(10, TimeUnit.SECONDS);
         receiveAll(consumer, n);

Thread.sleep()으로 잠깐 쉬게 하는 방법도 있지만 쓰지 않았습니다. 얼마나 쉬어야 충분한지 알 수 없고 바쁜 컴퓨터에서는 또 모자랄 수 있기 때문입니다. 시간을 기다리는 대신 상태를 기다리면 빠른 컴퓨터에서는 바로 지나가고 느린 컴퓨터에서는 필요한 만큼 기다립니다.

확인한 것과 확인하지 못한 것

고친 뒤 CPU를 가득 채운 상태에서 8번 돌려 8번 모두 통과했습니다.

다만 고치기 전의 실패를 제 컴퓨터에서 재현한 것은 아닙니다. 그래서 “실패가 사라졌다"를 직접 보이지는 못했습니다. 대신 log로 세운 설명에 맞춰 순서를 고정했습니다. 이 점은 변경 설명에도 그대로 적었습니다.

마치며

flaky test를 만나면 “가끔 실패하니 다시 돌리자"로 넘어가기 쉽습니다. 이번에 따라가 보니 원인은 운이 아니었습니다. 서로 다른 길로 가는 두 동작의 순서를 테스트가 보장하지 않았습니다.

테스트에서 “A 다음에 B"를 확인하고 싶다면 A를 호출하는 것만으로는 부족합니다. A가 끝났는지 확인한 다음에 B를 해야 한다는 것을 배웠습니다.