LabHub
배우기 러닝패스 코스

Finding the Cause in Logs

The Absence of Logs Is Also Information

LabHub 에서 이어서 보기

한국어 원문으로 표시합니다.

한 줄 요약

로그가 없으면 조사가 끝나는 게 아닙니다. 다른 흔적으로 시간을 좁히고, 그다음 사고에는 로그가 남도록 만드는 것까지가 일입니다.

Concept map: 다른 흔적 · 데이터 자체가 로그입니다. · 비어 있는 구간 · 로그 문장 추가

왜 이게 필요했나

"어제 오후에 몇 건 실패했대요" 라는 신고를 받고 로그를 찾습니다. 그런데 보존이 24시간이라 이미 지워졌거나, 로그 레벨이 WARN 이라 필요한 정보가 안 찍혔거나, 애초에 그 구간에 로그 문장이 없습니다.

이때 "로그가 없어서 확인 불가" 로 종결하면 같은 일이 반복됩니다.

로그가 아닌 흔적들

흔적 무엇을 알려 주나 확인 방법
파일 mtime 언제 무엇이 바뀌었나 find /etc -mmin -1440 -type f
DB 타임스탬프 데이터가 생긴/바뀐 시각 created_at, updated_at 분포
프로세스 시작 시각 언제 재시작됐나 ps -eo pid,lstart,cmd
시스템 부팅 시각 서버가 언제 올라왔나 uptime -s
파일 크기 변화 언제 급증했나 백업 스냅샷 간 비교
패키지 설치 시각 무엇이 언제 들어왔나 /var/log/dpkg.log, rpm -qa --last
셸 히스토리 사람이 무엇을 했나 ~/.bash_history (시각 설정 시)
인증서 유효기간 만료로 인한 장애 시각 openssl x509 -noout -dates

데이터 자체가 로그입니다. 실패한 주문의 created_at 분포를 분당으로 집계하면, 로그가 없어도 사고가 시작된 분(minute)을 특정할 수 있습니다.

SELECT date_trunc('minute', created_at) AS m, count(*)
FROM orders WHERE status='FAILED' AND created_at >= now() - interval '2 days'
GROUP BY 1 ORDER BY 1;

이 결과에서 값이 튀는 지점이 사고 시각입니다. 그리고 그 시각을 배포 기록, 설정 변경, 부팅 시각과 대조하면 후보가 하나둘로 줄어듭니다.

없다는 사실도 증거다

로그가 비어 있는 구간은 그 자체로 정보입니다.

"안 찍혔다" 를 "모른다" 로 번역하지 말고, "무엇이 안 찍혔는가" 를 물으면 범위가 좁아집니다.

다음을 위해 남긴다

조사 끝에 원인을 찾았다면 마지막 작업은 같은 일이 또 나도 이번보다 빨리 알 수 있게 만드는 것입니다.

  1. 로그 문장 추가 — 실패 경로에 무엇이 왜 실패했는지. 사후 조사에서 필요했던 값(요청 ID, 대상, 소요 시간)을 함께.
  2. 보존 기간 조정 — 24시간은 대부분의 조사에 부족합니다. 최소한 에러 로그만이라도 길게.
  3. 상관 ID — 요청마다 ID 를 붙여 시스템을 가로질러 추적할 수 있게. 이게 없으면 여러 서비스의 로그를 시각으로만 맞춰야 합니다.
  4. 지표 하나 — 이번에 문제였던 것을 카운터나 게이지로. 다음엔 그래프에서 보입니다.

이 네 가지를 보고서의 "재발 방지" 항목에 적으면, 그건 형식적인 문장이 아니라 실제로 다음 조사를 몇 시간 단축시킵니다.

사후 계측 — 지금 당장 필요한 경우

문제가 지금 진행 중인데 로그가 없다면, 재현되는 동안 관찰을 붙입니다.

거칠지만, 아무것도 없는 것보다 압도적으로 낫습니다. 그리고 이 파일이 다음 회의에서 유일한 근거가 됩니다.

남의 시스템에서 관측을 처음 붙일 때

FDE 로 들어간 현장에는 대개 로그가 없거나, 있어도 못 본다. 권한도 없고 배포도 마음대로 못 하는 상태에서 가장 적은 변경으로 가장 많이 보는 순서가 있다.

첫째, 이미 있는 것을 찾는다. 새로 붙이기 전에 그 시스템이 이미 남기고 있는 것을 센다. 웹 서버 접근 로그, 데이터베이스의 느린 질의 로그, 로드밸런서 통계, 클라우드의 흐름 로그. 대개 켜져 있는데 아무도 안 보고 있다.

둘째, 밖에서 잰다. 코드를 못 고쳐도 밖에서 두드리는 것은 할 수 있다. 몇 분 간격으로 핵심 경로를 호출해 응답 시간과 상태 코드를 남기면, 장애가 언제 시작됐는지는 그것만으로 알 수 있다. 원인을 모르더라도 시각을 아는 것이 조사의 절반이다.

셋째, 경계에 붙인다. 애플리케이션을 못 고쳐도 그 앞의 프록시나 사이드카는 바꿀 수 있는 경우가 많다. 요청 단위로 시간과 상태를 남기게 하면 코드를 한 줄도 안 고치고 요청별 관측이 생긴다.

넷째, 그때 비로소 코드를 고친다. 여기까지 오면 어디를 계측해야 하는지 이미 안다. 처음부터 코드에 손대면 엉뚱한 곳을 계측하게 되고, 그 변경을 되돌리는 비용까지 낸다.

남길 것과 남기지 말 것을 처음에 정한다. 남의 시스템일수록 개인정보가 무엇인지 모른 채 로그를 켜기 쉽다. 요청 본문을 통째로 남기는 설정은 켜기 전에 무엇이 들어 있는지 먼저 본다.

보고할 때는 숫자와 함께 그 숫자의 출처를 적는다. "느립니다" 가 아니라 "이 경로의 p95 가 4.2초이고, 로드밸런서 기준 지난 7일 중앙값은 0.4초입니다" 라고 쓰면, 그 자리에서 다음 행동이 정해진다. 출처가 없으면 그 숫자부터 다시 다투게 된다.

현장에서 만나는 모습

이어지는 실습에서 할 것

사고 구간의 오류 로그가 사라진 현장을 받습니다. 데이터의 created_at, 접근 로그의 빈 구간, 설정 파일의 수정 시각만으로 사고 시각을 분 단위까지 좁히고 후보를 하나로 만듭니다.

마지막에는 사후 계측기를 직접 만들어 봅니다. 채점기가 그것을 실제로 돌려 시각과 관찰값이 주기적으로 남는지 확인합니다.