녹음 post-mix 손상 stem — 14GB 거대 MP3 무한 인코딩·디스크 100% 폭주 원인 확정 hotfix PPI-1106 apps/socket

결론 — 범인부터 공개한다

세션 중 stem ffmpeg 재시작 시 SIGKILL로 finalize되지 못한 2.8KB 손상 OGG가 ffprobe에서 start_time=0·duration≈17억초로 "성공적으로" 읽히며 기존 검증(null 체크·duration>0)을 모두 통과, post-mix 정렬 기준(base = min start_time)을 0(=1970년)으로 무너뜨렸다. 그 결과 정상 stem들의 adelay가 epoch값 그대로(≈56년) 계산되어 ffmpeg가 56년치 무음을 128kbps CBR로 무한 인코딩 — 디스크 20GB가 찰 때까지(14GB 시점 발견) 멈추지 않았다. hotfix는 손상 stem 격리(2겹 sanity check) + 폭주 상한(-t·타임아웃)의 4중 방어.

수사 일지 ① — 사건 발생: 장애 현상 (ppi-socket-prod)

• 루트 디스크 /dev/nvme0n1p1 20G/20G 100% 사용 — 대부분 ppi-socket-prod 컨테이너 writable layer(14.2GB)
• 원인 파일 단 하나: /tmp/recordings/0dc4079a-…_4_1783337708161.mp3 — 약 14GB, 계속 증가 중
• post-mix ffmpeg 프로세스가 살아서 CPU 약 84%로 해당 MP3를 계속 기록
• ffmpeg 커맨드의 adelay가 비정상: 일부 stem adelay=1783337708425ms(epoch급), 한 stem은 adelay=0
• adelay=0인 stem은 2.8KB인데 ffprobe 결과 start_time=0.000000 / duration≈1,783,337,868초
• journal(83.5M)·/var/log(743M)·inode는 주원인 아님 — 단일 대용량 녹음 파일 문제

수사 일지 ② — 범행 재구성: 인과 사슬 5단계

1. 정상 stem에는 epoch 타임스탬프가 박힌다. PPI-1098이 도입한 후처리 믹스 설계에서 stem OGG는 -use_wallclock_as_timestamps 1 -copyts로 기록되어 start_time이 절대 wallclock(예: 1,783,337,708초)이다. recordingManager.ts:953-955
2. 손상된 2.8KB stem이 검증 두 겹을 모두 통과했다. collectValidStems()는 duration>0만 검사 — 손상 stem의 duration이 17억 초(양수)라 통과. postMixStems()의 가드는 start_time이 null인 stem만 드롭 — 이 stem은 0.0으로 "읽혔고" 0은 finite라 통과.
3. base가 0으로 무너졌다. base = Math.min(...knownPairs.map(p => p.start)) = 0이 되면서 정상 stem들의 adelay가 start − 0 ≈ 1.78e12ms ≈ 56년으로 계산됐다.
4. ffmpeg가 56년짜리 출력을 만들기 시작했다. adelay는 지연 구간을 무음 샘플로 채우고, amix duration=longest는 가장 긴 입력이 끝날 때까지 출력한다. ffmpeg 입장에선 오류가 아니라 유효한 명령의 정상 수행이다.
5. 멈출 장치가 없었다. post-mix에 -t(출력 길이 상한)도 실행 타임아웃도 없어 await가 무한정 대기 — 유일한 종료 조건이 "디스크 가득참"이었다.

수사 일지 ③ — 범인의 기원: 손상 stem은 왜 생기고, 왜 타임스탬프가 1970인가

발생 경로 — kill 기반 재시작의 부산물

• 아동 재접속·트랙 재생성·TTS↔Realtime 전환 등으로 producer가 교체되면 replaceChildConsumer / replaceAiConsumer가 해당 입력의 stem ffmpeg를 재시작한다. recordingManager.ts:385,420
• 구 ffmpeg 정리는 mid-session 경로에서 SIGTERM 1.5초 → SIGKILL 3초의 짧은 타임아웃(새 녹음을 빨리 시작하려는 의도된 트레이드오프). :42-43
• SIGKILL은 OGG 컨테이너 finalize(EOS 페이지 등)를 생략시킨다 — 교체가 연달아 일어나면("재시작 폭주") 방금 시작한 stem이 RTP를 거의 받기도 전에 kill되어 헤더+소량 데이터만 남은 2.8KB 파일이 된다. 이 부류 자체는 기존 코드 주석에도 명시된 알려진 손상이다.

"1970년"의 정체 — 기록된 값이 아니라 소실된 값의 기본치

• OGG 맨 앞의 코덱 헤더 페이지(OpusHead/OpusTags)는 스펙상 granule=0이고, wallclock이 박히는 건 그 뒤 데이터 페이지부터다.
• 파일이 헤더+극소량에서 잘려 "시작 시각을 알려줄 온전한 첫 데이터 페이지"가 없으니 ffprobe가 start_time을 0으로 폴백 — epoch 좌표계에서 0 = 1970-01-01.
• 반면 살아남은 페이지 조각 어딘가에 epoch granule이 남아 duration = 마지막 granule − 0 ≈ 17억 초. 시작 정보는 죽고 끝 정보만 살아남은 비대칭 손상이 "시작은 1970년, 길이는 56년"이라는 기형 조합을 만들었다.

수사 일지 ④ — 검문 돌파: 왜 기존 검증을 통과했나

필터들이 "읽을 수 있는가"만 봤지 "값이 말이 되는가"는 안 봤다. 대부분의 SIGKILL 잘림은 probe 실패·duration 0으로 기존 필터에 걸렸기에 평소 합본은 정상이었고, "검사 항목마다 그럴듯한 값을 돌려주는" 이 형태만 처음으로 뚫고 들어왔다.

수사 일지 ⑤ — 현장 감식: 거대 MP3의 내용물은 56년치 무음

무엇이 만들어지고 있었나

거대 MP3는 손상 stem이 반복해서 합쳐진 결과가 아니다. 손상 stem(2.8KB)은 내용 기여가 거의 없고, 역할은 정렬 기준(base)을 1970년으로 끌어내린 것뿐이다. 파일을 채운 실체는 정상 stem 앞에 붙은 무음 패딩 — post-mix ffmpeg 한 번의 실행이 끝나지 않고 무음을 계속 인코딩한 결과다.

// base=0(손상 stem의 start_time)으로 계산된 출력 타임라인
1970-01-01 ──[손상 stem 2.8KB, adelay=0]──┐
             │                            │
             │   ≈56년치 무음 패딩          │  ← adelay=1783337708425ms 가 만든 갭
             │   (adelay 가 무음 샘플로 채움) │     ffmpeg 는 이 구간을 성실히 인코딩 중이었다
             │                            │
2026-07-06 ──[정상 stem들: 실제 수업 오디오]─┘  ← 타임라인 맨 끝에야 등장

왜 계속 커졌나 — 멈출 조건이 하나도 없었다

• 목표 길이가 사실상 무한대: adelay 56년 + amix duration=longest → 출력 타임라인 56년. 인코딩이 "끝나야" 멈추는데 끝이 오지 않는다.
• 무음도 공짜가 아니다: 128kbps CBR MP3는 내용이 무음이든 발화든 타임라인 1초당 16KB를 무조건 기록. "무음이니까 작겠지"가 성립하지 않는 포맷. 무음 56년 = 이론상 ≈28TB 확정 기록량.
• 인코딩은 실시간보다 수백 배 빠르다: 무음 인코딩은 CPU-bound(관측된 84%). 발견 시점 14GB ≈ 타임라인 87만 초(약 10일 분량)를 이미 인코딩했고, 이 속도로 몇 달이라도 계속 커질 작업이 남아 있었다.
• 종료 조건 부재: -t(출력 길이 상한)도 실행 타임아웃도 없어 await가 ffmpeg exit을 무한정 대기 — 유일한 종료 조건이 디스크 고갈(20GB)이었고, 14GB 시점에 발견됐다.

그 14GB를 열어보면 앞부분부터 수십 년치 무음이며, 인코딩이 무음 구간을 다 지나지 못하고 발견됐으므로 실제 수업 오디오는 아예 담기지 못한 순수 무음 파일일 가능성이 높다.

우연인가 필연인가 — 스위스 치즈 3조건

"언제 터질지"만 우연이었고 "언젠가 터진다"는 예정돼 있었다. 수업이 매일 돌아가는 이상 ③의 확률은 누적된다. 참고로 base=min(start_time) 정렬은 최근 PPI-1098에서 도입됐으므로, 그 이전이었다면 같은 stem이 섞여도 폭주로는 이어지지 않았다 — 새 정렬 설계 + 신종 손상 형태가 만나 처음 터진 사이드 이펙트다.

검거 — 4중 방어 (PPI-1106, PR #837)

목표: 손상 stem 발생 자체를 막는 게 아니라(③은 통제 불가), 들어와도 피해가 "그 stem 하나 누락"에서 멈추도록 격리하고, 로직이 또 뚫려도 디스크 장애로 못 자라게 상한을 둔다.

1) duration sanity — collectValidStems

2) start_time sanity — planPostMix 순수 함수 추출

// start_time 이 null 이거나 녹음 시작 wallclock 에서 ±12h 벗어난 stem(손상 OGG 의
// start_time=0 등)은 드롭해 base 붕괴 → epoch 급 adelay → 무한 인코딩을 차단한다.
export function planPostMix(startTimesSec, recordingStartWallMs): PostMixPlan {
  // plausible = null 아님 && finite && |startMs - recordingStartWallMs| <= 12h
  // plausible 0개  → 전부 0ms 폴백 (usedFallback=true, t0=recordingStartWallMs)
  // plausible 있음 → base = min(plausible), 나머지는 droppedIndices 로 제외
}

3) 출력 길이 상한 — buildPostMixArgs

4) 실행 시간 타임아웃

바꾸지 않은 것

• 정상 stem들의 정렬 동작(PPI-1098의 턴 밀림 픽스)과 null stem 드롭 등 기존 동작은 그대로 보존 — 방어층만 추가
• kill 기반 재시작(조건 ①)은 녹음 공백과의 트레이드오프라 이번 범위에서 손대지 않음

검증 — 테스트 (TDD)

• apps/socket/test/recording-postmix-guard.test.ts — 12케이스, RED(구현 전 실패) 확인 후 GREEN
• prod 시나리오 재현: epoch stem + start_time=0 stem 혼합 → 손상 stem 드롭, base·delay 정상 유지
• 미래 시각 stem 드롭 / null 드롭 기존 동작 보존 / 전부-null·전부-비정상 폴백 / epoch급 duration 거름 / -t 상한 포함
• 전체 socket 스위트 54개 통과, tsc --noEmit 클린
• 회귀 가드 목적: 이후 post-mix 정렬 로직을 다시 손볼 때 이 가드가 제거되면 즉시 깨진다

운영 조치 (코드 픽스와 별개)

관련 문서 · 코드

• 선행 설계: TTS/Realtime 녹음 합본 겹침·밀림 — 입력별 독립 ffmpeg + 후처리 믹스(PPI-1098)
• 유사 부류 손상: ffprobe WARN — 빈 OGG 세그먼트 캡션 probe 비대칭
• 코드: apps/socket/src/recording/recordingManager.ts — planPostMix / isPlausibleStemDurationMs / buildPostMixArgs / collectValidStems / postMixStems
• PR: Dobraindev/ppi#837 (브랜치 PPI-1106)