Cloudflare 대시보드에서 트래픽이 튄 구간을 확인하러 들어갔다가, 그 아래에 훨씬 심각한 문제가 깔려 있는 걸 발견했습니다. 하루 동안 앱이 처리한 요청의 22%가 실패하고 있었습니다. 알림은 하나도 울리지 않았고, 헬스 체크는 전부 정상이었으며, 로그도 멀쩡해 보였습니다. 실패한 요청이 애초에 애플리케이션까지 도달하지 못했기 때문입니다.
원인은 제가 직접 작성한 컨테이너 시작 스크립트였습니다. 합리적인 작업을, 완전히 잘못된 타이밍에 하고 있었습니다.
트래픽 급증은 미끼였다#
원래 확인하려던 건 한 시간 동안 약 4,900건이 몰린 구간이었습니다. 중앙값은 시간당 121건이고요. 순 방문자는 42명. 방문자 한 명당 110건인데, 사람이 이렇게 브라우징하지는 않습니다.
스캐너였습니다. 봇 하나가 존재하지도 않는 서브도메인을 지어내며 시크릿 파일을 찾아다니고 있었습니다.
api-stage-asia.marucommunity.com/.env.local
api-us-east-1-demo.marucommunity.com/.env
api-eu-uat.marucommunity.com/wp-config.php~
app-test-us-east-1.marucommunity.com/actuator/configprops
prod-api-use2.marucommunity.com/.env.local
relay.marucommunity.com/.env.production서른 개쯤 되는 호스트명, 생각할 수 있는 모든 .env 변형, 그리고 Django 앱에 대고 요청한 Spring Boot actuator 엔드포인트까지. 전부 정규 호스트로 301 리다이렉트됐고 아무것도 노출되지 않았습니다. 지루하고, 실제로 무해한 트래픽이었습니다.
그런데 분석 화면을 열어둔 김에 같은 날짜를 상태 코드로 묶어봤습니다. 진짜 문제는 거기 있었습니다.
| 상태 코드 | 24시간 요청 수 |
|---|---|
| 전체 | 11,350 |
| 504 Gateway Timeout | 2,474 |
22%입니다. 게다가 사이트 전체에 고르게 퍼진 게 아니라, 가장 아픈 곳에 정확히 몰려 있었습니다.
| 엔드포인트 | 504 |
|---|---|
| 알림 안 읽음 개수 | 621 |
| 알림 목록 | 614 |
| 메시지 안 읽음 개수 | 469 |
| 피드 커서 | 210 |
전부 모바일 앱이 30초마다 폴링하는 엔드포인트입니다. 그러니까 이건 추상적인 에러율 숫자가 아니었습니다. 사용자들의 폰이 하루 종일, 아마 몇 주 동안, 안 읽은 알림 배지를 조용히 못 불러오고 있었던 겁니다.
로그가 멀쩡해 보였던 이유#
처음엔 앱이 느려졌겠거니 했습니다. 아니었습니다. 가장 나빴던 시간대의 애플리케이션 요청 로그를 아카이브에서 꺼내봤습니다.
[2026-09-08 01:00:29] "GET /api/v1/notifications/unread_count/" 304 61.615
[2026-09-08 01:00:29] "GET /api/v1/notifications/" 304 63.568
[2026-09-08 01:00:59] "GET /api/v1/notifications/unread_count/" 304 58.742
[2026-09-08 01:00:59] "GET /api/v1/notifications/" 304 105.43844~105밀리초, 전부 304. 오리진은 빨랐습니다.
이게 중요한 단서이고, 규칙으로 적어둘 만합니다. 엣지가 오리진은 들어본 적도 없는 에러를 보고한다면, 요청은 도착하기 전에 죽고 있는 것입니다. 애플리케이션 로그를 그만 읽고, 그 앞에 있는 것을 보세요.
제 경우엔 Fly.io의 프록시였고, 답은 머신 스케줄링 방식에 있었습니다.
0으로 스케일 다운은 비용에 대한 약속이지, 지연 시간에 대한 약속이 아니다#
제 설정은 이렇습니다. 언뜻 보면 합리적이죠.
[http_service]
auto_stop_machines = 'stop'
auto_start_machines = true
min_machines_running = 1유휴 머신은 정지하고, 트래픽이 오면 다시 시작합니다. 쓴 만큼만 냅니다. 트래픽이 들쭉날쭉한 작은 앱이라면 정확히 원하는 동작이고, 그래서 머신을 열 대 정의해두고도 평소엔 한 대만 돌고 있었습니다.
이 방식이 숨기는 청구서는 지연 시간입니다. 정지된 머신으로 요청이 들어오면, 누군가는 그 머신이 부팅될 때까지 기다려야 합니다. 부팅이 프록시의 인내심보다 오래 걸리면, 그 누군가는 504를 받습니다.
그래서 제 머신은 부팅에 얼마나 걸렸을까요? 한 번도 측정한 적이 없었습니다. 로그 아카이브는 알고 있습니다. 시작 스크립트가 각 단계를 출력하고, 모든 줄에 머신 ID가 붙어 있으니까요.
WITH s AS (
SELECT fly.app.instance AS inst, timestamp,
CASE WHEN message ILIKE '%Starting Granian%' THEN 'begin'
WHEN message ILIKE '%Migrations complete%' THEN 'migrated'
WHEN message LIKE '%"GET /api/health/%' THEN 'serving' END AS phase
FROM logs('koreapost', '2026-09-08')
)
SELECT inst,
min(timestamp) FILTER (WHERE phase = 'begin') AS started,
min(timestamp) FILTER (WHERE phase = 'migrated') AS migrated,
min(timestamp) FILTER (WHERE phase = 'serving') AS first_serve
FROM s GROUP BY inst모든 머신에서 일관되게 나온 답입니다.
| 단계 | 소요 시간 |
|---|---|
| 부팅부터 마이그레이션 완료까지 | 10~13초 |
| 마이그레이션부터 첫 요청 처리까지 | 8~19초 |
| 합계 | 25~33초 |
그리고 이게 얼마나 자주 일어나는지 세어봤습니다.
SELECT count(*) AS starts, count(DISTINCT fly.app.instance) AS machines
FROM logs('koreapost', '2026-09-08')
WHERE message ILIKE '%Starting Granian%'
-- starts: 92, machines: 10하루에 콜드 스타트 92번. 매번 그 머신으로 라우팅된 요청이 타임아웃되는 30초짜리 창이 열린 겁니다. 22%가 더는 미스터리가 아니었습니다.
원인은 제 entrypoint 안에 있었다#
모든 머신이 요청 하나를 처리하기 전에 실행하던 코드입니다.
if [ "$1" = "granian-api" ]; then
echo "Running migrations..."
python manage.py migrate --noinput
echo "Running collectstatic in background..."
python manage.py collectstatic --noinput &
exec granian --interface wsgi koreapost_project.wsgi:application ...
fi“하루에 92번"을 떠올리면서 다시 읽어보세요.
migrate는 완전한 Django 부팅입니다. 모든 모델을 임포트하고, Postgres에 연결하고, 마이그레이션 테이블을 조회한 뒤, 할 일이 없다고 판단합니다. 공유 CPU에서 아무것도 하지 않기 위해 10초를 씁니다. collectstatic은 두 번째 완전한 Django 부팅이고, 그다음 정적 파일을 오브젝트 스토리지에 업로드하면서 웹 서버가 기동하려는 바로 그 단일 코어를 두고 경쟁합니다. Granian이 세 번째 부팅이고요.
파이썬 인터프리터 세 개, 그중 둘은 이미 끝난 일을 반복하면서, 머신이 깨어날 때마다 매번.
이렇게 짠 이유는 나름 타당했고, 아마 여러분 코드도 비슷할 겁니다. 마이그레이션은 어딘가에서는 돌아야 하고, Fly의 release_command는 예전에 멈춘 적이 있었으며, entrypoint는 배포 시 반드시 실행되는 유일한 지점이니까요. 배포 작업을 넣기에 맞는 자리입니다. 다만 머신 시작마다 넣기에 맞는 자리가 아닐 뿐입니다. 그리고 머신이 알아서 멈추고 시작하기 시작한 순간, 이 둘은 더 이상 같은 사건이 아닙니다.
버그의 전부는 이것이고, 흔한 실수라고 생각합니다.
릴리스에 속한 작업이 머신 시작마다 실행되고 있었습니다. 0으로 스케일 다운이 사건 하나를 아흔두 개로 바꿔놓았습니다.
해법: 릴리스를 한 번만 선점하기#
특정 이미지로 부팅하는 여덟 번째 머신에서 마이그레이션이 돌 필요는 없습니다. 그 이미지에 대해 한 번만 돌면 되고, 나머지는 그게 끝났다는 사실만 알면 됩니다.
즉, 배포할 때마다 이름이 바뀌는 락입니다. Fly가 FLY_IMAGE_REF로 그 이름을 공짜로 주고, Redis는 이미 있었습니다. 전체가 Django보다 먼저 실행되는 작은 스크립트라서, 흔한 경우의 답이 프레임워크 부팅이 아니라 밀리초로 끝납니다.
def release_id() -> str:
"""배포된 이미지가 바뀔 때 정확히 같이 바뀌는 값."""
return os.getenv("FLY_IMAGE_REF") or os.getenv("FLY_MACHINE_VERSION") or ""
def claim() -> int:
release = release_id()
if not release:
return PREPARE
client = _client()
if client is None: # Redis가 없으면 예전과 똑같이 동작
return PREPARE
done_key, lock_key = _keys(release)
if client.get(done_key): # 이 이미지는 누군가 이미 준비해둠
return SKIP
owner = os.getenv("FLY_MACHINE_ID", "unknown")
if client.set(lock_key, owner, nx=True, ex=LOCK_TTL_SECONDS):
return PREPARE # 경쟁에서 이겼으니 우리가 처리
# 다른 머신이 준비 중이면 기다린다. 마이그레이션이 덜 끝난 스키마로
# 요청을 받는 것보다 느리게 시작하는 편이 낫다.
deadline = _monotonic() + WAIT_SECONDS
while _monotonic() < deadline:
_sleep(POLL_SECONDS)
if client.get(done_key):
return SKIP
if not client.get(lock_key) and client.set(lock_key, owner, nx=True, ex=LOCK_TTL_SECONDS):
return PREPARE # 주인이 마이그레이션 중에 죽었으니 넘겨받는다
return PREPARE # 충분히 기다렸으니 직접 한다entrypoint는 if 하나가 됩니다.
if python3 koreapost_project/release_gate.py claim; then
python manage.py migrate --noinput
python manage.py collectstatic --noinput &
python3 koreapost_project/release_gate.py done
fi
exec granian --interface wsgi koreapost_project.wsgi:application ...모든 실패는 “그냥 준비한다"로 끝나야 한다#
코드보다 이 부분을 베껴 가시는 걸 권합니다.
이런 게이트는 사용자와 스키마 마이그레이션 사이에 놓입니다. 건너뛰는 쪽으로 틀리면 마이그레이션되지 않은 데이터베이스에 요청을 받게 되고, 이건 진짜 장애입니다. 준비하는 쪽으로 틀리면 멱등한 no-op 마이그레이션을 두 번 돌리고 10초를 낭비합니다.
두 결과는 대칭이 아니므로, 코드도 대칭으로 다루면 안 됩니다. 불확실한 경로는 전부 PREPARE를 반환합니다.
- Redis가 없거나 접근 불가. 준비합니다. 예전 동작 그대로라서, 캐시 장애가 “고장"이 아니라 “느림"으로 degrade됩니다.
- 환경에 이미지 참조가 없음. 준비합니다. 어떤 릴리스인지 모르니 준비됐는지도 알 수 없습니다.
- 락 주인이 마이그레이션 도중 사망. 락이 만료되고, 다음 대기자가 넘겨받아 준비합니다.
- 타임아웃보다 오래 기다림. 그래도 준비합니다. 영영 서비스하지 못하는 머신이 중복 마이그레이션보다 나쁩니다.
반대 방향으로 의도한 비대칭이 하나 있습니다. 다른 머신이 락을 실제로 쥐고 있는 걸 확인한 머신은 서비스를 시작하지 않고 기다립니다. 배포 중에 느리게 시작하는 건 괜찮습니다. 절반만 적용된 스키마에 질의를 받는 건 괜찮지 않습니다.
resilient 캐시 래퍼로 이걸 만든다면 함정이 하나 있습니다. 제 래퍼는 Redis에 닿지 못하면 add()가 False를 반환하는데, 이게 “다른 누가 락을 쥐고 있다"와 완전히 똑같이 읽힙니다. 그대로 뒀다면 모든 머신이 마이그레이션을 건너뛰었을 겁니다. 정확히 위험한 방향이죠. 락을 되읽어서 구분하세요. 아무도 쥐고 있지 않은 락은 경쟁에서 진 게 아니라 캐시가 고장 났다는 뜻입니다.
Redis 없이 테스트하기#
이 로직은 단위 테스트할 가치가 있습니다. 정작 흥미로운 경로들은 손으로 재현할 수 없기 때문입니다. 메서드 두 개짜리 페이크면 충분합니다.
class FakeRedis:
"""게이트에 필요한 만큼의 redis-py: get, 그리고 nx/ex를 받는 set."""
def __init__(self) -> None:
self.store: dict[str, str] = {}
def get(self, key): return self.store.get(key)
def set(self, key, value, nx=False, ex=None):
if nx and key in self.store:
return None
self.store[key] = value
return True그다음 시간을 내 마음대로 흘려보내며 까다로운 경우를 몰아봅니다. 게이트가 time.sleep을 직접 부르지 않고 모듈 수준의 _sleep, _monotonic 별칭을 쓰는 점을 눈여겨보세요. 덕분에 같은 프로세스의 다른 스레드까지 건드리지 않고 테스트에서 교체할 수 있습니다.
def test_a_waiter_takes_over_when_the_owner_disappears(self):
self.assertEqual(release_gate.claim(), release_gate.PREPARE) # 주인이 락을 잡는다
_done, lock_key = release_gate._keys(release_gate.release_id())
def owner_dies(_seconds):
self.redis.store.pop(lock_key, None) # 락이 만료됐다
with patch.object(release_gate, "_sleep", owner_dies):
self.assertEqual(release_gate.claim(), release_gate.PREPARE)효과가 있었나? 절반은#
배포한 뒤 머신을 정지시켰다가 다시 시작하면서 시계를 봤습니다. 이제 시작 과정은 자기 판단을 출력하고 곧바로 비켜섭니다.
15:23:34 Starting Granian (API server — HTTP/1.1 + HTTP/2)...
15:23:36 release gate: this release is already prepared, starting straight away
15:23:44 "GET /api/health/ HTTP/1.1" 20010초, 두 번째 머신은 11초였습니다. 이전의 25~33초와 비교하면 창의 3분의 2가 사라졌고, 게이트 자체는 Django를 전혀 임포트하지 않아서 2초면 끝납니다.
하지만 10초는 여전히 10초입니다. 그 첫 순간에 도착한 요청은 여전히 실패합니다. 그래서 나머지를 찾아 나섰습니다.
아무도 캐싱하지 않던 바이트코드#
이미지에는 세상 거의 모든 파이썬 Dockerfile에 들어 있는 그 한 줄이 있습니다.
ENV PYTHONDONTWRITEBYTECODE=1좋은 조언입니다. 컨테이너가 런타임에 레이어 안으로 .pyc를 갈겨쓰면 안 되죠. 제가 끝까지 생각해보지 않았던 건 이 거래의 나머지 절반입니다. 런타임이 바이트코드를 절대 쓰지 않고, 빌드도 쓰지 않는다면, 아무것도 캐싱되지 않고, 모든 프로세스 시작마다 의존성 트리 전체를 소스에서 컴파일합니다.
세어봤습니다.
site-packages .py 파일 : 5,707
site-packages .pyc 파일 : 0Django, DRF, 모든 라이브러리가 하루 92번의 시작마다 매번 다시 컴파일되고 있었습니다. 프로덕션 머신에서 측정한 값입니다.
django.setup() | 시간 |
|---|---|
| 배포된 그대로 | 5.15초 |
compileall 이후 | 3.17초 |
해결은 한 줄이고, compileall은 명시적으로 쓰기 때문에 저 환경 변수가 있어도 동작합니다.
RUN python -m compileall -q /app/.venv/lib /app/koreapost_project /app/marketplace /app/utils || true빌드 시간 16초, 딱 한 번, 캐시되는 레이어에서.
작업하는 김에 더 조용한 문제도 하나 찾았습니다. .dockerignore에는 이렇게 적혀 있었습니다.
__pycache__/
*.pycDocker는 이 패턴을 경로의 각 구성요소가 아니라 상대 경로 전체에 대해 매칭합니다. 그래서 앵커되지 않은 패턴은 빌드 컨텍스트의 최상위에서만 매칭됩니다. 중첩된 __pycache__는 전부 이미지로 실려 가고 있었습니다. 노트북의 파이썬 3.15가 컴파일한 .pyc 218개가, 인터프리터가 3.14인 이미지 안에 실려 들어가서 전부 조용히 무시되고 있었죠. 패턴은 **/__pycache__/와 **/*.pyc여야 합니다.
솔직한 결과: 전체적으로는 2초가 아니라 1초 정도를 벌었습니다. 10초가 9초가 됐습니다. 격리된 벤치마크가 늘 그렇듯 과대평가였습니다.
서스펜드, 그리고 그걸 막고 있던 한 줄#
9초에서 더 걷어낼 작업이 없어졌습니다. 남은 건 피할 수 없는 부팅 한 번이었습니다. 파이썬이 뜨고, Django가 임포트되고, WSGI 앱이 공유 코어에서 올라오는 시간.
그러면 부팅을 안 하면 됩니다. Fly는 머신을 종료하는 대신 메모리를 스냅샷할 수 있습니다.
[http_service]
auto_stop_machines = 'suspend' # 이전에는 'stop'테스트하러 갔더니 Fly가 거절했고, 이번 작업 전체에서 가장 유용한 에러 메시지를 돌려줬습니다.
failed to suspend VM: failed_precondition:
Machines with swap cannot be suspended제 설정 상단에는 제가 직접 쓰고 스스로 믿고 있던 주석과 함께 이게 있었습니다.
# 메모리 스파이크가 OOM 킬 대신 디스크로 스왑되도록 하는 완충 장치.
swap_size_mb = 2048합리적인 예방책입니다. 그런데 실제로 일을 하고 있었을까요? 모든 머신이 이렇게 답했습니다.
MemTotal: 985220 kB
SwapTotal: 2097148 kB
SwapFree: 2097148 kB단 한 페이지도 스왑된 적이 없었습니다. 그날의 로그에도 OOM 킬은 없었고요. “oom"에 매칭된 11줄은 알고 보니 콘텐츠 해시에 우연히 그 세 글자가 들어간 자바스크립트 번들 요청이었습니다. 그리고 진짜 메모리 가드는 완전히 다른 곳, 서버 실행 커맨드에 있었습니다. --workers-max-rss 800이 워커가 1GB 천장에 닿기 한참 전에 재시작시키고 있었죠.
즉 이 완충 장치는 한 번도 일어난 적 없는 사건에 대한 보험이었고, 이미 다른 메커니즘이 커버하고 있었으며, 그 보험료가 서스펜드 기능이었습니다. 제거했습니다.
| 깨어나는 경로 | 응답까지 |
|---|---|
| 오늘 아침의 콜드 부팅 | 25~33초 |
| 게이트와 바이트코드 이후의 콜드 부팅 | 9~10초 |
| 서스펜드에서 재개 | 2.5~3.1초 |
세 번 측정했고 편차는 0.5초 이내였습니다. 깨어난 직후 모든 엔드포인트가 250~435밀리초 만에 200을 반환했습니다.
머신이 자는 동안 소켓은 어떻게 되나#
좋을 게 없고, 고칠 훅도 없습니다. Fly는 VM을 얼립니다. 프로세스에는 시그널이 가지 않고, 내려가는 길에 아무것도 닫을 수 없습니다. 쥐고 있던 커넥션은 깨어날 때도 그대로 메모리에 남아, 몇 분 전에 상대가 버린 소켓을 가리키고 있습니다.
이건 내려갈 때 푸는 문제가 아닙니다. 올라올 때 푸는 문제이고, 대부분은 이미 올바른 선택을 해둔 덕분에 풀립니다.
- DB 커넥션은 요청마다 새로 엽니다(
conn_max_age = 0). 오래 살아서 상할 것이 없습니다. - Redis 캐시는 예외를 던지지 않고 degrade합니다. 래퍼가 커넥션 에러를 잡아 미스로 돌려줍니다.
두 번째 것이 값을 하는 장면을 직접 봤습니다. 어느 재개에서 정확히 예상했던 실패가 로그에 찍혔습니다.
redis.exceptions.ConnectionError: Error while reading from fly-...그리고 그게 발생한 요청은 3.6초 만에 200을 반환했습니다. 죽은 캐시는 느린 페이지이지 에러 페이지가 아니니까요. 이후의 재개에서는 아무것도 찍히지 않았습니다.
여러분의 캐시 클라이언트가 죽은 커넥션에서 예외를 던진다면, 서스펜드는 모든 깨어남을 500 폭죽으로 바꿔놓을 겁니다. 설정을 켜기 전에 확인하세요.
저에게 거짓말을 한 테스트#
첫 서스펜드 측정은 이 기능이 재앙이라고 말했습니다. 502, 30초 만에, 두 번 연속으로.
저는 fly-force-instance-id로 요청을 특정 머신에 고정했습니다. 인스턴스 하나를 부하 테스트할 때는 훌륭한 헤더지만, 이 용도에는 최악입니다. 인스턴스를 강제하면 그 머신을 깨워줬을 프록시 로직을 건너뛰기 때문입니다. Fly는 이미 말해주고 있었습니다. 제가 그걸 에러가 아니라 답으로 읽었다면요.
machine was recently stopped and is unavailable to service request의미 있는 숫자는 실제 트래픽이 지나는 경로에서 나옵니다. 엣지를 통해 동시 요청 40개, 소프트 리밋 12를 훌쩍 넘겨서 프록시가 서스펜드된 머신으로 확장할 수밖에 없게 만들었습니다.
상태 코드: 40 × 200
가장 느린 것: 2.1초교훈은 두 가지이고, 두 번째가 값비쌉니다. 계측하기 편한 경로가 아니라 사용자가 지나는 경로를 측정하세요. 그리고 도구가 뭔가를 거절하면, 그 거절문을 읽으세요. “Machines with swap cannot be suspended"라는 한 문장이 이 오후 전체를 열어젖혔습니다.
여러분 앱에서 확인해볼 것#
유휴 인스턴스를 정지시키는 플랫폼을 쓰고 있다면, 아래 질문들에 저는 반나절을 썼고 몇 주치의 조용한 실패를 아낄 수 있었을 겁니다.
- 콜드 스타트는 얼마나 걸리나요? 컨테이너가 실행되는 시간이 아니라, 실제 요청에 응답하기까지의 시간입니다. 몇 초인지 바로 답할 수 없다면, 필요해지기 전에 측정해두세요.
- entrypoint가 시작마다 하는 일 중 배포에 속한 건 무엇인가요? 마이그레이션, 정적 파일 수집, 캐시 워밍, 인덱스 빌드. 한 번이면 다 괜찮습니다. 아흔두 번이면 다 비쌉니다.
- 바이트코드를 캐싱하고 있긴 한가요? 빌드에
compileall이 없는PYTHONDONTWRITEBYTECODE는 “아니요"라는 뜻입니다. - 정지 대신 서스펜드를 쓸 수 있나요? 못 쓴다면, 무엇이 막고 있나요? 제 경우엔 한 번도 건드려지지 않은 스왑 파일이었습니다.
- 엣지는 보는데 오리진은 모르는 에러가 있나요? 둘을 비교하세요. 그 격차는 리포팅 오차가 아니라 사이에서 죽고 있는 요청이고, 애플리케이션 로그는 절대 보여주지 않습니다.
덧붙이자면, 그동안 헬스 체크는 내내 초록불이었습니다. 늘 그렇습니다. 헬스 체크는 이미 떠 있는 머신을 상대로 돌기 때문에, 그 머신이 존재하기 전의 30초에 대해서는 아무것도 보고할 수 없습니다.