로깅

서버가 한 대이던 시절에는 원인을 찾는 방법이 단순했습니다. 그 서버에 접속해 화면에 찍힌 글을 읽으면 됐습니다. 의심 가는 자리에 값을 출력하는 줄을 넣어 두고 다시 돌려 보는 식이었습니다.

서버가 늘면서 이 방법이 무너졌습니다. 같은 프로그램이 열 대에서 돌고 있으면 문제의 요청이 어느 대에 갔는지부터 모릅니다. 열 대에 차례로 접속해 파일을 뒤지다 보면 30분이 지나 있고, 컨테이너처럼 쓰고 버리는 단위로 돌리는 경우에는 문제가 난 그 프로그램이 이미 사라져 파일도 함께 없어집니다. 고객이 "아까 저장이 안 됐어요" 라고 알려 와도 아까가 언제인지 특정하지 못해 아무것도 찾지 못하는 일이 흔했습니다.

그래서 기록을 만드는 일과 보관하는 일을 갈라 놓기로 했습니다. 프로그램은 벌어진 일을 정해진 모양으로 내보내기만 하고, 그 줄들을 한곳에 모아 검색할 수 있게 쌓아 두는 별도의 자리를 둡니다. 로깅은 그 앞쪽, 그러니까 남길 것을 정해 내보내는 쪽을 가리키는 말로 굳었습니다.

한 줄에 사건 하나를 적습니다. 한 줄에는 언제인지, 얼마나 심각한지, 무슨 일이 있었는지, 그리고 그 일에 얽힌 값들이 들어갑니다. "14시 02분 11초 / ERROR / 문서 저장 실패 / 사용자 8821 / 문서 4402 / 원인 타임아웃" 같은 모양입니다. 사람이 읽을 문장으로만 적지 않고 값마다 이름을 붙여 두는 방식을 구조화 로깅이라고 부릅니다. 이렇게 적어 두면 사용자 8821의 줄만 골라 내거나 원인별로 개수를 세는 일이 검색으로 됩니다.

심각도는 보통 다섯 단계를 씁니다.

1. DEBUG — 개발 중에만 보는 상세한 값입니다. 운영에서는 대개 꺼 둡니다.
2. INFO — 정상적으로 벌어진 일입니다. 로그인 성공, 배치 작업 시작 같은 것들입니다.
3. WARN — 지금 당장 실패는 아닌데 이상한 상태입니다. 재시도해서 성공했다거나, 응답이 평소보다 느렸다거나.
4. ERROR — 요청 하나가 실패했습니다. 사람이 볼 필요가 있는 줄의 대부분이 여기입니다.
5. FATAL — 프로그램 자체가 더 못 돌아가는 상태입니다.

단계를 나눠 두는 이유는 평소에 볼 양을 줄이기 위해서입니다. 운영에서는 INFO 이상만 남기고, 문제가 생기면 그 부분만 DEBUG 로 잠깐 낮춰 자세히 봅니다.

줄을 하나로 묶는 장치도 필요합니다. 요청 하나가 서버 안에서 열 줄을 남기는데 동시에 백 명이 쓰고 있으면 천 줄이 뒤섞입니다. 그래서 요청이 들어올 때 고유한 번호를 붙이고 그 요청에서 나오는 모든 줄에 같은 번호를 적습니다. 나중에 그 번호로 검색하면 그 요청 하나의 흐름만 모입니다.

남기지 말아야 할 것도 정해 둡니다. 비밀번호, 카드번호, 주민등록번호 같은 개인 식별 정보가 로그에 들어가면 그 줄을 보관하는 기간만큼 유출 위험이 늘어납니다. 값을 통째로 적지 않고 일부를 가리거나 대체 값으로 바꿔 내보냅니다.

장애가 났을 때 원인을 좁히는 마지막 단계에서 가장 많이 씁니다. 그래프에서 실패가 튄 시각을 찾고, 어느 구간이 느린지 추려 낸 다음, 그 시각 그 구간의 줄을 읽어 무엇 때문이었는지 확인하는 순서입니다. 인시던트를 정리한 기록에 근거로 붙는 것도 대개 이 줄들입니다.

고객 문의를 확인할 때도 씁니다. "어제 오후에 공유가 안 됐다" 는 문의를 받으면 그 계정의 그 시간대 줄을 찾아 실제로 실패가 있었는지, 있었다면 무엇 때문이었는지 봅니다. 재현이 안 되는 문제일수록 이 기록이 유일한 근거가 됩니다.

배포 직후에도 봅니다. 새 버전을 올린 뒤 ERROR 줄이 평소보다 늘었는지 확인하고, 늘었으면 되돌립니다. 알림을 특정 문구가 일정 횟수 이상 나오면 울리도록 걸어 두는 경우도 있습니다.

값이 드는 점은 미리 정해 둡니다. 줄마다 저장 공간을 먹고 검색용 색인을 만드는 데도 값이 듭니다. 하루 수억 줄이 쌓이는 규모에서는 최근 2주만 바로 검색되게 두고 나머지는 싼 저장소로 옮겨 필요할 때 꺼냅니다. 감사 목적처럼 법이나 계약으로 기간이 정해진 기록은 따로 뺍니다.

"요청 ID 있으세요? 그거 있으면 그 건만 바로 뽑을 수 있어요."

뒤섞인 줄에서 해당 요청만 골라내겠다는 말입니다.

"이건 로그에 안 남아 있어서 확인이 안 됩니다."

그 자리에 기록을 남기는 줄이 없어서 근거가 없다는 뜻입니다.

"DEBUG 로 내려서 30분만 보고 다시 올립시다."

자세한 줄을 잠깐 켜서 보고 양이 늘기 전에 되돌리자는 제안입니다.

페이지덱에서 문서 저장이 간헐적으로 실패한 적이 있습니다. 하루에 몇 건씩이라 재현이 안 됐고, 고객센터에 들어온 문의는 "가끔 저장이 안 돼요" 한 줄이었습니다. 태오가 실패한 저장 요청의 줄을 모아 보니 전부 문서 하나에서 나왔고, 원인 자리에 같은 값이 적혀 있었습니다. 동시에 편집하던 사람이 여섯 명을 넘은 순간이었습니다.

그전까지는 저장 실패를 세는 숫자만 있었습니다. 그 숫자로는 실패가 늘었다는 사실까지만 알 수 있어서, 무엇 때문인지는 매번 서버에 들어가 찾아야 했습니다. 이 일을 겪고 태오는 저장 실패 줄에 동시 편집자 수를 함께 적도록 고쳤습니다. 로깅에서 대부분의 개선은 새 도구가 아니라 이렇게 한 줄에 적는 값을 늘리는 쪽에서 나옵니다.

많이 남길수록 좋다고 생각하기 쉽습니다. 나중에 필요할지 모르니 일단 다 적어 두자는 판단은 자연스럽습니다. 그런데 양이 늘면 두 가지가 같이 늘어납니다. 보관과 검색에 드는 값이 늘고, 찾는 줄이 묻힙니다. 하루 열 줄 남기는 자리를 천 줄로 바꿔 두면 검색 결과 첫 화면이 그 줄로 가득 차서 정작 ERROR 한 줄을 못 봅니다. 기준은 양이 아니라 그 줄로 무엇을 판단할 수 있느냐입니다. 읽고 나서 할 일이 달라지지 않는 줄은 남기지 않습니다.

로그를 남겨 뒀으니 관측성이 확보됐다고 보는 것도 흔합니다. 가장 자세한 기록이니 그렇게 읽힙니다. 하지만 로그는 어디를 봐야 할지 알고 있을 때만 쓸모가 있습니다. 무슨 일이 벌어지고 있다는 사실 자체는 수치로 쌓은 쪽이 알려 주고, 여러 조각 중 어디서 막혔는지는 경로를 이어 보는 쪽이 알려 줍니다. 로그만 심어 둔 팀은 문제가 있다는 것을 고객이 알려 줄 때까지 모르고, 알게 된 뒤에도 어느 시각을 뒤져야 하는지부터 찾게 됩니다.