신규 서비스를 오픈하면서 서버 모니터링을 위해 aws cloudwatch를 사용하게 되었다. 원래는 cloudwatch와 newrelic 을 모두 선택지에 올려놓고 마지막까지 고민을 했다. newrelic 쪽이 기능도 많고 레퍼런스도 확실했지만 일부 서버에서 agent의 설치가 안되는 문제가 있었다. 사실 agent 설치 안되는 문제야 조금 더 시간을 들여서 파보면 해결할 수 있는 문제였겠지만 당장에 서비스 오픈을 코앞에 둔 상황에서 시간적인 여유가 부족했고, cloudwatch도 우리가 필요한 기능을 대부분 제공하고 있었기 때문에 cloudwatch로 가기로 했다.

cpu, 메모리, 디스크 사용량 등의 지표를 대시보드로 구성해놓고 며칠 모니터링하고 있으려니까 좀 이상한 현상이 눈에 띄었다.

일부 서버에서 주기적으로 network out이 튀고 있었다. 시간도 정확하게 6시 반쯤에 시작해서 11시에는 정상으로 돌아왔다. 제일 먼저 해당 서버에서 주기적으로 스케쥴링되어 돌고 있는 태스크가 있는지 확인했다. 하지만 스케쥴이 걸려있는 태스크라고는 cloudwatch 메트릭 값을 수집하는 agent 뿐이었고 이 에이전트도 5분마다 한번씩 실행되도록 구성되어 있었기 때문에 용의선상에서 벗어났다. 그외에 여러 의심되는 부분들을 샅샅이 뒤져봤으나 애초에 해당 서버는 aws s3에 있는 데이터들을 변환해 던져주는 역할만 하는 심플한 서버였기 때문에 원인을 진단하기가 어려웠다. network out이 튀는 정도가 분당 평균 5mb 근처였기 때문에 당장 서비스 운영에 문제를 줄만한 사안이 아니었고 이 문제 말고도 긴급을 요하는 태스크들이 많았기 때문에 자연히 칸반 보드의 todo list 어딘가로 해당 이슈는 쳐박히게 되었다.

문제는 다른 부분에서 다시 일어났다. 이 서버의 메모리 사용량이 슬금슬금 눈치채지 못할 정도로 느리게 증가하고 있었다. 최초 기동시에는 6퍼센트 정도에서 머물던 것이 시간이 지남에 따라 50%를 넘어 70%를 넘보는 수준까지 도달한 것이었다. 그때 팀원 중 한명이 s3fs를 의심하기 시작했다. 이 서버는 s3에 있는 데이터를 서빙하기 위해서 s3fs 라는 오픈소스를 이용해서 s3 특정 버킷을 가상으로 마운트 시켜놓고 쓰고 있었다. s3fs 프로젝트의 issue란을 뒤져보니 memory leak이 있다는 issue가 유난히 많았다. 팀 내부에서도 s3fs의 memory leak bug로 인한 현상으로 추정하고 옵션값 튜닝을 더 해보고 안되면 s3fs 대신 goofys 라는 솔루션으로 넘어가기로 했다. 하지만 그대로 s3fs의 memory leak bug 라고 단정해버리기엔 좀 찜찜한 것이, github issue에 올라온 memory leak 리포트들은 대부분 수십분에서 수 시간 내로 서버의 메모리를 모두 잡아먹고 뻗어버리는 현상이 발생했던 것과는 달리 우리 서버는 2주째 메모리 사용량을 야금야금 먹으면서 올라오긴 했지만 서버의 메모리를 모두 잡아먹진 않았다. 조금 더 살펴보기로 했다.

일단 좀 더 정확한 정황을 확인하기 위해 s3fs의 디버그 로그 옵션을 켜고 다시 재기동하였다. syslog에 어마어마한 양의 로그가 쌓이기 시작했다. 양 자체가 워낙에 많에 전수조사를 할 수는 없었지만 일단 일부 확인한 내용으로는 이상해보이는 로그는 보이지 않았다. 그렇게 주말을 보내고 월요일 아침 다시 로그를 확인해보았다. 이 때 였다. 의심스러운 로그가 눈에 들어오기 시작했다.

매일 아침 6시 25분마다 s3fs에 의해서 가상 마운트되어 있는 폴더 아래 모든 오브젝트들을 하나씩 순회하는 로그들이 찍혀있었다. 해당 s3 bucket에는 수만개 이상의 오브젝트들이 존재하고 있기 때문에 이 순회 작업은 수시간 후에야 끝났다. 그 때 잊고 있었던 네트워크 튐 현상이 떠올랐다. network out 지표에도 매일 아침 6시 반부터 11시 까지 그래프가 튀어 있었고 s3fs 로그에서는 그 시간대에 bucket내 모든 오브젝트들을 순회하는 로그가 찍혀있었다. 즉, s3fs 마운트 폴더에서의 순회요청은 그대로 디스크를 뒤지는 것이 아니라 network를 타고 나가 s3 서버로 요청을 던지게 되므로 network out 그래프가 튀게 된 것이다. 범인은 꼬리가 보이기 시작했다. 우리는 이 단서를 조금 더 파보기 시작했다.

한가지 더 이상했던 것은 s3fs 마운트 폴더를 순회하는 로그가 정확히 각 syslog의 가장 첫부분부터 시작이 되고 있었다는 것이다. syslog는 logrotate에 의해서 롤링되고 있었기 때문에 logrotate가 실행되는 시점에 어떤 명령에 의해서 s3fs 마운트 폴더 순회 명령이 걸렸다고 추정할 수 있었다. 범인의 몽타주가 얼핏 보이는 듯 했다. logrotate 실행 스크립트가 담겨있는 cron.daily 폴더를 조회해보았다.

운좋게 몇놈 없었다. 이 놈들 중 범인이 있다고 확신한 나는 각 스크립트들을 하나씩 취조하기 시작했고 마침내 mlocate가 범인임을 확인할 수 있었다. mlocate는 빠른 파일 접근을 위해 디스크 내용을 인덱싱하는 역할을 하고 있었는데, 그 인덱싱 작업을 매일 아침마다 돌고 있었고 그 대상에는 안타깝게도 s3fs 마운트 폴더도 존재했던 것이다. mlocate가 인덱싱을 위해서 해당 폴더 내 모든 하위 플더들을 순회하면서 인덱싱을 했고, 순회하면서 발생하는 모든 요청들은 모두 s3 서버로의 요청이 되어 network out 지표를 튀게 만들었던 것이다. 메모리 사용량 증가도 자세한 경과까지는 확인하지 못했지만 짧은 시간내에 감당하기 힘든 네트워크 요청들로 인해서 발생한 것이라고 이해하기에 어려움이 없었다.

조치는 간단했다. mlocate가 인덱싱을 하는 폴더들 중 s3fs 마운트 폴더를 예외로 넣은 후에 s3fs를 재기동해주었다. 메모리 사용량은 정상으로 돌아왔고 며칠이 지난 지금까지도 정상 범주를 벗어나지 않고 있다. network out 그래프 역시 정상의 범주로 돌아왔다.