내 에러 모니터가 3일 전에 끝난 장애를 매일 신고하고 있었다

"ja 채널 perf 쿼리가 매일 같은 시각에 500으로 실패합니다." 텔레그램 알림이 사흘 연속 같은 문구로 왔습니다. 서버측 500이니 폴백도 물려 있고, Google Analytics API가 가끔 500 뱉는 건 흔한 일이라 넘길 뻔했습니다. 그런데 하나가 걸렸습니다. 왜 하필 매일 같은 시각에, 정확히 ja 채널만.

질문 하나 먼저 드립니다. 당신의 알림 시스템은, 자기가 만든 알림을 다시 장애로 잡아낼 수 있습니까? 저는 이 질문을 해본 적이 없었습니다.

1원칙: 진짜 숫자 하나부터

지표를 볼 때 저는 한 문장을 강제로 겁니다. "여기서 진짜 의미 있는 숫자 하나가 뭐냐, 나머지는 파생 아니냐." 알림은 사흘간 최소 세 건. 그럼 500이 세 번 났나? 로그를 시간순으로 폈습니다.

08-04 18:30  [perf] ja — 쿼리실패:<HttpError 500 ... (순서 유지/폴백)
08-05 18:32  [perf] ja 순서: ['ddi','zodiac',...] | 점수 정상
08-06 18:34  [perf] ja 순서: ['ddi','zodiac',...] | 점수 정상
08-07 18:30  [perf] ja 순서: ['ddi','zodiac',...] | 점수 정상

진짜 500은 08-04 딱 한 번이었습니다. 08-05부터 ja perf 쿼리는 멀쩡히 점수를 뽑고 있었습니다. 그런데 알림은 매일 왔습니다. 신호는 1건, 알림은 4건. 파생 3건이 어디서 왔느냐가 진짜 문제였습니다.

접두가 하루에 하나씩 늘고 있었다

알림 원문을 나란히 붙여 봤습니다.

08-04  [shorts] [perf] ja — 쿼리실패:<HttpError 500 ...
08-05  [shorts] [shorts] [perf] ja — 쿼리실패:<HttpError 500 ...
08-06  [shorts] [shorts] [shorts] [perf] ja — 쿼리실패:<HttpError 500 ...
08-07  [shorts] [shorts] [shorts] [shorts] [perf] ja — 쿼리실패:<HttpError 500 ...

[shorts] 접두 개수 = 경과 일수. 이건 절대 우연이 아닙니다. 무언가가 어제의 알림 라인을 오늘 다시 읽어서, 앞에 자기 라벨을 하나 더 붙여 다시 내보내고 있었습니다.

모니터가 자기 꼬리를 먹고 있었다

고장 감지기(fleet_events)의 동작은 이렇습니다. 봇 로그들을 스캔해서 고장 마커(HttpError [45]\d\d, Traceback 등)가 있는 새 줄만 골라 텔레그램으로 보냅니다. 문제는 두 줄의 조합이었습니다.

# fleet_events: 찾은 고장을 stdout에 출력
print("[fleet_events]\n" + body)   # body에 "[shorts] [perf] ja ... HttpError 500"

# autopilot.sh: 그 stdout을 스캔 대상 로그에 append
$PY engine/fleet_events.py  >> docs/autopilot.log 2>&1

모니터가 자기 출력을 autopilot.log에 쓰는데, 바로 그 파일이 모니터가 내일 스캔할 로그였습니다. 다음 날 스캔이 자기가 쓴 HttpError 500 라인을 다시 만나고, 고장 마커에 매치되니 다시 알림, 라벨 하나 더 붙여 또 로그에 append. 자기 꼬리를 먹는 뱀. 08-04의 일시적 500 한 번이 영구 기관이 된 겁니다.

여기서 멈추고 여쭙겠습니다. 당신이라면? 500 알림을 보고 재시도 로직이나 폴백을 손보겠습니까 — 존재하지도 않는 서버 문제를 고치면서? 아니면 "이 알림이 진짜인가"부터 세어 보겠습니까? 저는 처음엔 전자로 손이 나갔습니다.

같은 날, 대시보드도 거짓말을 했다

그리고 같은 세션에서 자기개선 게이트 대시보드가 이런 행을 보여주고 있었습니다.

리패키징 플래그   aftermath   4 / 4   ○ 대기

4/4면 임계 도달인데 왜 대기? 값싼 버그처럼 보였습니다. 추적해 보니 한 줄에 서로 다른 두 데이터 소스가 섞여 있었습니다. "현재(4)"는 발행 목록의 롱폼 개수를 셌고, "발화 판정"은 전혀 다른 파일(리패키징 후보 산출물)의 존재 여부를 봤습니다. 실제 게이트가 보는 입력은 또 달랐습니다 — Analytics에 조회가 잡힌 롱폼 수(당일 발행분은 집계 지연으로 아직 3편). 그러니 4/4는 사실이고, 대기도 정상 동작이고, 다만 표시가 둘을 한 판정처럼 붙여 놓아 모순으로 읽혔습니다. 현재 >= 임계인데 미발화면 집계대기로 라벨을 갈라 착시를 걷어냈습니다.

두 증상, 한 뿌리

에코 루프와 자기모순 행은 겉보기엔 다르지만 같은 병입니다. 관측 도구가 관측 대상과 얽혔다. 하나는 자기가 쓰는 것을 읽었고, 하나는 두 소스를 한 판정에 섞었습니다.

수정은 뿌리에서 했습니다.

모니터 출력을 스캔 대상이 아닌 별도 로그(docs/monitor.log)로 분리. 알림은 어차피 텔레그램과 이력 파일에 남으니 손실 없음.
방어 이중화: 스캔 함수가 자기 출력 서명([label] 접두·알림 헤더)을 만나면 건너뛰게. 로그 리셋/로테이션으로 과거 메아리를 다시 읽어도 안전.
대시보드는 "현재"와 "발화"가 다른 소스일 때 집계대기로 구분.

솔직한 부분

제가 고친 건 거짓 반복 신고입니다. 08-04의 500 자체는 Google 서버측 일시 오류라 제가 못 막습니다 — 그건 폴백이 이미 처리했고, 애초에 고칠 것도 아니었습니다. 진짜 위험은 500이 아니라, 노이즈가 매일 울리면 진짜 알림이 왔을 때 무시하게 된다는 겁니다. 자기참조 알림은 늑대다 외치는 양치기를 자동화한 것과 같습니다.

당신의 파이프라인을 지금 점검할 세 가지:

알림/모니터의 출력이 그 모니터의 입력(스캔 대상)으로 되돌아가는 경로가 있는가? 로그를 한 파일에 몰아 쓰면 십중팔구 있다.
대시보드의 한 행에서 "현재 값"과 "상태 판정"이 같은 소스에서 나오는가, 아니면 그럴듯하게 붙여 놓았을 뿐인가?
반복되는 알림을 볼 때, 건수만큼 실제 이벤트가 있었는지 로그를 시간순으로 세어 봤는가?

관련해서, 같은 날 "고장 나 보이던 지표가 실은 의도된 설계였던" 이야기도 따로 적었습니다. 지표를 믿기 전에 코드를 읽는 습관에 대한 글입니다. 알림 인프라 자체를 짜던 초기 기록은 여기 있습니다.

지금 딱 하나만 해보세요. 당신의 알림 스크립트가 로그를 append하는 파일과, 그 스크립트가 다음에 스캔하는 파일이 같은 파일인지 grep 한 번. 같다면, 당신도 자기 꼬리를 먹고 있을지 모릅니다.