Loki ingester가 OOM으로 죽고 7시간 동안 로그가 사라진 이야기

지난주 수요일 새벽이었다. 새벽 2시쯤 자다가 슬랙 멘션 알림에 깼다. "어제 오후 4시부터 지금까지 로그가 안 보여요." 운영팀 야간 담당자였다. 휴대폰 화면 밝기에 눈이 시리면서도 멘탈은 이미 깨어버린 상태. 우리 클러스터는 노드 80대 규모에 Loki 3.7.x를 미러 모드로 돌리고 있었고, 하루에 1.5TB 정도의 로그를 받는다. 그게 7시간 동안 사라졌다는 얘기다.

솔직히 처음엔 좀 의심했다. "진짜 7시간 동안 아무도 모를 수가 있나?" 근데 확인해보니 진짜였다. Grafana에서 last 24h로 보면 오후 4시 지점에서 갑자기 라인이 뚝 끊겨 있었다. 그래프가 그렇게 정직하게 끊긴 건 처음 봤다.

ingester pod 상태부터 봤다

가장 먼저 한 일은 ingester pod의 상태 확인이었다. 6개 replica로 돌리고 있었는데 그 중 4개가 OOMKilled 상태로 CrashLoopBackOff에 빠져 있었다. 나머지 2개는 살아 있긴 했지만 거의 빈사 상태.

$ kubectl get pods -n loki -l app.kubernetes.io/component=ingester
NAME                READY   STATUS             RESTARTS         AGE
loki-ingester-0     1/1     Running            0                7d
loki-ingester-1     0/1     CrashLoopBackOff   23 (2m12s ago)   7d
loki-ingester-2     0/1     CrashLoopBackOff   21 (3m45s ago)   7d
loki-ingester-3     1/1     Running            1 (4h ago)       7d
loki-ingester-4     0/1     CrashLoopBackOff   19 (1m08s ago)   7d
loki-ingester-5     0/1     CrashLoopBackOff   18 (4m22s ago)   7d

문제는 이게 단순한 메모리 부족이 아니라는 점이었다. memory limit을 8Gi에서 12Gi로 올려도 같은 자리에서 OOM이 나고, 16Gi로 올려도 똑같았다. 죽는 시점에 본 메모리 사용량 그래프는 거의 수직 상승이었다. 5분 안에 0에서 limit까지 찍었다.

무엇이 메모리를 먹고 있었나

원인을 찾기 위해 ingester가 죽기 직전의 메트릭을 봤다. loki_ingester_memory_streams가 평소 12만 개 정도였는데, 오후 4시 직전부터 갑자기 80만 개를 넘어가고 있었다. 7배가 늘어난 거다.

스트림 수가 폭증한 이유를 찾는 데 한참 걸렸다. 결국 범인은 한 서비스의 로그 라이브러리 업데이트였다. 새로 들어간 버전이 request_id를 로그 라벨에 넣고 있었다. 라벨 카디널리티가 박살난 거다. 1분 만에 수십만 개의 새 스트림이 생겼고, 각 스트림마다 최소 하나의 청크를 메모리에 올려두는 Loki 구조상 메모리가 버틸 수가 없었다.

근데 더 큰 문제는 따로 있었다. ingester가 죽으면서 WAL에 쓰여 있던 데이터를 flush 못 하고 있었다. 재시작될 때마다 WAL replay를 하다가 다시 OOM. 무한 루프였다. 7시간이 이렇게 사라진 거다.

어떻게 빠져나왔나

새벽 2시 30분쯤 동료를 깨워서 같이 봤다. 우리가 했던 것들을 시간 순으로 정리하면 이렇다.

먼저 문제의 서비스를 식별하고 그 서비스의 로그 수집을 일단 중단시켰다. Promtail의 __path__ 매칭을 빼서 입수 자체를 막았다. 그래야 ingester가 숨을 좀 쉴 수 있을 것 같았다.

두 번째로 ingester의 max_streams_per_user 제한을 강제로 걸었다. 평소에는 0(무제한)으로 놔뒀던 건데, 이 사고 이후로는 무조건 상한을 둔다.

limits_config:
  max_streams_per_user: 200000
  max_global_streams_per_user: 800000
  per_stream_rate_limit: 5MB
  per_stream_rate_limit_burst: 20MB
  cardinality_limit: 200000

세 번째로 WAL 디렉토리를 일부 백업한 뒤 살릴 수 있는 만큼만 남기고 정리했다. 사실 이건 좀 거친 방법이긴 한데, 새벽 3시에 정상적인 판단은 어려웠다. 정확히는 WAL 디렉토리에서 사이즈 큰 segment 파일을 한쪽으로 옮겨 놓고 ingester를 재시작했다. 살아남았다.

네 번째로 chunk flush를 강제로 트리거했다. /flush 엔드포인트를 호출해서 메모리에 떠 있던 청크를 backend storage로 밀어냈다. 30분 정도 걸렸다.

사후 분석에서 알게 된 것들

다음 날 사후 분석 미팅에서 몇 가지가 명확해졌다.

첫째, 우리는 카디널리티 알람이 없었다. loki_ingester_memory_streams의 급격한 증가를 잡을 수 있는 알람이 단 하나도 없었다. 메모리 사용량 알람은 있었지만 그건 이미 늦은 시그널이다. 메모리가 차오를 때쯤이면 이미 OOM 직전이다.

둘째, 라벨 변경에 대한 거버넌스가 없었다. 어플리케이션 팀이 자유롭게 라벨을 추가할 수 있었고, 인프라 팀은 그걸 인지할 방법이 없었다. 지금은 라벨 변경 시 PR에 인프라 팀 리뷰어를 강제로 넣게 했다.

셋째, WAL replay가 OOM을 유발할 때 빠져나오는 표준 절차가 없었다. 새벽에 우리가 한 건 거의 야매에 가까웠다. 동료가 "이게 진짜 옳은 방법인지 모르겠는데"라고 말하면서 명령어를 친 게 기억난다. 지금은 런북에 절차가 정리되어 있다.

넷째, 그리고 가장 중요한 건데 — 단일 Loki 클러스터에 모든 서비스의 로그를 다 박아놓는 구조 자체가 문제였다. 한 팀의 실수가 전체 가시성을 죽일 수 있는 구조다. 이 부분은 아직도 해결 중이다. tenant 분리를 진지하게 검토하고 있는데, 운영 복잡도 때문에 결정이 쉽지 않다.

그래서 결론은

솔직히 이 글 쓰면서도 좀 부끄럽다. 카디널리티 폭증은 Loki 운영의 가장 클래식한 함정이고, 다들 한 번씩 겪는다는 걸 안다. 우리도 안다고 생각했다. 근데 "안다"는 것과 "잡을 수 있다"는 건 다른 얘기였다.

지금 우리 모니터링에는 loki_ingester_memory_streams 5분 변화율 알람과 loki_distributor_lines_received_total의 갑작스러운 스파이크 알람이 들어가 있다. 두 알람이 적절히 동작하는지는 아직 검증 중이다. 더 나은 방법이 있을 수도 있다.

혹시 비슷한 사고 겪고 빠져나온 방법이 있으면 공유 부탁드린다.