분석이 끝나기도 전에 누른 시작 — 내 쓰기를 앞지른 이벤트

fecit에는 “어려운 일엔 한 걸음 더”라는 결이 있습니다. 새 할 일을 만들면 서버가 제목을 바탕으로 난이도를 가늠하고, 묵직하다고 판단되면 시작하기 전에 작전을 한 줄 짜보라고 권합니다. 잡일엔 끼어들지 않고, 정말 무거운 일에만 살짝 멈춰 세우는 게이트입니다.

그런데 이번에 그 게이트가, 분석이 끝났는데도 안 떴습니다.

게이트가 안 떴다

증상은 단순했습니다. 어려운 할 일을 새로 만들고, 잠깐 기다렸다가 시작을 누르면 — 게이트가 떠야 하는데 그냥 시작돼 버립니다. 그런데 시작했다가 다시 등록 상태로 되돌리고 한 번 더 누르면, 그때는 게이트가 떴습니다.

“한 번은 안 되고 잠시 뒤엔 된다”는 건 거의 항상 타이밍 문제입니다. 난이도 신호가 그 할 일에 아직 안 붙은 시점에 시작을 눌렀고, 게이트는 신호가 있어야만 발동하니까 그냥 통과한 겁니다.

차단을 넣었더니, 차단이 풀려도 안 됐다

그래서 생각한 게 “분석이 끝날 때까지 상태 변환을 잠깐 막자”였습니다. 새로 만든 할 일은 분석이 안착할 때까지 시작/완료를 막고, 작은 스피너를 보여주는 거죠. 분석은 보통 순식간이니 사람은 거의 인지도 못 할 짧은 차단입니다.

영구히 잠기면 안 되니 안전망으로 타임아웃도 뒀습니다. 신호가 끝내 안 오더라도 몇 초 뒤엔 풀리게요.

그런데 또 안 됐습니다. 스피너가 멈춰서 바로 시작했는데 게이트가 안 떴습니다. 이쯤 되면 타임아웃을 늘리고 싶은 유혹이 듭니다. 3초가 짧았나? 5초로? — 하지만 그건 추측입니다. 분석이 정말 느린 건지, 아니면 다른 데서 새는 건지 모른 채 숫자만 키우는 건 도박이죠.

추측 대신 로그

그래서 세 군데에 로그를 심었습니다. 서버가 분석을 끝내고 신호를 쏘는 시각, 그 신호가 클라이언트에 닿는 시각과 생성 후 경과, 그리고 차단이 타임아웃으로 풀리는 시각.

서버 로그부터 답이 나왔습니다.

[AnalysisTiming] start task=6a3e…54bf
[AnalysisTiming] emit task=6a3e…54bf should_nudge=True elapsed=0.16s

분석은 0.16초 만에 끝났고, 신호도 제대로 발행됐습니다. 서버는 무죄였습니다. 0.16초면 타임아웃보다 한참 빠른데, 그럼 그 신호가 클라이언트에서 게이트를 켰어야 합니다.

클라이언트 로그가 진짜 범인을 가리켰습니다.

event arrived task=6a3e…54bf should_nudge=true … (NOT in cache)
timeout unblock task=6a3e…54bf shouldNudge=undefined

이벤트는 도착했습니다. 그런데 그 순간 방금 만든 할 일이 아직 로컬 캐시에 없었습니다. 핸들러는 캐시에서 그 할 일을 찾아 신호를 붙이려 했는데, 못 찾으니 그냥 돌아섰습니다. 신호는 버려졌고, 차단은 타임아웃으로만 풀렸으며, 게이트는 끝까지 신호를 못 본 채 통과했습니다.

내 쓰기를 앞지른 이벤트

원인은 레이스였습니다. 할 일을 만들면 클라이언트는 서버에 생성 요청을 보내고, 응답을 받아 로컬 캐시에 씁니다. 한편 서버는 그 생성 직후 백그라운드로 난이도를 분석하고 0.16초 만에 실시간 이벤트를 쏩니다.

문제는, 그 이벤트가 클라이언트 자신의 생성 응답·캐시 쓰기보다 빨랐다는 겁니다. 내가 “이 할 일을 캐시에 다 적었다”고 말하기도 전에, 서버는 이미 “이 할 일 분석 끝났어”라고 알려온 거죠. 핸들러는 캐시에 없는 id를 받고 당연히 못 찾고, 신호를 흘려버립니다.

실시간 동기화를 다루다 보면 “내 변경 → 서버 → 다른 기기”라는 한 방향만 생각하기 쉬운데, 이번엔 같은 기기 안에서 서버 이벤트가 내 로컬 쓰기를 앞질렀습니다. 이벤트의 도착 순서와 내 상태의 준비 순서가 보장되지 않는다는, 흔하지만 잊기 쉬운 사실입니다.

버리지 말고 재시도

고치는 방향은 분명했습니다. 신호가 도착했는데 대상이 아직 없으면, 버리지 말고 들어올 때까지 잠깐 기다린다.

const applyResult = (taskId, nudge, attempt = 0) => {
    const task = cache.getByIdSync(taskId);
    if (task) {                       // 캐시에 들어왔으면 적용
        task.shouldNudge = nudge;
        upsert(task);
        return;
    }
    if (attempt >= 12) return;        // 250ms × 12 ≈ 3초 한도
    setTimeout(() => applyResult(taskId, nudge, attempt + 1), 250);
};

생성과 이벤트 사이의 틈은 길어야 한두 번의 재시도면 메워집니다. 캐시에 할 일이 들어오는 즉시 신호가 붙고, 게이트는 제때 발동합니다. 신호가 끝내 안 오는 드문 경우만 타임아웃이 받칩니다.

깜빡이지 않게

여기서 한 가지가 더 남았습니다. 레이스를 고치고 보니, 정상 흐름은 너무 빨라서 스피너가 깜빡 하고 사라졌습니다. 0.x초짜리 차단에 스피너를 띄우는 건 오히려 거슬립니다.

그래서 표시는 차단보다 늦게, 정말 느릴 때만 나오게 했습니다. 차단은 즉시 걸리되, 스피너와 “분석 중” 표시는 일정 시간을 넘겨야 등장합니다. 빠른 평소엔 아무것도 안 보이고, 분석이 느릴 때만 fecit 별이 잠깐 나타나 그 할 일을 들여다봅니다 — 한 번 시작한 별의 펄스는, 도중에 분석이 끝나도 그 호흡 한 번은 마저 쉬고 사라지게 했습니다.

배운 것

1. 타이밍 버그는 추측으로 숫자를 키우지 말고 측정한다. “타임아웃이 짧았나?“는 가설이다. 서버 발행 시각, 이벤트 도착 시각, 차단 해제 경로를 찍으면 범인이 한 번에 드러난다. 로그 한 줄이 며칠치 추측을 이긴다.

2. 실시간 이벤트는 내 로컬 쓰기보다 빠를 수 있다. “내 변경 → 서버 → 다른 기기”만 생각하면, 같은 기기 안에서 서버 이벤트가 내 캐시 쓰기를 앞지르는 경우를 놓친다. 도착 순서는 보장되지 않는다.

3. 대상이 아직 없다고 신호를 버리지 마라. 못 찾으면 흘려보내는 대신, 짧게 재시도하며 기다린다. 단, 무한이 아니라 상한을 둔 재시도여야 한다.

4. 안전망은 정상 경로를 가로채면 안 된다. 타임아웃은 신호 유실을 대비한 보험일 뿐, 그게 먼저 발동해 정상 신호를 앞지르면 본래 동작이 샌다. 안전망보다 정상 경로가 먼저 끝나도록 여유를 둔다.

5. 빠른 건 표시하지 마라. 0.x초짜리 상태에 스피너를 띄우면 깜빡임만 남는다. 표시는 충분히 느릴 때만 등장시키면, 평소엔 매끄럽고 느릴 때만 설명이 따라온다.

---

어려운 일 앞에서 한 번 멈춰 세우려던 작은 게이트가, 실은 “내 이벤트가 내 쓰기보다 빠를 수 있다”는 오래된 진실을 다시 가르쳐 줬습니다. 고치고 나니 게이트는 제때 뜨고, 빠를 땐 아무 일도 없던 것처럼 조용합니다.