From 3017eb60772efd9a21eb6eff03d517895b8437f5 Mon Sep 17 00:00:00 2001 From: jmj Date: Tue, 29 Sep 2026 21:20:18 +0900 Subject: [PATCH] =?UTF-8?q?fix(ops):=20=EB=B0=B0=ED=8F=AC=ED=95=A0=20?= =?UTF-8?q?=EB=95=8C=EB=A7=88=EB=8B=A4=20=ED=97=AC=EC=8A=A4=20=EC=95=8C?= =?UTF-8?q?=EB=A6=BC=EC=9D=B4=20=ED=97=9B=EC=9A=B8=EB=A6=AC=EB=8D=98=20?= =?UTF-8?q?=EB=AC=B8=EC=A0=9C?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 오늘 21:08 에 PR 두 건을 병합해 배포가 돌았고, 21:10 폴링이 "[실패] 헬스 이상: DEGRADED / scheduler=DOWN" 을 팀 채널에 보냈다. 21:15 에 복구 알림. 장애가 아니라 배포였다. 원인 두 가지를 각각 맞는 층에서 고친다. 1) SchedulerHeartbeat 가 부팅 직후를 "스케줄러 죽음"으로 보고했다. lastBeat 가 null 로 시작하고 첫 박동은 initialDelay 10초 뒤라, Tomcat 이 뜬 뒤 10초 동안 엔드포인트는 정상 응답하면서 scheduler=DOWN 을 돌려준다. 오늘 기동이 12:09:53, 크론이 */5 정각이라 12:10:00 폴링이 그 창의 7초 지점에 꽂혔다. 우연이 아니라 배포가 정각 직전에 끝나면 늘 울린다. 기동 시각으로 시드한다. 스케줄러가 영영 안 뛰는 경우는 그 값이 늙어 maxAge(5분)를 넘겨 여전히 DOWN 으로 잡힌다 — 감지가 최대 5분 늦어질 뿐이고 그게 "안 뛴다"의 정의다. 기존 테스트 두 개가 정반대(한 번도 안 뛰었으면 DOWN, lastBeat 초기 null)를 고정하고 있었다. 그게 곧 버그라 의도에 맞게 다시 썼다. 2) 감시가 비정상을 1회만 보고 알렸다. 배포는 컨테이너를 재생성하므로 AiServerHealthIndicator 도 같은 성격으로 DOWN 이 된다(큐 컨슈머 0 — AI 컨테이너가 다시 붙는 중). 오늘 실제로 ai.* 큐 9개가 재시작 창에서 컨슈머 0 이었다. 지표만으로는 "배포 중"과 "죽었다"를 구분할 수 없고 구분되는 건 지속 시간뿐이다. 같은 비정상을 연속 2회(≈5분 간격) 봐야 알린다. 상태 파일을 두 줄 (마지막으로 알린 상태 / 확정 대기 후보)로 바꿨고, 운영에 있는 기존 한 줄 파일에서도 그대로 이어진다(확인함). 복구는 지연 없이 알린다 — 늦추면 아직 장애중으로 오해한다. 대가는 진짜 장애 감지가 최대 한 주기 늦는 것이고, 스위퍼 주기가 2~5분인 서비스라 감당할 수 있다. 배포마다 헛울려 아무도 안 읽는 알림보다 낫다. 한 번 걸러 한 번씩 나빠지는 플래핑은 잡지 못한다 — README 에 적었다. selftest 에 배포 블립 케이스(이상 1회 후 복귀 → 무발송)를 넣었다. 22건 통과. --- .../common/health/SchedulerHeartbeat.java | 12 ++++++-- .../health/SchedulerHealthIndicatorTest.java | 26 +++++++++++++---- infra/ops/README.md | 17 ++++++++++- infra/ops/health-check.sh | 29 +++++++++++++++++-- infra/ops/selftest.sh | 24 ++++++++++++--- 5 files changed, 93 insertions(+), 15 deletions(-) diff --git a/backend/src/main/java/com/stackup/stackup/common/health/SchedulerHeartbeat.java b/backend/src/main/java/com/stackup/stackup/common/health/SchedulerHeartbeat.java index f393548e..e02e11c7 100644 --- a/backend/src/main/java/com/stackup/stackup/common/health/SchedulerHeartbeat.java +++ b/backend/src/main/java/com/stackup/stackup/common/health/SchedulerHeartbeat.java @@ -27,7 +27,15 @@ public class SchedulerHeartbeat { private static final Logger log = LoggerFactory.getLogger(SchedulerHeartbeat.class); - private final AtomicReference lastBeat = new AtomicReference<>(); + // 기동 시각으로 채워 둔다. 비워 두면 **부팅 직후가 "스케줄러가 죽었다"로 보고된다** — + // Tomcat 이 뜬 뒤 첫 박동(initialDelay 10초)까지 10초 동안 엔드포인트는 정상 응답하면서 + // scheduler=DOWN 을 돌려준다. 2026-09-29 배포에서 실제로 그 창에 5분 주기 감시가 + // 꽂혀 팀 채널에 "[실패] 헬스 이상: DEGRADED" 가 나갔다(12:09:53 기동 / 12:10:00 폴링). + // 배포마다 헛울리는 알림은 읽히지 않게 되고, 그러면 진짜 장애도 같이 묻힌다. + // + // 스케줄러가 영영 안 뛰는 경우도 여전히 잡힌다 — 이 값이 그대로 늙어 maxAge(5분)를 + // 넘으면 DOWN 이다. 감지가 최대 5분 늦어질 뿐이고, 그건 "안 뛴다"의 정의와 같다. + private final AtomicReference lastBeat = new AtomicReference<>(Instant.now()); @Scheduled( fixedDelayString = "${scheduling.heartbeat-interval-ms:60000}", @@ -40,7 +48,7 @@ public void beat() { } } - /** 마지막 박동. 한 번도 뛰지 않았으면 null(기동 직후 또는 스케줄러 미동작). */ + /** 마지막 박동. 기동 시각으로 시작하므로 null 이 아니다(위 주석 참고). */ public Instant lastBeat() { return lastBeat.get(); } diff --git a/backend/src/test/java/com/stackup/stackup/common/health/SchedulerHealthIndicatorTest.java b/backend/src/test/java/com/stackup/stackup/common/health/SchedulerHealthIndicatorTest.java index 102e7fb8..dabd4245 100644 --- a/backend/src/test/java/com/stackup/stackup/common/health/SchedulerHealthIndicatorTest.java +++ b/backend/src/test/java/com/stackup/stackup/common/health/SchedulerHealthIndicatorTest.java @@ -49,22 +49,36 @@ private SchedulerHeartbeat heartbeatAt(Instant at) { assertThat(health.getStatus()).isEqualTo(Status.UP); } + // 이 두 테스트는 예전에 정반대를 고정하고 있었다("한 번도 안 뛰었으면 DOWN"). + // 그게 곧 버그였다 — 부팅 직후 10초(첫 박동 전)를 "스케줄러가 죽었다"로 보고해 + // 2026-09-29 배포에서 팀 채널에 헛알림이 나갔다. @Test - void 한_번도_안_뛰었으면_DOWN() { + void 기동_직후_첫_박동_전에도_UP() { Health health = new SchedulerHealthIndicator(new SchedulerHeartbeat(), 300).health(); - assertThat(health.getStatus()).isEqualTo(Status.DOWN); - assertThat(health.getDetails().get("reason").toString()) - .contains("아직 한 번도 실행되지 않았습니다"); + assertThat(health.getStatus()) + .as("방금 부팅한 것과 스케줄러가 죽은 것은 다르다") + .isEqualTo(Status.UP); + } + + @Test + void 한_번도_안_뛴_채_한도를_넘기면_DOWN() { + // 기동 시각으로 시드해도 스케줄러가 영영 안 뛰면 그 값이 늙어 잡힌다. + // 감지가 최대 maxAge 만큼 늦어질 뿐이고, 그게 "안 뛴다"의 정의다. + SchedulerHeartbeat neverBeat = heartbeatAt(Instant.now().minus(6, ChronoUnit.MINUTES)); + + assertThat(new SchedulerHealthIndicator(neverBeat, 300).health().getStatus()) + .isEqualTo(Status.DOWN); } @Test void beat_는_시각을_갱신한다() { SchedulerHeartbeat hb = new SchedulerHeartbeat(); - assertThat(hb.lastBeat()).isNull(); + Instant seeded = hb.lastBeat(); + assertThat(seeded).as("기동 시각으로 시드된다").isNotNull(); hb.beat(); - assertThat(hb.lastBeat()).isNotNull(); + assertThat(hb.lastBeat()).isAfterOrEqualTo(seeded); } } diff --git a/infra/ops/README.md b/infra/ops/README.md index 2ec66205..1ef5e563 100644 --- a/infra/ops/README.md +++ b/infra/ops/README.md @@ -32,7 +32,22 @@ ## 설계 결정 **상태가 바뀔 때만 보낸다.** 5분마다 같은 말을 보내면 아무도 안 읽게 되고, 그러면 진짜 장애 -때도 안 읽는다. 마지막 상태를 `~/.stackup-health-state` 에 두고 비교한다. +때도 안 읽는다. `~/.stackup-health-state` 에 두 줄(마지막으로 알린 상태 / 확정 대기 중인 +비정상 후보)을 두고 비교한다. + +**비정상은 연속 2회 봐야 알린다.** 처음엔 1회로 알렸는데 **배포마다 헛울렸다.** 배포는 +컨테이너를 재생성하므로 그 직후 몇십 초 동안 `scheduler`(첫 박동 전)·`aiServer`(큐 컨슈머 +0, 다시 붙는 중)가 정상적으로 비정상으로 관측된다. 2026-09-29 배포에서 실제로 +"[실패] 헬스 이상: DEGRADED / scheduler=DOWN" 이 팀 채널에 나갔다(기동 12:09:53, +폴링 12:10:00). + +지표만 보고는 "배포 중"과 "죽었다"를 구분할 수 없다 — 구분되는 건 **지속 시간**뿐이다. +대가는 진짜 장애 감지가 최대 한 주기(≈5분) 늦는 것이고, 스위퍼 주기가 2~5분인 서비스라 +감당할 수 있다. **복구 알림은 지연 없이** 보낸다(늦추면 아직 장애중으로 오해한다). +한 번 걸러 한 번씩 나빠지는 플래핑은 이 방식으로 잡히지 않는다. + +(`scheduler` 쪽 헛알림은 근본 원인도 따로 고쳤다 — `SchedulerHeartbeat` 가 기동 시각으로 +시드돼 "방금 부팅"을 "스케줄러 죽음"으로 보고하지 않는다.) **첫 실행이 정상이면 아무것도 안 보낸다.** "처음부터 정상"은 알릴 일이 아니다. diff --git a/infra/ops/health-check.sh b/infra/ops/health-check.sh index 2a5300ba..7029c0d1 100755 --- a/infra/ops/health-check.sh +++ b/infra/ops/health-check.sh @@ -47,13 +47,38 @@ print(state, detail) [ -n "${current:-}" ] || { current="UNPARSEABLE"; detail="헬스 응답 해석 실패"; } fi -previous=$(cat "$STATE_FILE" 2>/dev/null || echo "") -printf '%s' "$current" > "$STATE_FILE" +# 상태 파일은 두 줄이다: 1) 마지막으로 **알린** 상태 2) 아직 확정되지 않은 비정상 후보. +# 예전에는 한 줄(마지막 관측 상태)이었고, 그래서 **한 번만 나쁘면 바로 알렸다.** +# +# 그게 배포마다 헛울렸다. 배포는 컨테이너를 재생성하므로 그 직후 몇십 초 동안 +# · scheduler = 아직 첫 박동 전 (백엔드에서 따로 고쳤다) +# · aiServer = 큐 컨슈머 0 (AI 컨테이너가 다시 붙는 중) +# 이 정상적으로 관측된다. 지표만 보고는 "배포 중"과 "죽었다"를 구분할 수 없다 — +# 구분되는 건 **지속 시간**뿐이다. 그래서 같은 비정상을 연속 2회(≈5분 간격) 봐야 알린다. +# +# 대가: 진짜 장애 감지가 최대 한 주기 늦는다(≈10분). 스위퍼 주기가 2~5분인 서비스라 +# 감당할 수 있고, 배포마다 헛울려 아무도 안 읽는 알림보다 낫다. +# 한계: 한 번 걸러 한 번씩 나빠지는 플래핑은 잡지 못한다. +previous=$(sed -n '1p' "$STATE_FILE" 2>/dev/null || echo "") +pending=$(sed -n '2p' "$STATE_FILE" 2>/dev/null || echo "") + +write_state() { printf '%s\n%s\n' "$1" "${2:-}" > "$STATE_FILE"; } if [ "$current" = "$previous" ]; then + write_state "$previous" "" # 후보 취소 — 알린 상태로 되돌아왔다 exit 0 # 같은 상태 반복 — 조용히 넘어간다 fi +# 복구는 즉시 알린다. 지연시킬 이유가 없고(나쁜 소식이 아니다), 늦추면 "아직도 장애중" +# 으로 오해한다. 단, 애초에 알린 적 없는 비정상의 '복구'는 보내지 않는다 — +# previous 가 UP 이면 위 분기에서 이미 걸러진다. +if [ "$current" != "UP" ] && [ "$current" != "$pending" ]; then + write_state "$previous" "$current" # 1회차 — 확정 보류 + exit 0 +fi + +write_state "$current" "" + if [ "$current" = "UP" ]; then # 첫 실행(previous 없음)에 "복구됨"을 보내지 않는다 — 처음부터 정상인 게 정상이다. # diff --git a/infra/ops/selftest.sh b/infra/ops/selftest.sh index 4b1314e2..f1da45f8 100755 --- a/infra/ops/selftest.sh +++ b/infra/ops/selftest.sh @@ -74,9 +74,15 @@ check '첫 실행 정상: 무발송' 0 "$(sent)" ./health-check.sh; check '정상 반복: exit 0' 0 $? check '정상 반복: 무발송' 0 "$(sent)" +# 비정상은 **연속 2회** 봐야 알린다 — 배포 직후의 일시 상태로 헛울리지 않기 위해서다. echo "$DEGRADED" > "$HEALTH" -./health-check.sh; check '집계 UP·backup DOWN 포착: exit 0' 0 $? -check '집계 UP·backup DOWN 포착: 1건' 1 "$(sent)" +./health-check.sh; check '이상 1회차: exit 0' 0 $? +check '이상 1회차: 보류(무발송)' 0 "$(sent)" +check '이상 1회차: 알린 상태는 그대로 UP' UP "$(sed -n 1p "$STATE")" +check '이상 1회차: 후보로 기록' DEGRADED "$(sed -n 2p "$STATE")" + +./health-check.sh; check '이상 2회차: exit 0' 0 $? +check '이상 2회차: 1건 발송' 1 "$(sent)" ./health-check.sh check '같은 이상 반복: 발송 늘지 않음' 1 "$(sent)" @@ -84,11 +90,21 @@ echo "$UP" > "$HEALTH" ./health-check.sh; check '복구: exit 0' 0 $? check '복구: 2건' 2 "$(sent)" +# 이 서비스에서 가장 자주 일어나는 오탐 — 배포가 컨테이너를 재생성하는 동안 +# scheduler 첫 박동 전 / aiServer 컨슈머 0 이 정상적으로 관측된다. +echo "$DEGRADED" > "$HEALTH"; ./health-check.sh +echo "$UP" > "$HEALTH"; ./health-check.sh +check '배포 블립(이상 1회 후 복귀): 발송 늘지 않음' 2 "$(sent)" +check '배포 블립: 후보가 지워진다' '' "$(sed -n 2p "$STATE")" + # 리스너를 죽이는 대신 죽은 포트를 가리킨다 — kill 하면 셸이 "Terminated" 를 # 결과 사이에 끼워 넣어 읽기 나빠진다(리스너는 EXIT trap 이 정리한다). HEALTH_URL="http://127.0.0.1:9/health" ./health-check.sh -check '도달 불가: exit 0' 0 $? -check '도달 불가: UNREACHABLE 로 기록' UNREACHABLE "$(cat "$STATE")" +check '도달 불가 1회차: exit 0' 0 $? +check '도달 불가 1회차: 후보로 기록' UNREACHABLE "$(sed -n 2p "$STATE")" +HEALTH_URL="http://127.0.0.1:9/health" ./health-check.sh +check '도달 불가 2회차: 확정 기록' UNREACHABLE "$(sed -n 1p "$STATE")" +check '도달 불가 2회차: 발송' 3 "$(sent)" echo echo "통과 $pass, 실패 $fail"