[AWS RDS x MySQL] 운영하며 만난 버그 - RDS Timezone, MySQL current_date

728x90

현재 상황

테스트도 잘 마치고 평소에 정상 동작하는 API가 어쩔 때 한 번씩 잘 안된다는 버그 제보를 받았습니다.

문제는, API가 에러가 잡히는 것이 아닌 200으로 잘 응답하되 결과가 부정확한 것...

따라서 잘 안 되는 시점이 언제인지 정확히 트래킹도 되지 않았습니다. (에러 로그로 남지도 않잖아...)

왜 갑자기 안되지? 언제는 되고, 언제는 안 되는 게 말이 안 되지 않나?!

예상을 해보자

1. 어떤 API 인가

- 사용자가 체크를 하고 나서 (insert)

- 사용자가 오늘 체크한 횟수를 알기 위해 오늘 날짜에 해당하는 사용자의 행동 데이터의 개수를 읽어옵니다 (select)

- 나머지 데이터를 화면에 맞춰 가공한 뒤, 응답합니다.

{
  "careId": 0,
  "careName": "string",
  "totalCareCount": 0,
  "currentCount": 0, => 이게 문제!

 ...

2. 뭐가 문제인지

- 체크한 뒤, 데이터는 정상적으로 insert가 되는 것을 확인했습니다.

- 또한, 최종 응답 데이터 역시 200 response로 예외가 발생하지 않고 잘 처리되었습니다.

- 그런데 어쩔 때 한 번씩, currentCount에 대한 select가 제대로 되지 않고 이상한 횟수가 내려옵니다.

3. select가 어떤 조건으로?

- 그렇다면? select가 어떻게 동작하는지 다시 한번 확인했습니다.

- 현재 횟수를 select count(~~) from ~~ where log_date = current_date로 조회하고 있었습니다.

- 에러 케이스를 확인해보니, 항상 0을 리턴한다는 제보였고 저는 결국 currentCount를 조회하는 select 쿼리가 정상적으로 동작하지 않고 항상 0을 리턴한다고 판단했습니다.

- 그리고 저는 한 가지 의심을 하게 됩니다. current_date는 mysql 예약어를 사용했기 때문입니다.

혹시?

정리해보면

정상 동작되던 API가 불규칙하게 동작하지 않음.
서버에 찍힌 로그와 DB의 데이터를 확인 -> 정상 insert & 200 response가 내려가는 것을 확인
서버의 로직을 확인 -> 현재 횟수를 select count(*) from ~~ where log_date = current_date로 조회하는 중
나머지 응답은 정상적으로 동작, 현재 횟수만 항상 0이 나오고 response는 1회가 추가된 1이 응답
결국 현재 횟수의 count를 세는 select 쿼리가 정상적으로 동작하지 않고 항상 0으로 리턴한다고 판단
해당 쿼리의 where 조건 중 오늘 날짜에 insert 된 row만 조회하는 current_date가 의심됨.

확인

제가 의심한 이유는, 해당 예약어를 처음 사용해보기도 했고 뭔가 불현듯 스쳤습니다.

"예약어가 날짜와 관련됐을뿐더러, API가 잘 동작하다가 안 하다가 한다는 건 시간에 의존된 게 아닐까?"

바로 확인해봤습니다.

제가 이용하는 RDS의 timezone를 알 수 있는 now()를 확인해보니 UTC가 찍혔습니다.

원인을 찾았습니다...

API 서버가 동작하는 EC2는 KST이고 이용자가 애플리케이션을 사용하는 시간대 역시 KST입니다.

따라서 DB에 해당 데이터는 KST로 정상 insert가 되었지만 횟수를 세기 위해 select ~ where log_date = current_date를 이용해서 조회할 때는 하루 전 날짜의 데이터가 select 되는 것이었습니다.

그리고 이어서 다른 의문점 역시 풀렸습니다.

왜 갑자기 안되지? 언제는 되고, 언제는 안 되는 게 말이 안 되지 않나?!

딱 UTC와 KST의 9시간의 차이의 경계에 API를 사용하면 정상적으로 동작하지 않는 것이었습니다.

-> 20일 새벽 2시 48분에 check

-> DB insert log_date = '2022-11-20' (02:48:28)

-> select current_date로 뽑는 경우 RDS의 current_date는 '2022-11-19' (17:48:28)

-> select의 결과가 1이 나와야 하지만, 하루 전 날짜의 조건으로 select 했기에 결과가 0이 나와버림.

즉, 오전 9시부터 정상 동작하는 API가 되어버린 것입니다...!!! (9시간 차이로 UTC 역시 같은 날짜로 변경됨)

수정

결국 AWS EC2의 timezone이 KST로 동작해도, 또 다른 인스턴스인 AWS RDS의 timezone이 UTC로 동작하면 소용이 없는 것이었습니다.

결국 RDS 인스턴스의 timezone을 변경해야 하기 때문에, 해당 RDS의 파라미터 그룹을 변경해주었습니다.

새로 파라미터 그룹을 생성하고, time_zone을 검색해서 Asia/Seoul로 변경했습니다.

RDS의 default는 UTC라고 합니다.

이후 데이터베이스 - 수정 - 밑으로 내리면 추가 구성 - 데이터베이스 옵션 - DB 파라미터 그룹을 선택하는 곳이 있고, 방금 생성해준 파라미터 그룹을 적용했습니다.

그리고 즉시 적용 후 DB 인스턴스를 재부팅해줬습니다.

정상적으로 KST로 변경된 시간이 조회되는 것을 확인할 수 있었습니다.

정리

보통 RDS 예제에서 생성 후 timezone을 변경해줘야 한다는 글을 많이 봐서 알고는 있었습니다.

하지만 별 문제 있겠어? 하고 넘겼고 별 다른 생각 없이 MySQL의 예약어를 사용했고 버그를 만났습니다 하하..

테스트를 하고, 직접 데모도 돌려볼 때는 모두 오전/오후였어서 버그를 알아채지 못했지만, 애플리케이션 서버를 직접 운영해보니 날짜가 변경되는 경계 시간대에서 발생하는 문제를 만날 수 있었던 것 같습니다.

역시 개발할 때, 하나라도 대충 넘어가면 결국 그 부분이 에러로 돌아오는 것 같습니다..

timezone에 관련된 좋은 경험이었습니다.

+ 추가로, 문제를 해결하기 위해 로그를 찾으면서 고생을 좀 했는데 이래서 기본적인 cloudWatch Logs 모니터링이나 ELK 등을 이용한 로그 모니터링, 수집 시스템을 만드나 보다고 느꼈습니다.