Loki는 살아 있는데 DLQ에 로그가 쌓인 이유
이번 대응에서 먼저 확인한 것은 Loki를 더 크게 키우는 일이 아니라, 왜 정상 응답을 하던 Loki가 특정 로그만 거부했는지였습니다.
문제는 Loki 다운이 아니었습니다
운영 환경에서 Lambda DLQ(Dead Letter Queue)에 39건의 메시지가 쌓이면서 CRITICAL 알림이 발생했습니다. 처음 현상만 보면 Loki 장애처럼 보였지만, 실제로는 Loki가 죽은 것이 아니라 정책에 맞지 않는 오래된 로그를 HTTP 400으로 거부한 상황이었습니다.
이 글은 저희가 운영 중인 CloudWatch Logs, Lambda, Loki 파이프라인에서 왜 이 현상이 발생했는지 정리한 기록입니다. 모니터링 구조 자체는 이전 글인 모니터링 아키텍처 선택: Hybrid LGTM, HA, 헬스체크 설계에서 다뤘고, 이번 글에서는 그 구조가 실제 운영 장애에서 어떤 방식으로 실패했는지에 집중해보겠습니다.
같은 구조를 운영 중이라면 이 글에서 바로 가져갈 수 있는 것은 세 가지입니다. too far behind를 다른 400 에러와 구분하는 방법, max_chunk_age와 실제 허용 지연의 관계, 그리고 운영 반영 전후에 무엇을 검증해야 하는지입니다.
즉, 수집 경로는 살아 있었지만, 시간 윈도우 설정이 정상적인 지연 로그까지 받지 못하게 만들고 있었습니다.
증상은 명확했지만 원인은 헷갈렸습니다
문제를 좁히는 데 가장 도움이 된 것은 에러 로그 원문이었습니다. 검색 가능한 문자열이 분명했고, Loki가 어떤 이유로 거절했는지도 로그 안에 이미 들어 있었습니다.
이 로그는 Loki가 왜 데이터를 거절했는지 그대로 보여주기 위해 원문 그대로 남깁니다.
Loki API 에러 (400): entry with timestamp 2026-03-10 11:12:05.915 +0000 UTC
ignored, reason: 'entry too far behind,
oldest acceptable timestamp is: 2026-03-10T11:12:21Z'
user 'fake', total ignored: 50 out of 50
사건 당시 관찰된 값은 아래와 같았습니다.
| 항목 | 값 |
|---|---|
| 거절된 로그 원본 시각 | 11:12:05 |
| Loki가 수용 가능한 최소 시각 | 11:12:21 |
| 차이 | 16초 |
| 거절 비율 | 50개 중 50개 |
에러 코드가 5xx가 아니라 400이었다는 점이 조사 방향을 바꿨습니다. 네트워크가 끊긴 것도 아니고, Loki가 응답을 못 한 것도 아니었습니다. Loki는 요청을 정상적으로 받았고, 그 요청을 너무 늦게 도착한 데이터로 판단해 거절했습니다.
Lambda 쪽에서도 이 상황은 불리했습니다. 함수 내부 재시도와 비동기 재시도가 이어졌지만, 같은 페이로드를 다시 보내는 동안 허용 가능한 시각은 더 앞으로 이동했습니다. 결과적으로 재시도는 회복이 아니라 실패 확대에 가까웠습니다.
먼저 리소스와 네트워크를 의심했습니다
처음에는 Loki ingester가 순간적으로 내려갔거나, 네트워크가 흔들렸다고 생각했습니다. 운영 장애에서는 이런 가설이 자연스럽고, 실제로도 먼저 확인해야 하는 항목입니다. 하지만 확인 결과는 예상과 달랐습니다.
| 점검 항목 | 결과 |
|---|---|
| Loki 컨테이너 재시작 | 없음 |
| ECS 이벤트 | 교체, OOM Kill 없음 |
| CPU 사용률 | 최대 8.67% |
| 메모리 사용률 | 최대 7.26% |
| HTTP 응답 | 400 응답 반환 |
이 수치만 놓고 보면 리소스 부족 가설은 설득력이 약했습니다. CPU와 메모리는 여유가 있었고, 컨테이너 재시작도 없었습니다. 네트워크 문제였다면 타임아웃이나 5xx 계열 신호가 먼저 보여야 했는데, 실제로는 Loki가 요청을 받아서 400을 돌려주고 있었습니다.
따라서 저희는 조사 방향을 “서버 상태”에서 “Loki가 로그 타임스탬프를 어떻게 해석하는가”로 바꿨습니다.
unordered_writes만으로는 부족했습니다
원인은 설정에 있었습니다. 당시 설정을 다시 보면 unordered_writes는 켜져 있었지만, 저희가 실제로 감당해야 할 지연 시간과는 맞지 않는 값 조합이었습니다.
사건 당시 Loki 관련 설정은 아래와 같았습니다.
| 설정 | 값 | 의미 |
|---|---|---|
unordered_writes |
true |
순서가 조금 뒤섞인 로그 수용 기능 활성화 |
max_chunk_age |
30s |
청크(chunk) 최대 수명 |
chunk_idle_period |
10s |
유휴 상태 청크 flush 기준 |
Grafana는 Loki 2.4 이후 unordered writes를 지원하면서, 같은 스트림 내에서 허용 가능한 시간 창 기반으로 지연 로그를 판단하도록 동작합니다. 운영에서는 max_chunk_age, chunk_idle_period, unordered_writes 조합을 함께 보면서 창의 크기를 튜닝했으며, 이 조합을 벗어나는 지연은 같은 패턴의 too far behind 응답으로 거절됩니다.
이 동작 요건은 Grafana 공식 문서와 Loki 공식 블로그에서 확인할 수 있습니다.
저희 설정에 그대로 대입하면 계산은 단순했습니다.
| 항목 | 값 |
|---|---|
max_chunk_age |
30s |
| 유효 윈도우 | 15s |
| 실제 지연 | 16s |
| 결과 | 거부 |
문제는 unordered_writes=true라는 문구만 보면 “늦게 온 로그도 받겠지”라고 생각하기 쉽다는 점입니다. 저도 처음에는 그렇게 봤습니다. 하지만 Loki는 무한정 늦은 로그를 받지 않고, 같은 스트림 안에서 허용 가능한 시간 창을 넘는 순간 거절합니다.
16초 지연이 왜 장애가 되었는지
이 사건은 지연 자체보다, 같은 스트림에 먼저 들어간 새 로그가 기준 시각을 앞으로 밀어버린 점이 더 중요했습니다.
아래 다이어그램은 그 과정을 단순화한 흐름입니다.
sequenceDiagram
participant ECS as ECS App
participant CWL as CloudWatch Logs
participant L1 as Lambda A
participant L2 as Lambda C
participant Loki as Loki
ECS->>CWL: 11:12:05 로그 발생
CWL->>L1: 먼저 전달된 배치
L1->>Loki: 즉시 전송
Loki-->>L1: 204 성공
Note over Loki: stream의 최신 시각이 갱신됨
CWL->>L2: 늦게 전달된 동일 시각대 로그
L2->>Loki: 11:12:05 로그 전송
Loki-->>L2: 400 too far behind
AWS CloudWatch Logs 공식 문서에서는 구독 필터 전달이 보통 3분 이내의 준실시간이라고 설명합니다. 즉, 수 초에서 수십 초 수준의 지연은 파이프라인에서 충분히 나올 수 있는 범위입니다. 저희 구조에서도 늦게 온 Lambda 인스턴스가 이상했던 것이 아니라, 그 정도 지연을 수용하지 못하는 Loki 설정이 문제였습니다. 이 기준은 AWS CloudWatch Logs subscriptions 문서에서 확인할 수 있습니다.
이 시점에서 재시도는 해결책이 되지 못했습니다. 같은 타임스탬프를 가진 로그를 다시 보내는 동안, Loki가 허용하는 최소 시각은 계속 앞으로 이동했기 때문입니다. Lambda 비동기 호출도 AWS Lambda 공식 문서상 기본적으로 두 번 더 재시도하므로, 정책 위반 페이로드는 더 오래 실패할 뿐이었습니다.
직접 해결은 max_chunk_age 조정이었습니다
직접적인 해결책은 Loki를 더 크게 스케일링하는 것이 아니라, out-of-order 허용 범위를 운영 현실에 맞게 늘리는 것이었습니다.
사건 대응에서 실제로 비교한 선택지는 아래와 같았습니다.
| 대안 | 장점 | 단점 | 판단 |
|---|---|---|---|
30s 유지 |
flush가 빠르고 보수적 | 정상적인 지연 로그도 계속 거부 | 미채택 |
1h로 확대 |
CloudWatch 지연과 Lambda 재시도 대부분 수용 | DLQ 재처리와 장시간 지연에 대한 여유가 작음 | 미채택 |
2h로 확대 |
재시도와 DLQ 재처리까지 한 번에 커버 | 청크 수명 증가에 따른 메모리/flush 관찰 필요 | 채택 |
| 스트림 라벨 분리 | 구조적으로 가장 명확 | 라벨 설계와 수집 경로 변경이 필요해 즉시 대응책으로는 느림 | 후속 검토 |
이번 대응의 1차 목표는 “원인 제거 + 빠른 운영 안정화”였습니다. 그래서 구조 변경이 필요한 스트림 분리보다, 현재 파이프라인을 유지한 채 허용 시간 창을 늘리는 쪽을 먼저 선택했습니다.
이 설정 변경은 허용 시간 창을 늘리기 위한 목적입니다.
# before
max_chunk_age = local.loki_ha_effective ? "30s" : "1h"
# after
max_chunk_age = "2h"
2h를 선택한 이유는 “평상시 전달 지연”뿐 아니라 “재시도와 재처리”까지 한 번에 커버하기 위해서였습니다.
| 지연 시나리오 | 예상 범위 | 2h 설정에서의 판단 |
|---|---|---|
| CloudWatch Logs 전달 지연 | 수 초 ~ 수 분 | 수용 가능 |
| Lambda 내부 재시도 | 수 초 단위 | 수용 가능 |
| Lambda 비동기 재시도 | 수 분 단위 | 수용 가능 |
| DLQ 재처리 | 수 분 ~ 수십 분 | 수용 가능 |
이 선택은 “가장 엄격한 설정”보다 “실제 운영에서 버틸 수 있는 설정”에 가깝습니다. 저희는 로그가 몇 초만 늦어져도 버려지는 시스템보다, 늦더라도 받아서 분석 가능한 시스템을 우선했습니다.
복구 과정에서 함께 정리한 운영 보완
이번 인시던트의 직접 원인은 max_chunk_age였지만, 복구 과정에서는 배포 안정성과 WAL 보호 관점의 운영 보완도 같이 드러났습니다. 아래 두 항목은 원인 해결과는 별개로, 같은 구조를 오래 운영하려면 같이 챙겨야 할 부분이었습니다.
- Tempo health check는
/ready에서/status로 바꿔서 ring stale member 때문에 배포가 교착되는 상황을 줄였습니다. - ECS 서비스에는
distinctInstance제약을 추가해 rolling deploy 중 같은 인스턴스에 WAL을 공유하는 태스크가 겹치지 않게 했습니다.
검증은 스테이징과 운영 환경을 나눠 진행했습니다
해결 여부는 “에러가 사라졌는가”보다 “이전에는 실패하던 지연 패턴을 이제 수용하는가”로 검증했습니다.
스테이징에서는 같은 수집 경로와 같은 스트림 기준으로 지연된 타임스탬프를 가진 로그를 수동 전송해 수용 여부만 따로 확인했습니다. 여기서는 16초, 1분, 3분, 30분, 1시간 지연 케이스를 순차적으로 넣어 204 응답을 확인했습니다.
이 표는 스테이징에서 지연 시간을 점점 늘려가며 Loki 수용 여부를 확인한 결과입니다.
| 케이스 | 지연 시간 | 기대 결과 | 실제 결과 |
|---|---|---|---|
| Case 1 | 16초 | 성공 | 204 PASS |
| Case 2 | 1분 | 성공 | 204 PASS |
| Case 3 | 3분 | 성공 | 204 PASS |
| Case 4 | 30분 | 성공 | 204 PASS |
| Case 5 | 1시간 | 성공 | 204 PASS |
운영 환경에서는 장시간 지연 재현을 모두 반복하지는 않았습니다. 운영 영향이 큰 테스트는 피하고, 실제 사건과 가까운 16초, 3분 지연 케이스만 확인한 뒤 30분 동안 Lambda 에러와 DLQ 메시지 수를 함께 관찰했습니다.
| 케이스 | 지연 시간 | 기대 결과 | 실제 결과 |
|---|---|---|---|
| 운영 검증 1 | 16초 | 성공 | 204 PASS |
| 운영 검증 2 | 3분 | 성공 | 204 PASS |
| 시점 | Lambda 에러 | DLQ 메시지 |
|---|---|---|
| +10분 | 0 | 0 |
| +20분 | 0 | 0 |
| +30분 | 0 | 0 |
즉, 문제는 특정 로그 몇 건의 우연한 실패가 아니라, 지연 로그를 구조적으로 거부하던 설정이었습니다.
적용 시 감수하는 것과 다시 점검할 신호
max_chunk_age를 늘리면 항상 좋은 것은 아닙니다. 허용 시간 창이 커지는 대신, 열려 있는 청크의 수명과 메모리 점유 시간이 길어질 수 있습니다.
이번 변경 이후 저희가 계속 봐야 하는 지표는 아래와 같습니다.
| 항목 | 왜 보는가 | 다시 조정할 신호 |
|---|---|---|
| Ingester 메모리 사용률 | 오래 열린 청크 증가 여부 확인 | 평시 대비 지속 상승 |
| Flush 지연/실패 | 청크 수명 증가가 flush 지연 누적을 만드는지 확인 | flush 실패나 지연 누적 |
too far behind/쓰기 거부 수 |
정책 거부 재발 확인 | 400 거부 재등장 |
| 최근 로그 query 지연 | 쓰기 정책 변경이 조회 경험에 미치는 영향 확인 | 최근 구간 조회 지연 증가 |
롤백 기준도 미리 정해두는 편이 좋습니다. 메모리 압박이나 flush 지연 누적이 눈에 띄게 증가하면 2h를 유지할지 다시 판단해야 합니다. 그 경우에는 1h로 낮추거나, 느리게 도착하는 소스를 별도 라벨로 분리해 스트림 자체를 나누는 쪽이 더 맞을 수 있습니다.
같은 구조라면 무엇부터 확인할지
CloudWatch Logs, Lambda, Loki를 비슷하게 연결해두었다면 아래 순서로 확인해보는 편이 빠릅니다.
- 에러 코드가
400인지5xx인지 먼저 구분합니다.400이면 정책 거부 가능성을 먼저 봐야 합니다. - 에러 로그에
too far behind문구가 있는지 확인합니다. 이 문자열은 조사 방향을 거의 결정해줍니다. max_chunk_age,chunk_idle_period,unordered_writes조합을 함께 봅니다. 한 값만 보면 실제 허용 창을 놓치기 쉽습니다.- 늦게 도착하는 소스와 빠르게 도착하는 소스가 같은 스트림으로 섞이는지 점검합니다. Grafana도 공식 문서에서 ingestion delay가 다른 로그는 label로 스트림을 분리하는 방식을 권장합니다.
- 재시도가 문제를 해결하는 에러인지, 아니면 실패를 늘리는 에러인지 분리합니다.
too far behind는 후자에 가깝습니다.
이 접근이 항상 맞는 것은 아닙니다. ingestion 규모가 매우 크거나 메모리 여유가 낮은 환경에서는 max_chunk_age를 크게 늘리는 선택이 chunk 관리 비용을 늘릴 수 있습니다. 또한 느린 소스가 일부 스트림에만 집중되어 있다면 전체 윈도우를 키우기보다 라벨 분리로 스트림을 나누는 방식이 더 나을 수 있습니다.
정리
- 이번 장애는 Loki 다운이 아니라,
max_chunk_age=30s가 만든 15초 유효 윈도우 때문에 발생했습니다. unordered_writes=true만으로는 충분하지 않았고, 같은 스트림 안에서 허용 가능한 시간 창을 넘으면 Loki는 400으로 거절했습니다.- 리소스 증설보다 중요한 것은 지연 로그, 재시도, DLQ 재처리를 함께 고려한 시간 윈도우 설정이었습니다.
max_chunk_age를2h로 조정한 뒤 16초, 1분, 3분, 30분, 1시간 지연 로그 모두204로 수용되는 것을 확인했습니다.- 이 방식은 지연 수용이 중요한 파이프라인에 적합합니다. 반대로 ingestion 비용과 chunk 관리가 더 민감한 환경에서는 라벨 분리나 스트림 설계부터 다시 보는 편이 맞습니다.
비슷하게 “서버는 정상인데 로그만 안 들어오는” 상황을 겪으셨다면, 어떤 지점에서 원인을 좁혀가셨는지도 궁금합니다. 더 좋은 점검 순서가 있다면 댓글로 공유 부탁드립니다.
Comments