Warnings Arrive Before Errors

한 줄 요약

에러가 터진 시각은 사건의 시작이 아니라 이미 진행되던 열화가 임계를 넘은 시각이고, 진짜 시작은 그 앞의 경고 구간에 있다.

왜 이게 필요했나

장애를 조사할 때 대부분의 사람이 에러 로그부터 봅니다. 자연스럽지만, 에러는 이야기의 중간부터입니다.

전형적인 열화는 이렇게 진행됩니다. 어떤 변경이 있고 → 일부 요청이 느려지기 시작하고(경고) → 느린 요청이 늘면서 자원을 붙잡고 → 타임아웃이 터지고(에러) → 임계를 넘어 알람이 울립니다. 에러 로그만 보면 마지막 두 단계만 보입니다.

그래서 조사에서 던져야 할 질문은 "언제 에러가 시작됐나" 가 아니라 "언제 정상이 아니게 됐나" 입니다. 경고 레벨 로그의 첫 등장 시각이 그 답인 경우가 많습니다.

어떻게 동작하나

여러 로그를 겹쳐 인과를 만드는 절차는 이렇습니다.

1. 각 로그가 무엇을 아는지 정한다. 접근 로그는 사용자가 무엇을 겪었는지 압니다. 애플리케이션 로그는 왜 실패했는지 압니다. 느린 쿼리 로그는 어디서 시간이 갔는지 압니다. 배포 이력은 무엇이 바뀌었는지 압니다. 한 로그가 모든 질문에 답하지 않습니다.

2. 시간축을 맞춘다. 이게 실무에서 가장 자주 발목을 잡습니다. 한 서비스는 UTC 로, 다른 서비스는 오프셋 없는 로컬 시간으로 기록하면 같은 사건이 9시간 차이로 보이고 정렬할 방법이 없습니다. 그래서 구조화 로그에서 타임스탬프에 오프셋을 넣는 것이 규칙입니다. 이미 만들어진 로그를 다룰 때는 각 파일의 시각 표기 방식을 먼저 확인하고 시작합니다.

3. 레벨별로 첫 등장 시각을 뽑는다. warn 의 첫 시각과 error 의 첫 시각. 이 둘의 간격이 곧 "놓친 시간" 입니다.

4. 원인 후보와 시각을 대조한다. 배포 이력, 설정 변경, 트래픽 변화. 시각이 겹치면 강한 단서이고, 겹치지 않으면 그 후보는 지워집니다.

5. 방향을 확인한다. 상관은 인과가 아닙니다. A 가 B 보다 먼저 일어났다는 것은 필요조건이지 충분조건이 아닙니다. 배포가 03:19 이고 에러가 03:27 이면 순서는 맞지만, 그 배포가 정말 원인인지는 롤백 후 증상이 사라지는지로 확인해야 합니다.

현장에서 만나는 모습

여기서 구조화 로그의 값어치가 드러납니다. 로그 한 줄에 service.version 이 들어 있으면 "배포 때문인가" 라는 질문에 로그만으로 답할 수 있습니다. 없으면 별도의 배포 이력을 구해서 시각을 맞춰야 하고, 그 이력이 어디 있는지 아는 사람을 찾는 데 30분이 갑니다.

같은 이유로 request_id 가 중요합니다. 그것이 없으면 한 요청이 어느 서비스에서 어떻게 처리됐는지를 시각으로 추측해서 짝지어야 하는데, 초당 수십 건이 들어오는 시스템에서 그 추측은 거의 항상 틀립니다.

마지막으로 실무 감각 하나. 에러 메시지 안에 답이 들어 있는 경우가 놀랄 만큼 많습니다. db query timeout: table=payments 라는 한 줄이 있으면 이미 계층(데이터), 증상(타임아웃), 대상(payments 테이블)이 다 나와 있습니다. 로그를 세기 전에 한 줄을 제대로 읽는 것이 먼저입니다.

없는 것도 신호다

로그를 겹쳐 볼 때 사람들은 기록된 것만 본다. 그런데 조사에서 결정적인 단서가 되는 것은 있어야 할 자리에 없는 항목인 경우가 자주 있다.

정기 작업이 그날만 없다. 매시간 도는 배치의 로그가 사고 시각 근처에서만 비어 있다면, 그 배치가 못 돌았거나 아주 오래 걸렸다는 뜻이다. 도는 것을 세는 것보다 안 도는 것을 찾는 것이 어렵기 때문에, 주기적인 작업은 성공했을 때도 한 줄을 남기게 만들어야 한다. 실패할 때만 로그를 남기는 설계는 "아무 일도 안 일어난 것" 과 "죽어서 아무것도 못 한 것" 을 구별할 수 없게 만든다.

어떤 서비스의 로그만 그 구간에 없다. 다른 서비스는 계속 기록되는데 하나만 조용하다면, 그 서비스가 멈췄거나 로그 전송이 끊긴 것이다. 어느 쪽인지는 그 서비스의 상류에서 요청이 계속 갔는지로 갈린다.

요청은 있는데 응답 기록이 없다. 접근 로그에 요청이 남았는데 애플리케이션 로그에 그 처리 결과가 없다면, 처리 도중에 프로세스가 사라진 것이다. 이때는 그 시각의 종료 원인을 봐야 한다.

그래서 시간축을 그릴 때 각 로그의 건수를 분 단위로 함께 그리는 것이 도움이 된다. 오류 건수만 그리면 위의 세 가지가 전부 보이지 않지만, 전체 건수를 함께 그리면 "이 구간에 이 로그만 뚝 끊겼다" 가 한눈에 드러난다. 조사 시간의 대부분이 어디를 볼지 정하는 데 쓰인다는 점을 생각하면, 이 한 장이 주는 값은 크다.

그리고 이 관찰은 다음번을 위한 제안으로 이어집니다. 조사에서 "이게 없어서 확인할 수 없었다" 고 적은 항목이, 그대로 다음 분기에 추가해야 할 로그 목록입니다. 보고서에 그 문장을 남기지 않으면 다음 장애에서 똑같이 막힙니다.

이 목록은 대개 짧다. 요청 식별자, 배포 버전, 처리에 걸린 시간, 그리고 실패했을 때의 대상 이름 정도다. 네 가지를 로그 한 줄에 넣어 두면 다음 조사에서 겹쳐 볼 것이 거의 없어진다.

다음 실습에서 할 것

JSON Lines 애플리케이션 로그, 느린 쿼리 로그, 배포 이력을 각각 집계해 경고와 에러의 시각 간격을 재고, 세 로그가 가리키는 하나의 원인을 문서로 묶습니다.