Today I Learned
날짜
2024년 12월 17일 화요일
내용
드디어 마침내 결국 찾은 오류의 원인
지난주부터 아임리포트에 이상한 현상이 발견되었다. 네이버에서 대용량 보고서 요청을 보내도 빈 응답값이 반환되는 현상이다. 끈질기게 원인을 찾았으나 결국 찾지 못했는데, 증상만 보면 다음과 같다.
- 매일 오전에 실행되는 자동 업데이트에서만 발생한다. 수동 업데이트를 아무리 많이 보내봐도 재연되지 않는다.
- 요청에 대한 응답 코드는 200이나 빈 배열이 반환된다.
- 발생하는 로우데이터, 날짜 모두 불분명하다
여러 시나리오를 추정해봤으나 발견하지 못했다.
- 실제로 보고서가 없었다.
- 그렇다면 어제 받은 보고서를 오늘은 못받고, 내일은 다시 받는 상황이 설명되지 않음
- 순간적으로 너무 많은 요청이 몰려 실패했다.
- 네이버에선 그럴 경우 429를 반환한다. 이에 관한 로직은 내 서버에도 있다. 그리고 자동 업데이트에서만 발생하는 이유를 설명하지 못함.
그러던 중 실마리를 찾지 못하던 중 오늘 드디어 해결해냈다. 로우데이터 처리 로직에는 각 단계별로 로깅문을 추가해놨기 떄문에, 네이버 API 사용을 시작하고 끝내는 시간이 로그에 남는다. 이 시간을 기록했고 각 로우데이터가 대기열에서 기다리다 시작되었는지, 오류가 났는지 표로 정리했다.
특정 계정의 로우데이터를 정기업데이트 한 결과의 데이터이다.
| 로우데이터 ID | AWS 로그 스트림 ID | 네이버 API 사용 시작 | 네이버 API 사용 종료(완성 or 에러) | 에러가 났는가? | 대기열에 있다가 시작했는가? |
|---|---|---|---|---|---|
| 218 | ce0a0f47e33a4ec7999883047ffb40f4 | 05시10분58초 | 05시16분57초 | X | O |
| 219 | 31dbff72439349869d22caf80a6fd3b3 | 05시11분05초 | 05시17분29초 | X | O |
| 220 | f172045fa8d4463f8c0b8aa8bd76896a | 05시10분58초 | 05시16분57초 | X | O |
| 221 | 16dc278642634f7686121619303d1373 | 05시10분58초 | 05시12분33초 | X | O |
| 222 | 77215abff00b4b9b8753e9d71b054ad8 | 05시11분03초 | 05시15분31초 | O | O |
보자마자 말이 안된다는 생각을 했다.
우선, 모두가 대기열에 있다가 출발했다. 각 계정별로 1개의 데이터씩 처리하기 위해 대기열을 만들었다. 따라서 적어도 1개는 대기열에서 시작하는게 아니라 바로 시작했어야 했다. 두번째로, 네이버 API 사용 시간이 겹쳤다. 지난주 월요일에 고친대로 최소한 이 부분만큼은 각자 독립된 시간을 보장하도록 구현했기 떄문이다. 내가 구현한 것이 제대로 작동하지 않아서 문제가 발생하고 있다고 판단했다.
결국 모든 문제는 연결되어 있었다. “대기열에 있다가 시작했는지”를 파악하는 방법은 과정이 시작할 때 import_log 값이 무엇인지를 따진다. 처리 로직상 감지한 로그가 CREATING이 아니면면 대기열에서 출발했다고 생각하여 스프레드시트 상태 검사 로직은 건너 뛴다. 시트 상태검사는 대기열에 들어가기전에 이미 거친 로직이기 때문이다. 건너 뛸때 “대기열에 있던 애라 건너뛰었어요~”라고 로그를 출력하게 해놨다. 이 외에는 모두 대기열이 아니라고 판단한다.
자동 업데이트 코드상 로그를 생성하고 IMPORTING 상태로 둔다. 업데이트 몇시간 전 스프레드시트 상태 검사를 이미 진행하기 때문에 바로 데이터 처리로 넘어가도 되기 때문이다. 그럼 처리하는 과정에서는 “ CREATING이 아니니까 대기열에 있던애구나?” 라고 생각한다. 그래서 모든 로우데이터가 대기열에 있다가 출발한것 처럼 로그가 찍혔고, 나도 그렇게 생각했다. 자동 업데이트 떄는 1단계(시트 상태검사)를 건너뛰고 2단계(데이터 임포팅)으로 바로 가고 있었다. 여기까진 몰랐던 일이나, 아무 문제가 없다.
문제는 네이버 API 사용 상태를 1단계에서 검사하기 떄문이다. 1단계가 완료된 후 네이버 API 키 사용 상태를 검사하여 누군가 사용하고 있을 경우 너무 많은 요청을 보내 거절당하는 것을 방지하기 위해 대기열 상태에 넣는 로직이 있다. 정기 업데이트의 경우에는 모두가 1단계를 건너 뛰었으므로 이 로직이 작동하지 않았다. 그래서 모두 동시에 API를 쐈다. 그래서 표에 네이버 API 사용 시간이 겹쳐있었다. 그렇다면 왜 요청이 200이 떴으니 제대로 작동해야하지 않나? 동시에 쏴서 너무 많이 발생했으면 429 를 status_code로 반환했어야 했다.
네이버에서 데이터를 가져올 때 각 일자에 맞는 보고서를 생성한후 다운로드한다. 이후 겹치지 않도록 생성한 보고서 목록을 삭제하는 요청을 보낸다. 이 요청들이 한 계정 내에 있는 여러 로우데이터 에서 모두 보냈다. 마치
- 219번 로우데이터가 A 계정에 대한 2024년 10월 1일 보고서 생성을 요청함
- 219번 로우데이터가 A 계정에 대한 2024년 10월 2일 보고서 생성을 요청함
…
- 219번 로우데이터가 A 계정에 대한 2024년 10월 31일 보고서 생성을 요청함
- 221번 로우데이터가 A 계정에 대해 생성되어 있는 모든 보고서 삭제를 요청함
- 219번 로우데이터가 현재 생성되어 있는 보고서를 조회함 ⇒ 빈값
이런식으로.. 이게 우연히 겹치면 보고서가 안오고 적당히 겹치면 어떤것만 오고 안겹치면 잘 왔었다. 결국 해결을 위해 API의 단독 사용을 보장하는 락을 제대로 기능하게 만들어야 했다. 그래서 API를 사용중인지 확인하고, 사용중으로 상태를 변경하거나 사용완료 처리하는 요청 모두 서버로 요청을 보내 확인하도록 로직을 바꾸었다. 이 덕에 조금 더 엄밀하게 대기열이 관리될 수 있을 것.
회고
속이 다 시원하네
