경고는 에러보다 먼저 온다

한 줄 요약

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

왜 이게 필요했나

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

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

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

어떻게 동작하나

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

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