passport-ping은 일본에 있는 한국 공관의 여권 발급 공고를 긁어서, 내 접수번호가 뜨면 알려주는 서비스예요. b7g에서 제일 먼저 만든 거고요.
어느 날 다른 일을 하다가 DB를 열어볼 일이 있었어요. 별 의도 없이 최신 행을 봤는데, 날짜가 8개월 전이더라고요.
거기서 “아, 죽었구나” 했어요. 그게 틀렸어요. 죽은 건 서비스가 아니라 제 관측이었어요. 이 글은 그 오진을 세 단계로 벗겨낸 기록이에요.
아래 시각은 전부 조사한 날인 2026년 8월 29일 기준이에요.
1단계 — 로그를 봤더니 4개월째 조용했어요
죽었다는 확신을 굳히러 서버에 들어갔어요.
$ docker logs passport-ping 2>&1 | wc -l
4027
$ docker logs passport-ping --timestamps 2>&1 | tail -1
2026-04-22T00:58:22.872397934Z }4,027줄이 쌓여 있는데 마지막 줄이 4개월 전이에요. 게다가 그 마지막 줄은 DB 연결 에러의 꼬리였어요.
여기서 결론을 냈어요. “4월에 뭔가 터졌고, 그 뒤로 이 컨테이너는 아무 말도 안 하고 있다.”
컨테이너 상태는 이거였고요.
Up 10 days (healthy) RestartCount=0멀쩡히 떠 있는데 넉 달째 말이 없는 프로세스. 그럴싸한 그림이었어요. 너무 그럴싸해서 더 안 캐물었어요.
2단계 — --tail로 보니 방금 것이 나왔어요
그런데 로그 파이프가 정말 끊긴 건지 확인해보고 싶어서, 컨테이너 안에서 직접 한 줄을 밀어넣어 봤어요.
$ docker exec passport-ping sh -c 'echo PROBE-$(date +%s) > /proc/1/fd/1'
$ docker logs passport-ping --tail 2
[404] GET /wp-admin/install.php
PROBE-1787986233찍혔어요. 그것도 방금 것만이 아니라, 모르는 사이에 들어와 있던 그날치 404 요청까지 같이요.
그러니까 같은 컨테이너의 로그를 두 가지 방법으로 읽었는데 답이 달랐어요.
$ docker logs passport-ping --timestamps 2>&1 | tail -1
2026-04-22T00:58:22.872397934Z } ← 4개월 전
$ docker logs passport-ping --tail 1 --timestamps
2026-08-29T06:50:33.226427738Z PROBE-1787986233 ← 방금| tail과 --tail은 다른 명령이었어요. 앞엣것은 docker logs가 파일을 처음부터 끝까지 다 뱉게 한 뒤 그 결과의 꼬리를 자르는 거고, 뒤엣것은 도커한테 “끝에서부터 N줄만 달라”고 부탁하는 거예요. 평소엔 같은 답이 나오니까 구분할 일이 없었어요.
경계를 좀 더 재봤어요.
| 명령 | 줄 수 | 보이는 구간 |
|---|---|---|
docker logs c (처음부터) | 4,027 | 2026-04-09 ~ 2026-04-22 |
docker logs c --since 2026-04-20 | 1,585 | 4월 일부 |
docker logs c --since 2026-04-23 | 0 | — |
docker logs c --since 2026-08-29 | 0 | — |
docker logs c --tail 100000 | 100,000 | 2026-06-21 ~ 2026-08-29 |
docker logs c --tail 500000 | 4,027 | 2026-04-09 ~ 2026-04-22 |
앞에서 읽는 방식(--since 포함)은 전부 2026-04-22 근처에서 죽고, 뒤에서 읽는 방식만 멀쩡해요. 로그 파일 그 지점에 전방 리더가 넘어가지 못하는 무언가가 있다는 뜻이에요. 손상된 레코드일 가능성이 높다고 보는데, /var/lib/docker 아래는 root 소유라 파일을 직접 열어보진 못했어요. 여기까지가 확인한 것이고, 원인은 추정이에요.
그리고 --tail도 무한한 탈출구가 아니에요. 마지막 줄을 보세요. 100,000은 되는데 500,000을 달라고 하면 다시 4,027줄로 되돌아와요. 요청한 줄 수가 파일 전체를 덮을 만큼 커지면 결국 앞에서부터 읽게 되고, 그러면 같은 벽에 부딪히는 거예요. “넉넉하게 크게 주면 되겠지”가 정반대로 작동해요.
곁다리로 하나 더 배웠어요. 아까 그 4027도 반쯤 무의미한 숫자였어요.
$ docker logs passport-ping 2>/dev/null | wc -l # stdout만
671
$ docker logs passport-ping 2>&1 1>/dev/null | wc -l # stderr만
3356docker logs는 컨테이너의 stdout을 자기 stdout으로, stderr를 자기 stderr로 내보내요. 그래서 2>&1 | tail을 하면 두 흐름이 시간순이 아니라 스트림별로 뭉쳐서 나와요. 제가 “마지막 줄”이라고 본 건 사실 stderr의 마지막 줄(4월에 났던 DB 연결 에러의 꼬리)이었어요.
참고로 두 스트림 다 같은 지점에서 잘려요. 전방으로 읽으면 stdout 671줄·stderr 3,356줄이 전부 2026-04-22에서 끝나고, --tail 100000으로 읽으면 stdout 7,131줄·stderr 92,869줄이 8월 29일까지 나와요. 스트림을 섞은 건 곁가지고, 벽은 읽는 방향에 있었어요.
3단계 — DB를 지역별로 나눠봤어요
로그가 살아 있다면 DB의 “8개월 전”은 뭐였을까요. 이번엔 합계 말고 지역별로 갈라봤어요.
| 공관 | 수집 건수 | 마지막 수집 |
|---|---|---|
| 도쿄 (ZJA) | 46건 | 2026-08-25 |
| 요코하마 (ZYO) | 18건 | 2026-08-28 |
| 오사카 (ZOS) | 1건 | 2025-12-26 |
접수번호는 누적 10,106개, 마지막 검출이 하루 전인 8월 28일이에요.
죽은 건 세 곳 중 한 곳이었어요. 제가 처음에 본 “8개월 전”은 오사카 행 하나였고, 저는 그걸 서비스 전체의 상태로 읽었어요.
이게 결과 지표를 총계로 보면 안 되는 이유예요. 방향이 양쪽 다 틀려요. 한 칸만 보면 전부 죽은 것처럼 보이고, 합계만 보면 한 칸이 죽은 게 안 보여요. 도쿄·요코하마가 계속 쌓아주니까 총계는 바로 전날에도 늘었거든요. 오사카가 여덟 달째 0건인 채로요.
매일 정확한 보고서가 나오고 있었어요
제일 뼈아픈 건 이거였어요. --tail로 그날 아침 배치 로그를 열어봤더니, 버그가 그냥 적혀 있었어요.
[배치] 도쿄 DB 최대 seq: 1346014
[Crawler] 도쿄 최신 seq 탐색 시작: 1346015부터 5회 시도
[Crawler] 도쿄 seq=1346015에서 접수번호를 찾을 수 없음
[Crawler] 도쿄 seq=1346016에서 접수번호를 찾을 수 없음
[Crawler] 도쿄 seq=1346017에서 접수번호를 찾을 수 없음
[Crawler] 도쿄 seq=1346018에서 접수번호를 찾을 수 없음
[Crawler] 도쿄 seq=1346019에서 접수번호를 찾을 수 없음
[Crawler] 도쿄 최신 seq: 1346019
[배치] 도쿄 새로운 게시물 발견: 1346015 ~ 1346019다섯 개를 열어서 다섯 개 다 “찾을 수 없음”이라고 해놓고, 바로 다음 줄에서 “최신 seq: 1346019” 라고 결론을 내요. 그리고 그 다음 줄이 압권이에요. “새로운 게시물 발견”. 존재하지 않는 다섯 페이지를요.
원인은 짧아요. 탐색 루프가 이렇게 생겼거든요.
if (result.success) {
latestSeq = seq;
} else {
// 404 또는 오류 발생 시 중단
break;
}주석이 가정을 그대로 말하고 있어요. “없는 글이면 404가 오겠지.” 그런데 대상 사이트는 없는 페이지에도 200을 줘요. 본문에 “페이지를 찾을 수 없습니다”라고 적힌 1,557바이트짜리 HTML을 200으로요. 진짜 공고가 115,703바이트니까 74분의 1인데, 상태 코드만 보면 둘이 똑같아요. 없는 페이지에 404 대신 200을 주는 이 패턴을 soft 404라고 불러요.
그래서 break가 한 번도 실행되지 않아요. 탈출구가 없는 탐색 루프는 그냥 끝까지 다 도는 루프고, 그 함수는 사실상 마지막 번호 + 5를 반환하는 상수 함수가 돼 있었어요. 도쿄·요코하마는 공고 번호가 정확히 1씩 올라가는 전용 게시판이라 그 5칸 창에 우연히 걸려서 지금까지 작동한 거고, 오사카만 전 공관 공용 포털이라 다음 공고가 수천 번호 뒤에 있어서 5칸으로는 구조적으로 닿을 수가 없어요.
그리고 이 보고서가 매일 한 번씩 나오고 있었어요. 로그로 확인되는 구간(6월 21일~8월 29일)만 세도 70번이고, 8월은 29일 동안 29번이라 하루도 안 빠졌어요. 그 앞은 로그가 안 남아 있어서 못 세지만, DB에 작년 12월부터 수집 기록이 있으니 그때부터 계속이었을 거예요.
그래서 뭘 바꿨나
로그를 남기는 것과 감시하는 것은 다른 일이더라고요. 이 서비스는 기록을 안 남긴 적이 없어요. 읽는 사람이 없었을 뿐이에요. 그리고 사람은 매일 로그를 읽지 않아요. 저는 8개월 동안 한 번도 안 읽었어요.
그래서 감시의 정의를 이렇게 바꿨어요. 기록을 남기는 게 아니라, 안 읽어도 알려주는 것.
구체적으로는 N일 이상 새 행이 0이면 알림 하나예요. 다만 이번에 배운 걸 얹어서, 파티션별로 봐요.
| 서비스 | 결과 지표 | 나누는 축 |
|---|---|---|
| passport-ping | 새로 수집된 접수번호 | 공관별 |
| page-archive | 새로 만들어진 아카이브 | — |
| body-log | 새로 기록된 끼니 | — |
| srt2.link | 새로 발생한 클릭 | — |
임계치는 그 대상의 자연 주기에서 정해요. 공고가 주 1회쯤 올라오는 게시판이면 하루 0건은 정상이니까 N을 10일쯤으로요.
만들 건 별로 없어요. b7g 서비스들이 전부 같은 DB를 쓰거든요. 그리고 감시 도구는 이미 있어요. site-ping이요. 알림도 스케줄도 인시던트 기록도 거기 다 있으니까, 이건 새 시스템이 아니라 감시 타입을 하나 늘리는 증분이에요. “URL을 친다” 옆에 “쿼리를 던진다”를 하나 더요.
덤으로 이게 site-ping의 정체를 다시 정의해줬어요. site-ping은 만들어놓고 정작 안 쓰다가 다음날 진짜 장애를 맞은 서비스예요. 제품으로만 보면 널린 업타임 모니터링 도구들한테 밀려요. 그런데 결과 지표 감시는 외부 서비스가 못 해줘요. 남의 SaaS는 제 DB를 볼 수 없으니까요. 이 축에서는 대체재가 없어요.
남은 생각
이번 건에서 진짜 무서웠던 건 크롤러 버그가 아니에요. 제가 30분 만에 세 번 틀린 결론을 냈다는 거예요.
“서비스가 죽었다”(DB 한 줄을 전체로 읽음) → “로그도 4개월째 죽었다”(파이프로 읽어서 앞부분만 봄) → “배치가 안 돌고 있다”(위 둘의 합성). 셋 다 관측 도구를 잘못 쓴 결과였고, 셋 다 그럴싸했어요. 서로 아귀가 맞아서 더 그랬고요.
무너뜨린 건 한 문장이었어요. “그 이력은 DB에 다 남아 있잖아.” 로그가 뭐라고 하든 일한 결과는 행으로 남으니까요. DB를 지역별로 갈라 본 순간 세 결론이 한꺼번에 무너졌어요.
그래서 이번에 얻은 건 도구 규칙 하나랑 습관 하나예요.
도구 규칙: 컨테이너 로그의 최신 상태를 볼 땐 docker logs c | tail이 아니라 docker logs c --tail N을 쓴다. 파이프는 도커한테 파일을 통째로 읽으라고 시키는 거라, 중간에 걸리는 게 있으면 거기서 끝나요. 뒤에서 읽으면 그 지점을 안 지나가고요.
습관: 상태를 판정할 땐 서로 다른 층에서 두 번 잰다. 로그 하나로 “죽었다”고 정하지 않고 DB를 열어보는 거요. 이번엔 그 둘이 정반대를 말했는데, 맞은 쪽은 일한 결과가 남는 층이었어요.