[Spring, JPA] 50% 확률로 통과하는 LocalDateTime 테스트 코드 버그 수정하기

 

 

 

우테코 프로젝트에 슈뢰딩거의 테스트가 1개 있다. 운이 좋으면 50% 확률로 테스트에 성공하고, 운이 나쁘면 50% 확률로 테스트가 실패한다.

 

신기하게도 로컬에서는 단 한 번도 테스트가 실패한 적이 없었고, 서비스할 때도 전혀 문제 없었는데, Github Actions에서만 저렇게 빈번하게 실패한다.

 

 

 

1. 데이터 조회 방식

---

 

https://funeat.site/products/store/4216

 

에러가 발생하는 곳은 최신순으로 정렬한 리뷰를 검증하는 테스트 코드에서 나오게 된다.

 

쿼리문이 길어서 where절만 가지고 왔다.

최신순으로 정렬한 리뷰는 다음 조건에 부합하는 데이터들을 가져오게 된다.

 

 

예시를 들어서 설명해보면, 만약 3번 상품에서 가장 마지막에 데이터로 보내준 리뷰가 6번 리뷰라고 가정해보자. 이때 최신순으로 정렬해서 보여줄 경우 다음 페이지는 6번 리뷰보다 더 일찍 작성한 리뷰들이 보일 것이다.

 

 

그러면 위 사진처럼 2가지 종류의 데이터를 가지고 온다.

 

1) 6번 리뷰보다 더 일찍 작성한 리뷰 (2번 리뷰, 3번 리뷰)

2) 6번 리뷰와 동시에 작성했지만, 더 빠르게 데이터가 저장된 리뷰 (5번 리뷰)

---

 

 

 

2. 버그 확인하기

---

 

로컬에서는 버그가 발생하지 않다보니 깃허브 액션을 계속 실행해가며 테스트를 진행했다.

 

테스트는 위 코드와 같은데 리뷰 3개를 저장하고, 최신순으로 정렬할 때, 3번 리뷰 다음으로 나오는 리뷰들을 확인하는 테스트이다.

당연히 3번 리뷰보다 1번, 2번 리뷰가 먼저 작성됐으므로 정답은 [1번 리뷰, 2번 리뷰]만 actual에 저장되어야한다.

 

그런데 신기하게도 [3번 리뷰, 2번 리뷰, 1번 리뷰]가 저장되어서 나와 테스트가 실패하게 된다.

 

내가 원하는 결과물은 왼쪽과 같이 3번 리뷰를 마지막으로 조회 했으므로 1번 리뷰와 2번 리뷰만 나오면 되는데, 실제로는 오른쪽처럼 3번 리뷰를 포함해서 나오는 것이다.

 

다시 쿼리문을 살펴보자

첫번째 조건은 3번 리뷰와 같은 시각에 작성 했지만, ID가 더 낮은 데이터를 가져온다. 이건 애초에 r1_0.id < ?를 가지고 있으니 3번 리뷰를 가져오는게 말이 안된다.

 

두번째 조건은 3번 리뷰보다 더 빠르게 작성된 리뷰만을 가져온다.

이것도 마찬가지로 [3번 리뷰의 작성 시각] < [3번 리뷰의 작성 시각]이 성립한다는 것이므로 역시 말이 안된다.

 

두 조건 모두 상식적으로 3번 리뷰를 가져오지 않아야하지만 3번 리뷰의 데이터도 가져오게 된다.

둘 중 하나는 거짓이라는건데, 아무리 생각해도 r1_0.id < ?가 거짓말을 하지 않을 것 같다. 저게 거짓이라면 3번 리뷰가 다른 번호로 변해야하는데, 테스트 결과는 [3L, 2L, 1L]으로 문제가 없었다.

 

리뷰 작성 시각이 거짓인 경우를 확인하기 위해 로그를 추가한 상태로 Github Actions를 돌려보니 위 사진과 같이 나왔다.

 

1) review3의 생성 시각: 26.362916145초

2) review3의 생성 시각: 26.362916초

 

분명 같은 데이터인데 0.000000145초의 차이가 발생했다.

하나는 소수점 아래 9자리까지 표현이 되고, 하나는 소수점 아래 6자리까지 표현이 된다.

 

왜 이런 차이가 나오는걸까?

---

 

 

 

3. 소수점 9자리와 6자리가 차이나는 이유

---

 

[LocalDateTime과 데이터베이스 저장 형식]

Java의 LocalDateTime은 LocalDate와 LocalTime으로 이루어져 있다.

 

여기서 LocalTime 값을 확인해보면 nanoOfSecond가 999,999,999로 최대 9자리 수까지 표현이 가능하다.

 

http://www.h2database.com/html/datatypes.html#timestamp_type

H2 데이터베이스 공식문서를 살펴보면 TIMESTAMP은 최대 소수점 아래 9자리수까지 저장할 수 있다. 하지만 기본값은 소수점 아래 6자리까지 저장한다.

 

https://dev.mysql.com/doc/refman/8.3/en/fractional-seconds.html

MySQL 공식문서를 살펴보면 TIME, DATETIME, TIMESTAMP 모두 소수점 아래 6자리까지만 지원이 된다고 나와있다.

 

 

Github Actions의 테이블 생성문을 보면 마찬가지로 TIMESTAMP(6)으로 나와있다.

지금까지 같은 데이터지만 소수점 아래 9자리, 소수점 아래 6자리 차이로 인해 자기 자신도 포함이 됐던 것이다.

---

50% 확률로 테스트가 성공하거나, 실패하는 이유

이제 원인을 알았으니 왜 성공하거나 실패하는지 알아보자

성공 / 실패 차이는 해당 테스트가 돌아가는 시각에 영향을 받는다.

http://www.h2database.com/html/datatypes.html#timestamp_type

https://dev.mysql.com/doc/refman/8.3/en/fractional-seconds.html

 

H2와 MySQL 더 깊은 소수점 아래 값을 가져오면 모두 반올림을 한다고 나와있다. 이런 특징으로 인해 성공, 실패 케이스로 나뉘게 된다.

 

[테스트 성공 케이스]

- 실제 값: 10.000000999초

- 저장 값: 10.000001초 (반올림)

데이터 탐색시 10.000000999 > 10.000001은 성립하지 않으므로 자기자신 값을 가져오지 않는다.

 

[테스트 실패 케이스]

- 실제 값: 10.000000123초

- 저장 값: 10.000000초 (반올림)

데이터 탐색시 10.000000123 > 10.000000은 성립하므로 자기자신 값도 가져오게 된다.

 

0.0000005초 차이로 테스트가 성공하냐, 실패하냐로 나뉘게 된다.

---

 

 

 

4. 서비스/로컬에서는 왜 문제가 없었을까??

---

1) 서비스에서는 문제가 없었던 이유

실제 서비스와 Github Actions의 차이는 영속성 컨텍스트 때문이다.

테스트 환경에서는 하나의 테스트가 거대한 트랜잭션을 이루고 있기 때문에 "리뷰 작성"과 "리뷰 조회"가 같은 트랜잭션에서 이루어진다. 그래서 리뷰 작성으로 INSERT문을 실행하면 영속성 컨텍스트 1차 캐시 안에 해당 엔티티가 남아있기 때문에 리뷰 조회시 SELECT 문이 호출되지 않는다. 하지만 실제 서비스에서는 "리뷰 작성"과 "리뷰 조회"는 별개의 API로 존재해서 트랜잭션이 서로 다르기 때문에 문제가 발생하지 않는다.

 

참고로 테스트 코드 중간에 entityManager.clear()를 호출하면 두 개의 값 모두 데이터베이스를 통해 값을 가지고와서 소수 6번째 자리로만 표기된다.

 

---

 

2) 로컬에서는 테스트가 계속 성공 했던 이유

로컬에서 테스트가 계속 성공한 이유는 운영체제 차이이다.

인텔리제이 디버그 모드로 확인해보면 데이터들은 소수점 아래 6자리까지만 값이 표시 된다. 0.123456000으로 표기되는 것이다. 왜 그런지 하루종일 살펴보니 MacOS에서는 단위는 nanoseconds까지 지원하지만, 실제 값은 뒤에 "000"이 있으므로 microseconds 값까지 제공된다. 터미널로 확인해도 마찬가지다. 하지만 Ubuntu에서는 터미널을 확인해보면 nanoseconds까지 제대로 값이 나온다.

애초에 소수점 아래 6자리값만 실질적으로 가지고 있으니 버그날 일이 없었던 것이다.

---

 

 

 

왜 이런 문제가 발생하게 됐을까?

---

리뷰 목록은 4개의 정렬 조건이 제공된다. 이때 4개 정렬 조건을 따로따로 구현해두면 관리할 코드가 많아졌었다.

그래서 동적쿼리문을 한 번 만들 때, 4개 정렬 조건에 모두 사용할 수 있는 where절 템플릿을 만들었다.

이 템플릿을 사용해 한 번에 깔끔하게 처리하려는 것이 오히려 문제를 일으켰다.

 

 

[수정한 방법]

최신순으로 검색하는 방법은 단순히 ID를 기준으로 내림차순으로 보여주면 된다.

하지만 현재 코드에서는 해당 기능을 따로 구현하면 오히려 변경할 코드도 많고, 추가할 코드도 많아진다.

 

 

기존 코드를 최대한 유지하기 위해 최신순으로 정렬할 때 사용하는 LocalDateTime 값을 소수점 아래 6자리까지만 계산해서 보여주도록 수정했다. 어떻게 보면 Github Actions에서만 발생하는 오류이기 때문에 테스트를 통과하기 위해 프로덕트 코드를 수정하는 것이다. 하지만 생각해보니 기존의 소수점 아래 9자리 LocalDateTime 코드를 소수점 아래 6자리로 수정했기 때문에 좀 더 명확한 코드를 작성했다는 생각이 든다.

---

 

 

결론

---

TIMESTAMP에 관한 설정이 아예 안되어 있으면 created_at, updated_at을 사용하는 쿼리문을 모두 점검해봐야 한다. 다행히 우리 프로젝트는 created_at, updated_at을 사용하는 쿼리문이 리뷰 정렬 밖에 없어서 하나만 수정하면 됐었다.

 

그리고 최근 유지보수하면서 문서화의 중요성을 많이 깨닫게 되었다. 작년에 PR을 꼼꼼히 적어두고, 노션에도 문서화를 꼼꼼히 해놨어서 문제의 기술적 원인뿐만 아니라 왜 우리 프로젝트에 이런 문제가 발생한건지에 대한 원인도 빠르게 찾을 수 있게 됐다.

---