ffprobe duration WARN 대량 발생 원인 분석 — 빈 OGG 세그먼트 / 캡션 probe 비대칭

마지막 업데이트 2026-07-22

ppi-socket 운영 서버에서 하루 WARN의 약 절반(ffprobe duration failed ~1,200건/24h, 대부분 End of file)이 발생. 추적 결과 이는 손상된 파일도, 깨진 파이프라인의 결과도 아니다. producer 교체마다 세그먼트가 갈라지며 생기는 빈/짧은 세그먼트가 상시 발생하고, 녹음 종료 시 캡션 빌드가 크기 필터 없이 전 세그먼트를 probe하기 때문에 찍히는 WARN 노이즈다. 최종 녹음물·캡션 결과에는 영향이 없다.
📌 정정 이력 — 본 문서 초판은 ffprobe WARN을 "ffmpeg 포트 충돌 → 빈 세그먼트" 한 체인으로 묶었으나, 데이터 검증 결과 ffprobe 실패의 ~92%는 포트 충돌·크래시와 무관(50개 방에 분산)함이 확인되어 결론을 정정함. 포트 충돌(reserveLocalUdpPort)은 빈 세그먼트의 ~8%만 설명하는 별개의 소수 이슈로 §6에 분리 정리.
관측 환경Grafana ppi-logs · Loki 직접 집계 · service=ppi-socket, env=prod
관측 기준now−24h (2026-06-09 20:05 ~ 06-10 20:05 KST)
증상ffprobe duration measurement failed ... : End of file WARN 대량(≈1,200/24h)
실제 원인① 세그먼트 로테이션이 빈/짧은 세그먼트를 상시 생성 + ② 캡션 probe 경로(oggSegments)에 size>0 필터 부재
데이터 영향🟢 없음 — 오디오 합치기 경로는 빈 파일을 이미 제외. WARN은 노이즈
별개 이슈🟠 reserveLocalUdpPort 포트 충돌(=ffmpeg 비정상 종료 7건/일) — §6
관련 코드apps/socket/src/recording/{recordingManager,ffprobe,udpPort}.ts

⚡ 한 줄 요약

RecordingManagerproducer가 교체될 때마다 세그먼트를 끊는다(dual-spawn). 교체가 잦거나 연달아 일어나면 방금 연 세그먼트가 오디오를 거의 못 받고 닫혀 빈 OGG가 된다(방당 ~20개). 녹음 종료 시 캡션 빌드는 oggSegments크기 검사 없이 전부 probe한다 — 오디오 경로엔 있는 size>0 필터가 캡션 경로엔 없다. 그래서 빈 파일마다 End of file WARN이 찍힌다. 녹음·캡션 결과물은 정상이고, 이건 데이터 손실이 아니라 로그 노이즈다.

1. 발생량 (now−24h)

588,194
info
2,701
warn
89
error
33
unknown
메시지건수level분류
ffprobe duration measurement failed1,224 (warn의 45%)warn본 문서 주제 — 노이즈
└ 그중 End of file1,051 (86%)warn빈 파일
Failed to stop recording29error드문 최악 케이스
No valid recording segments27error한 세션 전 세그먼트가 무효
Active ffmpeg exited abnormally24error별개: 포트 충돌(§6)
Failed to resume consumer28error별개: SFU 미디어 계층
Failed to consume12error별개: SFU 미디어 계층

cf. 초기 AI 스냅샷(WARN 1,738 / ffprobe 896)과 시점 차이로 절대값은 다르나 "ffprobe가 WARN 최다·대부분 End of file" 구조는 동일. 단 AI가 "No valid segments 1건"이라 한 것은 실제 27건으로 과소집계였음.

2. "손상"이 아니라 "빈/없는" 파일 — 에러 분류

ffprobe 실패 1,224건을 에러 종류로 분류하면, 구조가 깨진(손상된) 파일을 가리키는 Invalid data found는 0건이다.

에러 메시지건수비율실제 파일 상태
End of file1,05186%빈 파일 (0바이트 / OGG 페이지 없음)
No such file or directory~116~9%probe 시점에 파일 미존재
invalid duration (N/A)57~5%스트림/길이 없음 = 사실상 빈 파일
Invalid data found (= 진짜 손상)00%없음
바이트는 있는데 구조가 깨진 "손상" 파일이라면 ffprobe가 Invalid data found를 낸다. 한 건도 없다. 즉 "손상된 OGG를 probe하다 실패"가 아니라 "비었거나 존재하지 않는 세그먼트를 probe"가 정확한 표현이다.

3. 사고(크래시)와 무관함 — 분포 검증

항목
ffprobe 실패가 발생한 고유 방 수50개에 분산
ffmpeg 비정상 종료(포트 충돌) 방에 속한 실패~8%
ffprobe 실패 최다 Top 10 방전부 크래시·bind 실패 0건 (방당 19~25건)

수십 건(consumer 실패 28+12, ffmpeg 크래시 24)의 사고가 1,200건의 빈 세그먼트를 만들 수 없다. 빈 세그먼트는 거의 모든 수업에서 방당 ~20개씩 고르게 나오는 상시 현상이다.

4. 진짜 원인 — 코드 분석

4-1. 세그먼트는 producer 교체마다 갈라진다

recordingManager.tsreplaceChildConsumer/replaceAiConsumertransitionFfmpeg

if (session.childPair) {
  session.childProducer = childProducer;
  if (session.ffmpegProcess) {
    await this.transitionFfmpeg(session, router);   // ← 매 producer 교체마다 새 세그먼트
  }
}
…
private async transitionFfmpeg(session, router) {
  …
  const segNum = ++this.segmentCounter;
  session.recordingPath = join(RECORDING_TMP_DIR, `${roomId}_${startedAt}_seg${segNum}.ogg`);  // 새 .ogg
  await this.startFfmpeg(session);   // 새 ffmpeg + pushOggSegment 등록
}

아동 마이크/핑퐁이(AI) 오디오 트랙이 재발행될 때마다(발화 단위·활동 전환·재접속) producer가 교체되고, 그때마다 세그먼트가 끊긴다. 교체가 연달아 일어나면 방금 연 세그먼트가 오디오를 거의 못 받고 닫혀 빈 OGG가 된다. → 방당 ~20개 누적.

참고: seg1119 같은 높은 번호는 private segmentCounter = 0서버 전체 공통 카운터라 그렇다. 한 방에 1119개가 아니라 기동 후 전 세션 누적값이다.

4-2. 비대칭 — 빈 파일 필터가 한쪽(오디오)에만 있다

oggSegments — 캡션 타이밍용

모든 세그먼트를 무조건 등록, 필터 없음, 정리 안 함. (pushOggSegment @ :554/1057/1225)

segmentPaths — 오디오 합치기용

size>0일 때만 push → 빈 파일 제외. (collectSegment @ :1064)

// ② 오디오 경로 — 빈 파일을 제대로 거른다
private async collectSegment(session) {
  const fileStat = await stat(session.recordingPath);
  if (fileStat.size > 0) session.segmentPaths.push(session.recordingPath);
}

// ① 캡션 경로 — 크기 검사 없이 전부 probe (← WARN 노이즈의 출처)
private async buildAndUploadCaptions(session, mp3S3Key) {
  const segments = await Promise.all(
    session.oggSegments.map(async (seg) => ({
      ...seg,
      audioDurationMs: (await probeAudioDurationMsSafe(seg.filePath)) ?? 0,  // 빈/없는 파일도 그대로 probe
    })),
  );
}

캡션을 MP3 타임라인에 맞추려 각 세그먼트 duration이 필요해서 oggSegments를 순회하는데, ②에 있는 size>0 가드가 ①엔 없다. 그래서 오디오에선 버려진 빈/없는 파일이 캡션 probe에선 검사되고 → ffprobe duration measurement failed WARN → null(=0ms) 반환.

ffprobe.tsprobeAudioDurationMsSafe는 실패를 잡아 WARN 로깅 후 null 반환 → 캡션 계산엔 0ms로 무해하게 처리됨.

5. 원인 흐름 (시각화)

1producer 교체(발화·활동 전환·재접속)마다 세그먼트 로테이션
transitionFfmpeg가 새 seg{N}.ogg + 새 ffmpeg 생성. 교체가 잦음.
2짧게 닫힌 세그먼트가 오디오를 못 받아 빈 OGG로 남음
연속 교체 시 방금 연 세그먼트가 ~0 오디오로 닫힘 → 0바이트 파일. 방당 ~20개.
3오디오 합치기(segmentPaths)는 size>0로 빈 파일 제외 → 녹음 정상
최종 MP3·캡션 결과물에는 영향 없음.
4캡션 빌드(oggSegments)는 필터 없이 전 세그먼트 probe
buildAndUploadCaptions가 빈/없는 파일도 probeAudioDurationMsSafe 호출.
5빈 파일마다 End of file WARN → 하루 ~1,200건 노이즈
실패는 null(0ms)로 흡수되어 결과엔 무해. 로그만 시끄러움.

6. 별개 이슈 — reserveLocalUdpPort 포트 충돌 (소수)

위 노이즈와 독립적으로, ffmpeg 비정상 종료(Active ffmpeg exited abnormally, 24건/24h) 중 다수는 RTP 수신 UDP 포트 bind 충돌이다. 오늘 7건 분석에서 5건이 bind failed: Address already in use였다.

// udpPort.ts — 포트를 bind해 번호만 읽고 소켓을 닫아버림 (TOCTOU)
socket.bind(0, "127.0.0.1", () => {
  const port = socket.address().port;
  socket.close(() => resolve(port));   // 닫는 순간부터 포트 free → ffmpeg가 늦게 bind하면 충돌
});

확보(close)와 ffmpeg 실제 bind 사이에 다른 reserve(ai 입력·dual-spawn 새 ffmpeg·다른 방)가 같은 포트를 선점 → code=1 종료 → 그 세그먼트 1개가 빈다. ffprobe 실패의 ~8%만 설명하므로 WARN 노이즈의 주범은 아니나, 크래시·간헐적 녹음 손실 위험이 있어 별도 처리가 필요하다.

7. 영향 평가 & 개선 방향

영향: 빈 세그먼트는 오디오 합치기에서 이미 제외되어 최종 녹음물·캡션 결과는 정상. ffprobe WARN은 운영 로그/알림 노이즈이며 데이터 손실이 아니다.

개선 우선순위

  1. [노이즈 제거 · 우선] 캡션 probe에 ②의 가드를 ①에도 적용buildAndUploadCaptions의 probe 루프 전에 oggSegmentssize>0/존재 여부로 거르거나, 빈/없는 파일은 0ms로 조용히 스킵(WARN 미발생). 하루 ~1,200건 노이즈 즉시 제거, 결과 동일.
  2. [근본 · 선택] 빈 세그먼트 자체를 덜 만들기 — 연속 producer 교체를 디바운스/병합하거나, 직전 세그먼트가 일정 ms 미만이면 새 세그먼트를 끊지 않고 합치는 식으로 빈 세그먼트 생성 자체를 줄임.
  3. [별개 이슈 · §6] 포트 충돌 제거reserveLocalUdpPort가 소켓을 닫지 말고 fd를 ffmpeg에 인계하거나, EADDRINUSE 감지 시 새 포트로 세그먼트 재시작. ffmpeg 크래시 24건/일 제거.
분석 작성: 2026-06-10 / chulsu · 데이터: Grafana ppi-logs(Loki) ppi-socket prod (now−24h) · 코드: apps/socket/src/recording/*