한 문단 요약
이 시스템은 6시간마다 자동으로 64개 쇼핑몰을 돌며 K-pop 이벤트를 수집한다. 어느 날부터 새벽 사이클에서 "리스트 수집 시간 초과(600초)" 오류가 무더기로 쏟아졌고, 멀쩡한 사이트들이 "고장 났다"며 자동 격리됐다. 사이트를 아무리 들여다봐도 멀쩡했다. 진짜 원인은 엉뚱한 곳에 있었다 — 예약된 스크랩이 내 맥이 잠든 사이에 깨어나 실행되면서, 타임아웃 시계가 잠자는 시간까지 흘려버린 것이다. 사이트 탓이 아니라 로컬 머신의 수면이 만든 가짜 장애였다. 이 글은 그 오탐을 "관찰 → 가설 → 검증 → 수정"으로 추적해 근절한 기록이다(커밋 e6df5fc).
1. 문제 — "사이트가 죽었다"는 거짓 경보
스크래퍼는 6시간 간격의 자동 사이클로 각 쇼핑몰의 이벤트 목록을 수집한다. 목록 수집에는 10분(600초) 벽시계 타임아웃이 걸려 있다 — 한 사이트가 너무 오래 붙잡으면 잘라내고 다음으로 넘어가기 위해서다 (main/scraper.js:241의 오류 문자열, :940의 LIST_TIMEOUT_DYNAMIC_MS = Math.min(SHOP_TIMEOUT_DYNAMIC_MS, 600000)).
2026-06-26 ~ 07-01, 이 타임아웃이 82건 터졌다. 문제는 단순한 실패가 아니라 연쇄 오염이었다:
- 스크래퍼에는 서킷 브레이커가 있다 — 어떤 샵이 연속으로 실패하면 "고장(broken)"으로 판정해 자동 격리한다(불필요한 재시도를 멈추고 운영자에게 알리기 위함).
- 그런데 타임아웃 82건이 여러 샵에 흩어져 쌓이자, 서킷 브레이커가 멀쩡한 사이트들을 "고장"으로 격리하기 시작했다. 실제로 사이트에 접속하면 정상이었다.
즉 오탐이 신뢰 장치 자체를 오염시키고 있었다. 서킷 브레이커는 "진짜 죽은 사이트"를 걸러내라고 만든 건데, 가짜 신호가 그걸 무의미하게 만들고 있었다. 이건 사이트 버그가 아니라 관측 시스템의 버그였고, 그래서 더 위험했다 — 이대로 두면 "격리됨" 표시를 아무도 못 믿게 된다.
2. 진단 — 관찰 → 가설 → 검증
증상만 보면 "특정 사이트들이 느려졌다"로 오진하기 쉬웠다. 셀렉터를 고치거나 타임아웃을 늘리는 헛수고로 빠질 수 있는 함정이었다. 진단 노트(tasks/todo.md, 커밋 e6df5fc 시점)에 남긴 추적은 다음 순서였다.
① 관찰 — durationMs 모순
가장 먼저 눈에 걸린 건 숫자가 앞뒤가 안 맞는다는 것이었다. 타임아웃은 명목상 600초(10분) 인데, 실제로 기록된 실행 시간(durationMs)은 11~23분이었다.
명목 타임아웃: 600초 = 10분 ← 여기서 잘려야 함
실제 durationMs: 11 ~ 23분 ← 그런데 이만큼 걸렸다?
10분에서 자르기로 한 타임아웃이 어떻게 23분씩 걸릴 수 있나? setTimeout(600000)이 정상이라면 불가능하다. 타이머가 재는 "시간" 자체가 실제 경과와 어긋나 있다는 뜻이었다. 이 모순이 결정적 단서였다.
② 가설 — 벽시계 타임아웃이 "잠든 시간"을 소진했다
setTimeout은 벽시계(wall-clock) 기준이다. 만약 사이클이 도는 도중 머신이 잠들면, JS 이벤트 루프는 멈추지만 벽시계 상으로는 시간이 계속 흐른 것으로 계산된다. 깨어나는 순간 "이미 600초가 지났다"며 타임아웃이 즉시 터진다 — 실제로는 네트워크가 10분을 쓴 게 아니라, 잠자는 시간이 타임아웃 예산을 먹어치운 것이다. durationMs가 명목값을 초과한 이유가 여기서 설명된다.
가설의 배경: 자동 사이클은 6시간 간격이라 새벽 시간대에도 발동한다. 맥이 딥슬립에 든 상태에서 스케줄러가 잠깐 깨어나는 창(macOS의 DarkWake)에 사이클이 걸리면, 수집이 시작됐다가 다시 잠들고, 그 사이 벽시계 타임아웃이 소진되는 시나리오다.
③ 검증 — DarkWake 시각 대조 + 대조군 + 대안 반박
가설을 세 방향으로 검증했다.
- 시각 상관 — macOS 전원관리 로그(
pmset)의 DarkWake 이벤트 시각과 82건의 타임아웃 발생 시각을 대조했더니 초 단위로 일치했다. 타임아웃이 터진 순간마다 머신이 DarkWake 상태였다. - 대조군(awake-day) — 내가 맥을 켜두고 깨어 있던 날(06-29, 07-02)에는 같은 타임아웃이 0건이었다. 코드는 그대로인데 "잠들었느냐"만 다르면 증상이 나타났다 사라졌다 한다 → 인과의 방향이 확정된다.
- 대안 가설 전부 반박 — 오탐을 다른 흔한 원인으로 돌릴 수 있는지 하나씩 지웠다:
| 대안 가설 | 반박 근거 |
|---|---|
| 코드 회귀(최근 커밋이 깨뜨림) | 06-25 ~ 07-02 사이 커밋 0건 (git 이력으로 독립 확인) |
| 감사 부하 | 감사 산출물은 07-02 생성 — 사건(06-26~) 이후라 원인일 수 없음 |
| 스왑/메모리 압박 | 부차적 요인일 뿐 근본 원인 아님 |
| 네트워크 순단 | 1개 사이클의 일시 현상만 설명, 82건 패턴은 설명 못 함 |
원인 확정: "리스트 수집 시간 초과(600초)" 82건의 근본 원인은 사이트도 셀렉터도 네트워크도 아닌, 6시간 자동 사이클이 맥 딥슬립의 DarkWake 창에서 발동해 벽시계 타임아웃이 수면 구간을 소진한 것이었다. (근거: 커밋 e6df5fc 메시지, tasks/todo.md@e6df5fc, main/scraper.js:814 및 main/sleep-guard.js:5 주석.)
3. 수정 — sleep-guard, 2층 방어 (커밋 e6df5fc)
원인이 "수면"이라면, 해법은 수면을 알아채고 그때의 타임아웃을 장애로 세지 않는 것이다. 새 모듈 main/sleep-guard.js(127줄 신규)를 도입해 두 층으로 방어했다.
┌─ 1층: 예방 (best-effort) ──────────────────────────────┐
│ powerSaveBlocker('prevent_app_suspension') │
│ 사이클 도는 동안 idle-sleep 진입을 막으려 시도. │
│ 단, 뚜껑 닫기·수동 잠자기는 못 막는다 → 완전하지 않음. │
└────────────────────────────────────────────────────────┘
┌─ 2층: 감지 + 중립화 (핵심 보증) ───────────────────────┐
│ 수면을 감지 → 그 구간에 걸친 타임아웃은 │
│ 'SLEEP_INTERRUPTED' 로 재라벨 → 서킷 브레이커가 무시. │
└────────────────────────────────────────────────────────┘
1층(예방)은 완벽할 수 없다 — powerSaveBlocker는 idle-sleep 진입만 지연시킬 뿐, 뚜껑을 닫거나 수동으로 잠재우는 건 못 막는다(이 한계는 tasks/todo-archive-2026-07-03-speedup.md:153에 명시). 그래서 진짜 보증은 2층(감지+중립화)이 한다.
덧붙임(이 글을 쓰며 발견): 인용 코드를 재검증하던 중, 이 1층의powerSaveBlocker.start()인자가 Electron 유효 상수('prevent-app-suspension')가 아닌 언더스코어 표기였음을 발견했다. 실제 Electron 구동 실측 결과 throw →try/catch가 삼켜 1층 예방이 도입 이래 조용히 no-op 였다(2층 감지는 독립적으로 정상이라 오탐 방어엔 영향 없음). 같은 날 확인·수정해 PR #66(merge4837b2f, 회귀 테스트 1개 추가)으로 닫았다. 이 발견 자체가 케이스 스터디 ④(AI-native 워크플로)의 "문서화가 감사를 강제한" 실사례다.
어떻게 "수면"을 감지하나 — 하트비트 갭
머신이 잠들면 JS 는 아예 안 돈다. 이 성질을 역이용한다.
// main/sleep-guard.js:19-49 (요약)
const HEARTBEAT_MS = 15000; // 15초마다 tick
const GAP_FACTOR = 4; // tick 이 4배(=60초) 이상 밀리면 freeze 로 판정
_timer = setInterval(() => {
const now = Date.now();
const gap = now - _lastTick;
if (gap > HEARTBEAT_MS * GAP_FACTOR) { // 60초 넘게 tick 이 안 돌았다
_freezeWindows.push({ from: _lastTick, to: now }); // = 그 구간 머신이 얼어 있었다
}
_lastTick = now;
}, HEARTBEAT_MS);
15초짜리 하트비트를 돌려두고, tick 간격이 60초 이상 벌어지면 그 사이 "JS 가 안 돌았다 = 머신이 얼어 있었다(수면/정지)"고 판정해 {from, to} 벽시계 구간을 _freezeWindows에 기록한다. DarkWake 는 resume 이벤트를 안 쏠 수 있어서, 하트비트 갭이 1차 신호이고 Electron powerMonitor의 suspend/resume 은 보조 신호로 둔다. (타이머는 unref()라 CLI 종료를 막지 않는다.)
타임아웃을 "수면 탓"으로 재라벨
각 샵 실행이 끝나면, 그 실행 구간 [startedAt, now]에 수면이 얼마나 겹쳤는지 묻는다.
// main/scraper.js:820-829
const sleepAnnotate = (err, startedAt) => {
const sleptMs = sleepGuard.sleptBetween(startedAt, Date.now());
if (err && err.isTimeout === true && sleptMs > 60000) { // 타임아웃 + 수면 60초 초과
return {
message: `${err.message} (수면 중단 ${Math.round(sleptMs / 1000)}초 — 사이트 문제 아님)`,
errorCode: 'SLEEP_INTERRUPTED',
};
}
return { message: err && err.message, errorCode: undefined };
};
sleptBetween(t0, t1)은 저장된 freeze 구간과 실행 구간의 교집합 시간을 합산해 돌려준다. 조건은 두 가지를 동시에 만족해야 한다 — (a) 그 오류가 타임아웃이고(err.isTimeout === true, 메시지 파싱이 아니라 구조적 플래그), (b) 실행 구간에 수면이 60초 넘게 겹쳤을 때. 그제서야 SLEEP_INTERRUPTED로 재라벨한다. 이 게이트가 좁아서, 진짜 느린 사이트의 타임아웃은 그대로 장애로 남는다(오탐만 걸러내고 실장애는 안 가린다).
서킷 브레이커 오염 차단
마지막으로, 재라벨된 실패를 서킷 브레이커가 중립 처리하게 했다.
// main/shop-health.js:112-121
let consecFails = 0;
for (let i = list.length - 1; i >= 0; i--) {
if (!list[i].success) {
if (list[i].errorCode === 'SLEEP_INTERRUPTED') continue; // 수면 오탐은 안 센다
consecFails++;
} else break;
}
continue가 핵심이다 — break(스트릭 끊기)도 consecFails++(실패로 세기)도 아니다. SLEEP_INTERRUPTED 기록은 연속 실패 카운트에 안 들어가고, 성공 스트릭을 끊지도 않는다. 즉 서킷 브레이커의 시야에서 투명하게 건너뛴다. 이로써 수면 오탐이 멀쩡한 샵을 "고장"으로 격리하는 연쇄가 끊긴다. (이후 감사에서 격리 사유 문자열도 실장애만 고르도록 추가 보강됐다 — shop-health.js:161-171, e6df5fc 이후 커밋.)
4. 결과
- 수정 규모(
e6df5fc, 2026-07-02 12:10 KST): 6개 파일, +266 / −6.main/sleep-guard.js127줄 신규 +main/scraper.js(+34, 배선) +main/shop-health.js(중립 처리) + 유닛 테스트 (sleep-guard.test.js+51,shop-health-classify.test.js+17). - 인과가 코드로 봉인됐다 — 진단에서 확정한 "수면 → 벽시계 타임아웃 → 서킷 브레이커 오염" 사슬을, 감지(하트비트) → 재라벨(
SLEEP_INTERRUPTED) → 중립화(서킷 브레이커)로 그대로 끊었다. 대조군 근거(awake-day 0건)가 "수면이 없으면 오탐도 없다"를 이미 증명했으므로, 수면을 오탐에서 분리한 이 수정은 설계상 82건 유형의 재발을 차단한다. - 안정성 —
main/sleep-guard.js는 도입 이래 한 번도 수정되지 않았다. 파일 전체 git 이력이e6df5fc단일 커밋이다(이후 34일간 무변경). 뒤이은 커밋들(6d1f2b4,90738b1)은shop-health.js만 손댔고 sleep-guard 로직 자체는 건드릴 필요가 없었다. - 검증 —
tests/unit/sleep-guard.test.js6개 그린(하트비트 없이 freeze 창을 주입하는__test훅으로 결정적 테스트), 전체 스위트 119파일 / 1,082 테스트 그린(vitest 4.1.5, 현재 maine77ef03).
진단 → 수정 요약
증상 "리스트 수집 시간 초과(600초)" 82건 (06-26~07-01), 서킷 브레이커 오염
단서 durationMs 11~23분 ≫ 명목 600s (모순)
검증 pmset DarkWake 시각 초단위 일치 · awake-day(06-29,07-02) 0건 · 대안 4개 반박
근본원인 자동 사이클 × 딥슬립 DarkWake × 벽시계 타임아웃
수정 sleep-guard(e6df5fc) — 감지+SLEEP_INTERRUPTED 재라벨+서킷 브레이커 중립화
현재 단일 커밋 이래 34일 무변경 · 유닛 6 + 전체 1,082 그린
5. 배운 것
- 증상의 층위와 원인의 층위가 다를 수 있다. "사이트 타임아웃"이라는 증상은 애플리케이션 층에서 왔지만 원인은 OS 전원관리 층에 있었다. 증상이 난 곳만 파면 영원히 못 찾는다.
- 모순되는 숫자가 최고의 단서다. "10분 타임아웃이 23분 걸렸다"는 물리적으로 불가능한 값이 수사의 방향을 통째로 바꿨다. 로그를 볼 때 "말이 안 되는 수치"를 그냥 넘기지 않는 습관이 진단을 가른다.
- 벽시계 타임아웃은 수면 앞에서 거짓말한다.
setTimeout은 단조 시계(monotonic)가 아니라 벽시계라, 프로세스가 얼어 있는 동안에도 "시간이 갔다"고 계산한다. 장기 실행·예약 작업의 타임아웃은 이 함정을 항상 안고 있다. - 대조군이 인과를 확정한다. "깨어 있던 날 0건"이라는 자연 실험이, 상관(pmset 시각 일치)을 인과로 끌어올렸다. 재현 가능한 대조 없이는 "그럴듯한 가설"에서 멈춘다.
- 오탐도 장애다 — 신뢰 장치를 오염시키면 진짜 신호를 묻는다. 서킷 브레이커는 진짜 죽은 샵을 격리하려고 만든 건데, 가짜 신호가 들어오자 그 판단 전체를 못 믿게 됐다. 관측 시스템의 오탐은 단순 노이즈가 아니라 신뢰의 근간을 갉는 2차 장애다. 그래서 "예방(best-effort) + 감지·중립화 (보증)"의 2층 방어로, 막지 못하는 경우까지 오염만은 확실히 차단하도록 설계했다.
근거 (repo 대조)
| 주장 | 근거 |
|---|---|
| 600초 목록 타임아웃 실체 | main/scraper.js:241(오류 문자열), :940(LIST_TIMEOUT_DYNAMIC_MS) |
| 82건 · 06-26~07-01 · durationMs 11~23분 · DarkWake 시각 일치 · awake-day 0건 · 대안 반박 | 진단 노트 tasks/todo.md@e6df5fc, 커밋 e6df5fc 메시지, main/scraper.js:814 및 main/sleep-guard.js:5 주석 (동일 진단 4곳 기록) · 커밋 회귀 반박은 git 이력(06-26~07-01 커밋 0)로 독립 확인 |
| 하트비트 갭 감지 (15s tick, 60s freeze) | main/sleep-guard.js:19-20, :40-49, _freezeWindows/sleptBetween :74-82 |
타임아웃 재라벨 게이트 (isTimeout && sleptMs>60000) | main/scraper.js:820-829 (sleepAnnotate), 정적/동적 목록 catch :1128·:1296 |
서킷 브레이커 중립화 (continue) | main/shop-health.js:112-121 |
| 수정 규모·커밋·일시 | e6df5fc (2026-07-02 12:10 KST, 6 files +266/−6, sleep-guard.js +127 신규) |
| 도입 이래 단일 커밋·무변경 | git log -- main/sleep-guard.js = e6df5fc 1건 (이후 6d1f2b4·90738b1은 shop-health.js만) |
| 테스트 그린 (6 + 1,082) | npm test(vitest 4.1.5) on main e77ef03 |
참고: 82건·durationMs 수치는 사건 당시 진단 노트·커밋 메시지에 기록된 운영 관측값이다(원시 카운트 로그shop-health.json은 미추적,reports/는 gitignore). 본문은 repo 에 커밋된 진단 기록과 코드·git 이력을 근거로 하며, 진단 방법(pmset DarkWake 시각 대조·awake-day 대조군)은 노트에 명시된 그대로다.
후기 — 이 글의 사실 검증이 또 하나의 버그를 찾았다 (2026-08-05)
이 케이스 스터디를 쓰며 코드를 재검증하던 중, 1층 예방의 인자 오타가 발견됐다. powerSaveBlocker.start('prevent_app_suspension') — Electron 유효 상수는 하이픈 표기('prevent-app-suspension')다. 실제 Electron 구동으로 실측한 결과 언더스코어 표기는 예외를 던지고, 그 예외가 try/catch 에 삼켜져 1층은 도입 이래 34일간 조용히 비활성(no-op)이었다. 그동안 오탐 방어를 실제로 수행한 것은 전적으로 2층(하트비트 갭 감지 → 재라벨 → 중립화)이었다.
당일 수정·머지했다(PR #66, 4837b2f — 상수 교체 + 오타 회귀 방지 핀 테스트, 수정 모듈을 실제 Electron 에서 구동해 blocker 활성/해제까지 확인). 결과적으로 이 사건은 본문 교훈의 실증이 됐다: best-effort 층은 조용히 죽을 수 있으므로, 보증은 감지·중립화 층에 두어야 한다. 그리고 작성한 글의 주장을 코드로 재검증하다 새 결함을 찾아내는 이 과정 자체가, 이 프로젝트가 정확성을 다루는 방식이다.
초고 · 2026-08-05 KST. 공개 게시 전 개인정보·API 키 없음 확인.