6. 간헐적 오류 잡기
동기
맵샷에는 원인을 알 수 없던 고질적인 에러가 하나 존재했습니다.
굉장히 랜덤한 주기로 발생하는 에러인지라 원인 파악, 발생 조건 등 정보를 얻기 굉장히 힘들었습니다. 계속 고쳐야지, 고쳐야지.. 미루고 있다가 최근 멘토링을 받던 순간 하필 에러가 터졌고, 이제는 미뤄서는 안 되겠다는 생각이 퍼뜩 들었습니다.
문제 상황
맵샷의 특정 지도 타입들은 별도의 서버를 통해 제작됩니다.
1번(이미지 요청)부터 7번(Key 값 수령)까지 하나의 요청으로 묶여 있는데, 이 과정 어딘가에서 지속적으로 에러가 발생했습니다. 다양한 생각을 해보았지만 도저히 떠오르는 곳이 없었고, 이건 상상으로 해결될 문제가 아니다 싶어 모든 요청 과정을 로깅하기 시작했습니다.
해결 과정
로깅 개선
먼저 기존의 문제점 개선 및 효율적인 로깅 방식에 대해 고민해봤습니다.
기존 로깅 방식의 문제는 다음과 같았습니다.
에러 별로 로그 파일을 달리 관리하면 차후에 편할 것 같다는 생각을 해서 레벨별로 파일을 분리했던 것인데, 정확하게 틀린 예측이었습니다. 오히려 시간 순대로 하나의 로그 파일에 모든 정보가 담겨야 흐름 파악이 용이했습니다.
다른 하나는 에러 발생 시에만 해당 익셉션에 대헤 로그를 찍고 있었는데, 전후 과정이 전혀 없다보니 있으나 마나한 로그가 되었습니다.
그래서 먼저 3개로 분리해서 저장하던 로그 파일을 하나로 병합, 첫 번째 문제는 해결했습니다.
이제 에러가 발생하는 전후 맥락을 보기 위해 정보성 로그를 작성해야 했습니다.
먼저 필터를 이용해 request 관련 정보와 response code를 기록했습니다. response는 Status Code만 기록했는데, 이미지 파일이 왔다 갔다 하는 API다 보니 body 값을 모두 남기면 로그 파일이 너무 커질 것 같기 때문이었습니다.
그리고요청 마다 고유의 ID를 부여해서 로그를 기록할 수 있게 도와주는 MDC라는 기능을 찾게 되었고, UUID를 MDC에 기록해 요청 별 추적이 용이하게 했습니다.
이제, 남은 건 에러가 터지길 기다리는 일 뿐이었습니다.
WebClient
다행인지 불행인지 기존 주기보다 비교적 빠르게 에러가 발생해 주었고, 얼른 로그 파일을 확인하러 달려갔습니다. 그리고 드디어 원인을 밝혀 냈습니다.
커다란 지도 이미지를 하나의 파일로 전송하면 효율이 떨어져서 분할 후 전송하고 있었는데, 마지막 지도 이미지가 오기 전 Timeout이 발생하여 에러가 발생한 것이었습니다.
다행인 것은 대부분의 이미지들이 시간 내에 저장이 완료되었고, 저장에 실패한 요청들도 굉장히 근소한 시간 차이라 (0.1초 수준) 기존의 30초였던 WebClient의 타임아웃 시간을 5초 정도만 늘려 줘도 해결될 것이라고 생각했습니다. 그렇게 뿌듯하게 코드를 커밋하고 2시간 후에, 같은 에러가 또 다시 발생했습니다.
AWS API GATEWAY
로그를 확인해보니 같은 증상이었고, 처음에는 코드를 잘못 작성했나 싶어서 레퍼런스들을 다시 찾아봤습니다. 그런데 아무리 보고 테스트를 로컬에서 돌려도 문제가 없어서, 리눅스 자체 정책이라도 뭐가 있는건가 하고 더 찾아보는 순간, AWS의 API Gateway에 관련 정책이 존재했습니다.
Lambda의 앞단에 API Gateway가 존재했는데, 무슨 수를 써도 timeout을 늘릴 방법은 없다는 대답을 봤고 결국 지도 생성 안정성을 위해 조금 느리게 작동하도록 기입한 코드를 약간 타이트하게 조여줌으로서 해당 에러와는 작별을 고하게 되었습니다.
결론
그동안 에러 상황에 필요한 것이 로그라고 생각해 진짜 에러 로그만 찍었습니다. 하지만 모든 일에는 흐름이 있듯이, 한 순간의 장면만 보고는 해당 사건의 원인을 추적하기에는 너무나 어려웠습니다.
소 잃고 외양간 고친다는 말이 있습니다. 만약 에러에 대한 관련 로그가 전무하다면 외양간을 고칠 도구조차 없다는 교훈을 주는 사건이었습니다.
Last updated